[squid-users] Linking Squid Logs

Mon Apr 5 04:02:29 UTC 2021

On 3/31/21 1:59 PM, Garbacik, Joe wrote:
>  3. Is there a way to generate an unique Id for each flow so, besides
>     the data in flow0, once can easily link these logs together?  

I could not spend enough time to grok the true meaning behind all those
logformat %codes and the corresponding logged values in your questions,
but if you are trying to tie CONNECT requests with bumped transactions
inside those CONNECT tunnels, then you can do that using
%transport::>connection_id. Unfortunately, that logformat %code is only
available in master (future v6) branch.

If you cannot use master/v6 code, then you may be able to accomplish the
same effect by annotating the connection during CONNECT request and then
logging that annotation. See the annotate_client ACL and %note logformat
%code. The difficulty with this older solution is what to use for the
annotation value -- the value has to be unique in a worker process scope
(at least).

I have not tested that, but you can try to use %master_xaction as the
annotation _value_. If it is supported (again, I have not checked), then
you will need to "quote" the annotation value string for Squid to start
interpreting %codes in an annotation value.

If you are using SMP Squid, then you will also need to log something
like "kid${process_number}" to make those master transaction IDs unique
across workers OR give each worker a dedicated access.log. You will also
have to move logs across Squid restarts, for similar uniqueness reasons.

You can also generate globally unique IDs using a key=value pair
returned by an external ACL and use those IDs instead of
%master_xaction. That is supported for sure. The clt_conn_tag=value pair
may be especially handy here.

All this requires testing/experimentation, but I suspect that there is a
way to make it work in modern Squids without source code modifications.

HTH,

Alex.

