[squid-users] Logs not showing ssl::servername

Wed Nov 30 08:16:43 UTC 2022

Hi again!

Thanks for the info!

Log with error code and error detail at the end, both "-":
1669794718.051 INTERNAL_IP *TCP_TUNNEL/500* arsenal.us-west-2.amazonaws.com
splice /CN=arsenal.us-west-2.amazonaws.com 54.240.254.131* - -*

The cache.log with ALL,1 does not look to share a lot, in fact I don´t see
any messages referencing this transaction:

22/11/30 07:51:39 kid1| Current Directory is /
2022/11/30 07:51:39 kid1| Creating missing swap directories
2022/11/30 07:51:39 kid1| No cache_dir stores are configured.
2022/11/30 07:51:39| Removing PID file (/run/squid.pid)
2022/11/30 07:51:39 kid1| Current Directory is /
2022/11/30 07:51:39 kid1| Starting Squid Cache version 5.7 for
x86_64-pc-linux-gnu...
2022/11/30 07:51:39 kid1| Service Name: squid
2022/11/30 07:51:39 kid1| Process ID 64694
2022/11/30 07:51:39 kid1| Process Roles: worker
2022/11/30 07:51:39 kid1| With 1024 file descriptors available
2022/11/30 07:51:39 kid1| Initializing IP Cache...
2022/11/30 07:51:39 kid1| DNS Socket created at [::], FD 9
2022/11/30 07:51:39 kid1| DNS Socket created at 0.0.0.0, FD 10
2022/11/30 07:51:39 kid1| Adding nameserver 127.0.0.53 from /etc/resolv.conf
2022/11/30 07:51:39 kid1| Adding domain dev.ops.mitekcloud.local from
/etc/resolv.conf
2022/11/30 07:51:39 kid1| helperOpenServers: Starting 5/32
'security_file_certgen' processes
2022/11/30 07:51:39 kid1| Logfile: opening log
daemon:/var/log/squid/custom.log
2022/11/30 07:51:39 kid1| Logfile Daemon: opening log
/var/log/squid/custom.log
2022/11/30 07:51:40 kid1| Local cache digest enabled; rebuild/rewrite every
3600/3600 sec
2022/11/30 07:51:40 kid1| Store logging disabled
2022/11/30 07:51:40 kid1| Swap maxSize 0 + 262144 KB, estimated 20164
objects
2022/11/30 07:51:40 kid1| Target number of buckets: 1008
2022/11/30 07:51:40 kid1| Using 8192 Store buckets
2022/11/30 07:51:40 kid1| Max Mem  size: 262144 KB
2022/11/30 07:51:40 kid1| Max Swap size: 0 KB
2022/11/30 07:51:40 kid1| Using Least Load store dir selection
2022/11/30 07:51:40 kid1| Current Directory is /
2022/11/30 07:51:40 kid1| Finished loading MIME types and icons.
2022/11/30 07:51:40 kid1| HTCP Disabled.
2022/11/30 07:51:40 kid1| Pinger socket opened on FD 27
2022/11/30 07:51:40 kid1| Squid plugin modules loaded: 0
2022/11/30 07:51:40 kid1| Adaptation support is off.
2022/11/30 07:51:40 kid1| Accepting HTTP Socket connections at conn13
local=[::]:3128 remote=[::] FD 23 flags=9
2022/11/30 07:51:40 kid1| Accepting NAT intercepted HTTP Socket connections
at conn15 local=[::]:3129 remote=[::] FD 24 flags=41
2022/11/30 07:51:40 kid1| Accepting NAT intercepted SSL bumped HTTPS Socket
connections at conn17 local=[::]:3130 remote=[::] FD 25 flags=41
2022/11/30 07:51:40| pinger: Initialising ICMP pinger ...
2022/11/30 07:51:40| pinger: ICMP socket opened.
2022/11/30 07:51:40| pinger: ICMPv6 socket opened
2022/11/30 07:51:41 kid1| storeLateRelease: released 0 objects
2022/11/30 07:52:09 kid1| Preparing for shutdown after 3 requests
... Starts ending the connections for shutdown, ends with next message...
*2022/11/30 07:52:40 kid1| Squid Cache (Version 5.7): Exiting normally.*

I checked with further log levels but it outputs a lot of data (I know this
one is not for admins, I wanted to try to sent only the relevant logs since
those aws agents do several calls and I was not to only record one
transaction). Also if I needed, this is shared as an attachment?

Thanks in advance!

El mar, 29 nov 2022 a las 21:52, Gabriel Vilariño (<gvilarino6 at gmail.com>)
escribió:

