[squid-users] acl / format code evaluation

[Jason Spashett]

Hello,

I am using squid 5, and after reading the following I have attempted
to link the connect requests to the other requests within a TLS
tunnel.
http://lists.squid-cache.org/pipermail/squid-users/2021-April/023526.html

I added an extra log format code to squid 5, called %random, which
always returns a random string, in the hopes of using this to stamp
against log entries to tie them together.

The squid configuration follows, this seems to partially work in that
the requests in the tunnel have the same conn_id, but the connect
request itself has a different one, which leads me to to believe that
the format code is being evaluated twice in that case perhaps. I am
not sure why the in tunnel requests appear to work, but the id on the
connect request is different.

Note that I added %master_xaction to the log too, to see if that
worked, and it does, but it's not particularly practical on it's own
due to the problem of it not being unique enough.

Can anyone tell me why this isn't working, and or when the log format
codes get evaluated.


Squid configuration
-------------------
#
acl connection_id_acl annotate_client conn_id+="%master_xaction/%random"
acl has_conn_id_acl note conn_id
acl set_conn_id_once_acl any-of has_conn_id_acl connection_id_acl
note "" "" set_conn_id_once_acl
#
logformat log time="%tl" conn_id=%{conn_id}note request_type=%>rm url=%>ru

log output
----------
time="04/Nov/2021:14:54:19 +0000" conn_id=2550/Fh0Lje1
request_type=CONNECT url=blog.jason.spashett.com:443
time="04/Nov/2021:14:54:19 +0000" conn_id=2550/e5sVhqi
request_type=GET
url=https://blog.jason.spashett.com/minecraft-4k-ported-to-the-d-programming-language/
time="04/Nov/2021:14:54:20 +0000" conn_id=2550/e5sVhqi
request_type=GET url=https://blog.jason.spashett.com/css/main.css