> In my squid.conf, I have the following logformat which passes all the
> data from the client via the load balancer to the squid server as headers:
>
> logformat MyLogFormat  ---> local_time="[%tl]"
> squid_service=%{service}note squid_status=%Ss squid_hierarchy_status=%Sh
> ** haproxy_id=%{X-Request-Id}>h orig_src_ip=%{X-Client-Egress-Ip}>h
> orig_src_port=%{X-Client-Egress-Port}>h
> haproxy_ingress_ip=%{X-Haproxy-Ingress-Ip}>h
> haproxy_ingress_port=%{X-Haproxy-Ingress-Port}>h haproxy_egress_ip=%>a
> haproxy_egress_port=%>p squid_ingress_ip=%>la squid_ingress_port=%>lp
> squid_egress_ip=%<la squid_egress_port=%<lp dst_ip=%<a dst_host=%<A
> dst_port=%<p ident_username=%[ui username=%[un request_method=%rm
> request="%rm %ru HTTP/%rv" status_code_from_server=%>Hs
> status_code_to_client=%<Hs referer="%{Referer}>h"
> user_agent="%{User-Agent}>h" protocol_version=%rv **
> dns_response_time=%dt response_time=%tr mime_type=%mt *XFER*
> total_request_size=%>st total_reply_size=%<st ** %{src_zone}note
> %{dst_zone}note %{method_category}note %{dst_category}note
> %{file_upload}note ** REQUEST HEADERS %>h *** RESPONSE HEADERS %<h ***
> tag_returned=%et tag_string="%ea" previous_hop_mac=%>eui
> peer_response_time=%<pt total_response_time=%<tt *SSL*
> src_ssl_negotiated_version=%ssl::>negotiated_version
> dst_ssl_negotiated_version=%ssl::<negotiated_version
> src_tls_hello_version=%ssl::>received_hello_version
> dst_tls_hello_version=%ssl::<received_hello_version
> src_tls_max_version=%ssl::>received_supported_version
> dst_tls_max_version=%ssl::<received_supported_version
> src_tls_cipher=%ssl::>negotiated_cipher
> dst_tls_cipher=%ssl::<negotiated_cipher ssl_bump=%<bs
> ssl_bump_mode=%ssl::bump_mode ssl_sni=%ssl::>sni
> src_cert_subject="%ssl::>cert_subject"
> src_cert_issuer="%ssl::>cert_issuer"
> dst_cert_subject="%ssl::<cert_subject"
> dst_cert_issuer="%ssl::<cert_issuer" cert_errors="%ssl::<cert_errors"
> *** error_page_presented=%err_code err_detail="%err_detail"
> rule_id=%{ruleid}note rule_type=%{ruletype}note
> XFF=%{X-Forwarded-For}>h dst_app=%{dst_app}note
>
>
>
> This creates the two logs at the end of this message, What I am
> wondering is:
>
>  1. Why aren't all the request headers (look between * ** *REQUEST
>     HEADERS and *** RESPONSE HEADERSin each log) seen in the first log
>     present in the second log
>  2. I'm assuming since squid is then making the request in the second
>     log, it leaves the items in Flow0 (client load balancer) empty but
>     does retain the data for flow1 (load-balancer-> squid)and flow2
>     (squid -> destination). Even the XFF is not passed. It there anyway
>     to included retain this data?

> Which generates these two logs when doing SSL intercept
> 
> Log 1-----
> 
> 2021-03-31T12:22:08.402609+00:00 squid1 --->
> local_time="[31/Mar/2021:08:22:08 -0400]" squid_service=explicit
> squid_status=NONE squid_hierarchy_status=HIER_DIRECT **
> haproxy_id=73834348 | **Flow0** src_ip=10.11.63.205 src_port=55624
> haproxy_ingress_ip=192.16.8.1.33 haproxy_ingress_port=3128 | ** Flow1**
> haproxy_egress_ip=192.16.8.1.39 haproxy_egress_port=6079
> squid_ingress_ip=192.16.8.1.36 squid_ingress_port=3128 | ** Flow2*
> squid_egress_ip=192.16.8.1.40 squid_egress_port=55984
> dst_ip=10.51.129.182 dst_host=myhost.foo.com dst_port=443
> ident_username=- username=- request_method=CONNECT request="CONNECT
> myhost.foo.com:443 HTTP/1.1" status_code_from_server=200
> status_code_to_client=- referer="-" user_agent="git/2.7.4"
> protocol_version=1.1 ** dns_response_time=- response_time=174
> mime_type=- *XFER* total_request_size=763 total_reply_size=0 **
> src_zone=CoreLab - method_category=Safe - - ** REQUEST HEADERS
> User-Agent=git/2.7.4 HDR_Proxy-Connection=Keep-Alive
> HDR_X-Client-Environment=SecLab HDR_X-Client-Environment=Corporate
> HDR_X-Client-IP=10.11.63.205 HDR_X-Proxy-Channel=3128
> HDR_X-Haproxy-Role=Squid HDR_X-Correlation-ID=73834348
>  HDR_X-Client-Egress-Ip=10.11.63.205 HDR_X-Client-Egress-Port=55624
> HDR_X-Haproxy-Ingress-Ip=192.16.8.1.33 HDR_X-Haproxy-Ingress-Port=3128
> HDR_X-Haproxy-Egress-Ip="" HDR_X-Haproxy-Egress-Port=""
> HDR_X-Server-Ingress-Ip="" HDR_X-Server-Ingress-Port=""
> HDR_X-Server-Queue=0 HDR_X-App-Node=%3CNOSRV%3E HDR_X-SSL-Cipher=""
> HDR_X-SSL-Version="" HDR_X-Request-Id=73834348
> HDR_X-Forwarded-For=10.11.63.205 HDR_Connection=close
> HDR_Host=myhost.foo.com:443 HDR_ *** RESPONSE HEADERS - ***
> tag_returned=- tag_string="-" previous_hop_mac=00:50:56:b8:03:73
> peer_response_time=- total_response_time=98 *SSL*
> src_ssl_negotiated_version=- dst_ssl_negotiated_version=TLS/1.2
> src_tls_hello_version=TLS/1.0 dst_tls_hello_version=TLS/1.2
> src_tls_max_version=TLS/1.2 dst_tls_max_version=TLS/1.2 src_tls_cipher=-
> dst_tls_cipher=ECDHE-RSA-AES256-GCM-SHA384 ssl_bump=- ssl_bump_mode=bump
> ssl_sni=myhost.foo.com src_cert_subject="-" src_cert_issuer="-"
> dst_cert_subject="/C=US/postalCode=12345/ST=California/L=Sunnyvale/street=123
> Any Street/O=Demo, Inc./OU=None/CN=foo.com"
> dst_cert_issuer="/C=GB/ST=Greater Manchester/L=Salford/O=Sectigo
> Limited/CN=Sectigo RSA Organization Validation Secure Server CA"
> cert_errors="-" *** error_page_presented=- err_detail="-"
> rule_id=Explicit-45-Rule1.conf_2 rule_type=ALLOW XFF="10.11.63.205"
> squid_dst_app=MyApp
> 
>  
> 
> Log 2----
> 
> 2021-03-31T12:22:08.495914+00:00 squid1 --->
> local_time="[31/Mar/2021:08:22:08 -0400]" squid_service=explicit
> squid_status=TCP_MISS squid_hierarchy_status=HIER_DIRECT ** haproxy_id=-
> | **Flow0** src_ip=- src_port=- haproxy_ingress_ip=-
> haproxy_ingress_port=- | ** Flow1** haproxy_egress_ip=192.16.8.1.39
> haproxy_egress_port=6079 squid_ingress_ip=192.16.8.1.36
> squid_ingress_port=3128 | ** Flow2** squid_egress_ip=192.16.8.1.40
> squid_egress_port=55984 dst_ip=10.51.129.182 dst_host=myhost.foo.com
> dst_port=443 ident_username=- username=- request_method=GET request="GET
> https://myhost.foo.com/test.js HTTP/1.1" status_code_from_server=401
> status_code_to_client=401 referer="-" user_agent="git/2.7.4"
> protocol_version=1.1 ** dns_response_time=- response_time=33 mime_type=-
> *XFER* total_request_size=231 total_reply_size=434 ** src_zone=CoreLab -
> method_category=Safe - - ** REQUEST HEADERS User-Agent=git/2.7.4
> HDR_Accept=*/* HDR_Accept-Encoding=gzip HDR_Accept-Language=en-US,
> *;q=0.9 HDR_Pragma=no-cache HDR_Host=myhost.foo.com HDR_ *** RESPONSE
> HEADERS HTTP/1.1 401 Unauthorized HDR_Date=Wed, 31 Mar 2021 12:22:07 GMT
> HDR_%0D *** tag_returned=- tag_string="-"
> previous_hop_mac=00:50:56:b8:03:73 peer_response_time=32
> total_response_time=33 *SSL* src_ssl_negotiated_version=TLS/1.2
> dst_ssl_negotiated_version=TLS/1.2 src_tls_hello_version=TLS/1.0
> dst_tls_hello_version=TLS/1.2 src_tls_max_version=TLS/1.2
> dst_tls_max_version=TLS/1.2 src_tls_cipher=ECDHE-RSA-AES256-GCM-SHA384
> dst_tls_cipher=ECDHE-RSA-AES256-GCM-SHA384 ssl_bump=0 ssl_bump_mode=bump
> ssl_sni=myhost.foo.com src_cert_subject="-" src_cert_issuer="-"
> dst_cert_subject="/C=US/postalCode=12345/ST=California/L=Sunnyvale/street=123
> Any Street/O=Demo, Inc./OU=None/CN=foo.com"
> dst_cert_issuer="/C=GB/ST=Greater Manchester/L=Salford/O=Sectigo
> Limited/CN=Sectigo RSA Organization Validation Secure Server CA"
> cert_errors="-" *** error_page_presented=- err_detail="-"
> rule_id=Explicit-45-Rule1.conf_2 rule_type=ALLOW XFF="-" squid_dst_app=MyApp
> 
>  
> 
> 
> _______________________________________________
> squid-users mailing list
> squid-users at lists.squid-cache.org
> http://lists.squid-cache.org/listinfo/squid-users
> 