> Thanks Alex!
>
> Here are the fixed logs:
> 1669726977.734 INTERNAL_CLIENT_IP TCP_TUNNEL/500
> arsenal.us-west-2.amazonaws.com splice /CN=arsenal.us-west-2.amazonaws.com
> 54.240.251.223
>
> As you can see, the destination is an aws service, more interesting, it
> effectively *logs the splice* action! That´s why I though it was letting
> the traffic go trough. Also the debug logs from SSL show this:
> 2022/11/29 10:32:38.943 kid1| 83,5| PeekingPeerConnector.cc(273) *startTunneling:
> will tunnel instead of negotiating TLS* # Last line from previously
> attached logs
>
> As far as I know this means *is getting to the TCP_TUNNEL, at that point
> it can not know anything about the internal status on the connection
> between client and host*. If not, *where I should be looking for this
> error? *Should try to review further the debug ssl logs to se if I fend
> something more useful? Maybe tcpdump? This could be just the end service
> failing on the request? Or is an error between Squid and the end sever?
>
> If I understand right the request that fails is the fake connect and I
> need to understand why. Also note almost same config logged this as
> TCP_TUNNEL/200 on version 3.5. But as said before, I really not sure how
> to check, since that service is just an agent installed on some aws
> machines and don´t know how to reproduce this behavior.
>
>
>
>
> Thanks again! Hope I answered fine since I didn´t get the answer email.
>
>
> El mar, 29 nov 2022 a las 14:06, Gabriel Vilariño (<gvilarino6 at gmail.com>)
> escribió:
>
>> Just got it solved. Was caused because of checking default access.log.
>> Using a new file solves all the problems.
>>
>> However, in this context, what means TCP_TUNNEL/500? is it because the
>> TLS handshake? I would like to know if it is tunneling correctly or is
>> having some trouble (not easy to test right now).
>>
>> Thanks!
>>
>> El mar, 29 nov 2022 a las 13:16, Gabriel Vilariño (<gvilarino6 at gmail.com>)
>> escribió:
>>
>>> Hi there,
>>>
>>> I am setting up an HTTP/HTTPS transparent proxy, meaning the clients not
>>> need any certificates for using the proxy. This works fine on version 3.5
>>> of Squid, however after upgrading to 5.7 the behavior of the logs change:
>>>
>>> 1669723133.174   8037 10.184.19.220 TCP_TUNNEL/500 6207 CONNECT
>>> 54.240.253.128:443 - ORIGINAL_DST/54.240.253.128 -
>>>
>>> Directive: logformat squid %ts.%03tu %>a %Ss/%03>Hs %ssl::>sni
>>> %ssl::bump_mode ssl::>cert_subject %<ru
>>>
>>> On version 3.5 we were obtaining the domain name (an aws service) in the
>>> place of ORIGINAL_DST. Also now we are not seeing any information about the
>>> bump_mode in no one of the connections while before we were seeing it. One
>>> could trough that it could be because of the /500 message, however on a 200
>>> one to docs.ansble.com it also don´t show any data on the sni field:
>>>
>>> 1669723513.363    332 10.184.19.220 TCP_TUNNEL/200 38192 CONNECT
>>> 104.26.0.234:443 - ORIGINAL_DST/104.26.0.234 -
>>>
>>> Also the 500 looks to come from the squid not understanding something on
>>> the SSL negotiation:
>>>
>>> 2022/11/29 10:32:38.943 kid1| 83,4| support.cc(248) check_domain:
>>> Verifying server domain arsenal.us-west-2.amazonaws.com to certificate
>>> name/subjectAltName arsenal.us-west-2.amazonaws.com 2022/11/29
>>> 10:32:38.943 kid1| 83,5| bio.cc(136) read: FD 28 read 347 <= 65535 2022/11/29
>>> 10:32:38.943 kid1| 83,5| Io.cc(91) Handshake: -1/0 for TLS connection
>>> 0x558453168970 over conn99 local=SQUID-INTERNAL-IP:44264 remote=
>>> 54.240.251.223:443 ORIGINAL_DST FD 28 flags=1 2022/11/29 10:32:38.943
>>> kid1| 83,2| PeerConnector.cc(256) handleNegotiationResult: ERROR: failure
>>> while establishing TLS connection on FD: 280x558452b68980*1 2022/11/29
>>> 10:32:38.943 kid1| 83,5| NegotiationHistory.cc(85) retrieveNegotiatedInfo:
>>> SSL connection info on FD 28 SSL version NONE/0.0 negotiated cipher 2022/11/29
>>> 10:32:38.943 kid1| 83,5| PeekingPeerConnector.cc(84)
>>> checkForPeekAndSpliceMatched: Will check for peek and splice on FD 28 2022/11/29
>>> 10:32:38.943 kid1| 83,5| PeekingPeerConnector.cc(395)
>>> serverCertificateVerified: HTTPS server CN:
>>> arsenal.us-west-2.amazonaws.com bumped: conn99
>>> local=SQUID-INTERNAL-IP:44264 remote=54.240.251.223:443 ORIGINAL_DST FD
>>> 28 flags=1
>>> 2022/11/29 10:32:38.943 kid1| 83,5| PeekingPeerConnector.cc(273)
>>> startTunneling: will tunnel instead of negotiating TLS
>>>
>>> It is clear that in creates the tunnel so the 500 probably is that
>>> error? Why the bump/sni messages never log anything (according to
>>> https://wiki.squid-cache.org/Features/SslPeekAndSplice they should log
>>> splice not -). This is the config for bumping:
>>>
>>>
>>>
>>> acl step1 at_step SslBump1
>>> acl step2 at_step SslBump2
>>> acl step3 at_step SslBump3
>>> ssl_bump peek step1 all
>>>
>>> .... http rules ...
>>>
>>> acl allowed_https_sites ssl::server_name_regex "/etc/squid/whitelist.txt"
>>> ssl_bump peek step2 allowed_https_sites
>>> ssl_bump splice step3 allowed_https_sites
>>> ssl_bump terminate step2 all
>>>
>>>
>>>
>>>
>>> Ip tables simply redirect:
>>>
>>> iptables -t nat -A PREROUTING -p tcp --dport 80 -j REDIRECT --to-port
>>> 3129
>>> iptables -t nat -A PREROUTING -p tcp --dport 443 -j REDIRECT --to-port
>>> 3130 # https port on squid: https_port 3130 intercept ssl-bump
>>> cert=/etc/squid/ssl/dummy.pem
>>>
>>> Thanks in advance, i have been trying this for a week now reading a lot
>>> of posts but not luck...
>>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20221130/ec207dd3/attachment-0001.htm>