[squid-users] Squid Logs Partially duplicated when denied

[Amos Jeffries]

On 30/05/19 11:47 pm, Garbacik, Joe wrote:
> I have the following for each of my rules (except for my last rule:
> http_access deny all rule):
> 
> http_access allow AllowedSrc AllowedInternalDst
> 
> note ruleid ACCESS2INTERNAL  AllowedSrc AllowedInternalDst
> 
> note ruletype ALLOW AllowedSrc AllowedInternalDst
> 
>  
> 
> I have the following log-format entry used for all logs (note the last
> two fields now indicate to which rule I matched and the expected behavior):
> 
> 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-Forwarded-For}>h
> haproxy_egress_ip=%>a haproxy_port=%>p squid_ingress_port=%>lp
> 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
> 

Please be aware that there are length limits to log lines. 8KB is
hard-coded in all current releases. With each logging module having its
own I/O limit - which may be smaller than the general 8KB limit in some
modules.


> 
> So when traffic is allowed, everything works as expected (Note the
> orig_src_ip, rule_id, rule, type are all populated):
> 
> ---> local_time="[30/May/2019:07:25:12 -0400]" squid_service=explicit
> squid_status=TCP_TUNNEL squid_hierarchy_status=HIER_DIRECT **
> haproxy_id=5CEFBD98_0AFB14CC_0AFB1621_206C_9E79_461F
> orig_src_ip=10.10.2.24 <TRUNCATED>  rule_id=ACCESS2INTERNAL  rule_type=ALLOW
> 
>  
> 
> When a client is denied, it creates two log entries, each with portion
> of the logs filled out (i.e. orig_src_ip in the first log, and the
> requested url and the  rule that I expected to match in second log):
> 
> *---> local_time="[30/May/2019:07:20:32 -0400]"* squid_service=explicit
> squid_status=TCP_DENIED squid_hierarchy_status=HIER_NONE **
> haproxy_id=5CEFBC7F_0AFB14CC_0AFB1621_206C_9DBE_461F
> orig_src_ip=10.10.2.24 <TRUNCATED>
> error_page_presented=ERR_ACCESS_DENIED err_detail="-"  rule_id=- rule_type=-
> 
> * *
> 
> *---> local_time="[30/May/2019:07:20:32 -0400]"* squid_service=explicit
> squid_status=NONE squid_hierarchy_status=HIER_NONE ** haproxy_id=-
> orig_src_ip=- <TRUNCATED>  request_method=GET request="GET
> https://example.org/ HTTP/1.1" status_code_from_server=403
> status_code_to_client=- <TRUNCATED>
> error_page_presented=ERR_ACCESS_DENIED err_detail="-" 
> rule_id=ACCESS2INTERNAL  rule_type=
> 
> ALLOW
> 
>  
> 
> So my questions are these:
> 
>  1. Is there a better way to log which rules a connection matches?


No. The case you have is a very good example of why.

-> There many ACLs all being evaluated for any one transaction.

-> There are multiple protocol levels. Each with different ACLs being
applied.

-> There are multiple *transactions* at the HTTP level that those ACLs
are all being tested one. With possibly conflicting or otherwise vastly
different results.

In aggregate no one ACL can be said to 'cause' the behaviour. They are
just small steps in a quite large sequence of choices.



>  2. Why does the denied log twice and not as a single log entry? Why
>     isn't the requested URL logged in the first log entry and then done.

Because there are two transactions to log.



>  3. Why do I see two squid_status types on the denied (TCP_DENIED and NONE)?
> 

You appear to be using SSL-Bump features. Which means;

The ALLOW case was a spliced transaction. The tunnel data remains
untouched - so only the tunnel layer to log. Thus TCP_TUNNEL

The DENY case requires delivery of a error page to clients. Because of
how Browsers treat error responses to CONNECT requests the TUNNEL must
be bumped to inject the error page in a place where it will get show to
the Browser user, which means two transactions now exist;
 a) the TUNNEL transaction
 b) the decrypted HTTPS request which gets the HTTP format error
response injected.


Amos