Linking Squid Logs

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Linking Squid Logs

Garbacik, Joe

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 HEADERS in 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?
  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?  

 

Thanks

 

 

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
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Linking Squid Logs

Amos Jeffries
Administrator
On 1/04/21 6:59 am, Garbacik, Joe wrote:
> 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:
>

...
>
> 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

They are different transactions.


>  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?



First log entry is an HTTP request to initiate (CONNECT) a tunnel.

Second log entry is an HTTPS request to fetch (GET) data from a server.

What is happening is;

In the beginning there exists a TCP connection between Haproxy and
Squid. Transferring HTTP messages.

One of those messages is a CONNECT request. Meaning connect this current
TCP connection to the named server:port and stop performing HTTP - all
following bytes will be some other protocol.

When Squid acknowledges the tunnel is connected bytes initiating a TLS
connection start arriving. Squid does its SSL-Bump things to look inside.

The CONNECT message and state related to it are now complete. It gets
logged and discarded.
   ** this messages is your log line #1.


What is found inside the TLS is a private HTTP communication channel
with its own *fully separate* HTTP messages going on between the client
and server. Squid starts acting as an interception proxy for those messages.
   ** one of these messages is your log line #2.


Notice firstly that the CONNECT message is only between the client and
Squid. There are no HTTP headers or such going to the server for tunnel
setup - just a TCP CYN packet.

Notice secondly that the intercept-proxy/SSL-bump decrypted HTTP
messages have no relationship to the CONNECT or any prior forward-proxy
HTTP messages on the TCP connection. They only thing they have in common
is that they arrived on the same TCP connection between haproxy and Squid.
  If there is actually a relationship between them it might be visible
in the fact that haproxy received both from the same client at its end

    ...  or not. Because we don't know whether haproxy can actually see
the origin client or just another proxy multiplexing traffic into _that_
TCP connection.



>  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?
>

That can only be done reliably by the client itself sending an HTTP
header in all messages with its flow ID.

Otherwise the closest you can get is to define "flow" as everything from
a haproxy ingress = { src-IP, src-port, dst-IP, dst-port, squid
local-IP, squid local-port } to Squids egress = { src-IP, src-port,
dst-IP, dst-port, dst-domain }.



Amos

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Linking Squid Logs

Alex Rousskov
In reply to this post by Garbacik, Joe
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
> [hidden email]
> http://lists.squid-cache.org/listinfo/squid-users
>

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users