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

Thu Dec 1 15:41:34 UTC 2022

Hi there,

Sorry for the delay. I have problems to only log 1 request.

I removed the internal ip that makes the request and one internal dns, but
dont think that´s important. Also removed all machines that weren´t
producing this traffic so we should only have the AWS arsernal request (on
the access.log I only see one but could be a second one, however all of
those produce exact same result).

About the motivation Alex, really the only thing that concerns me is the
strange log (TCP_TUNNEL and error 500). On the usage side, I can not tell
if that call is working (going trough or not) since I don´t even use that
service. I was evaluating how Squid works and simply run in that strange
log. My final objective is to simply understand what´s going on (tunnel or
500) but there is nothing critical that I have to fix.

Link: https://privfile.com/download.php?fid=6388c98c4ad19-MTQ5ODM= is valid
for one day, password is "pepe" without "".

Thanks!

El mié, 30 nov 2022 a las 9:16, Gabriel Vilariño (<gvilarino6 at gmail.com>)
escribió:

> 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/20221201/f2c95df8/attachment-0001.htm>