[squid-users] Squid Logs Partially duplicated when denied

[Garbacik, Joe]

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

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?
  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.
  3.  Why do I see two squid_status types on the denied (TCP_DENIED and NONE)?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20190530/2bb3f21b/attachment-0001.html>