[squid-users] Logs not showing ssl::servername
Alex Rousskov
rousskov at measurement-factory.com
Thu Dec 1 16:26:28 UTC 2022
On 12/1/22 10:41, Gabriel Vilariño wrote:
> About the motivation Alex, really the only thing that concerns me is the
> strange log (TCP_TUNNEL and error 500).
Based on your debugging cache.log (thank you!) and superficial Squid
code analysis, I believe HTTP status code 500 in your use case is a
Squid bug. The transaction was actually successful.
Squid did not send a CONNECT response because your Squid intercepts
traffic (and the client does not send CONNECT requests and does not
expect CONNECT responses). Instead of logging a "-" for the sent HTTP
status code in this case, Squid logged 500. That is a bug.
Your next steps are summarized at
https://wiki.squid-cache.org/SquidFaq/AboutSquid#How_to_add_a_new_Squid_feature.2C_enhance.2C_of_fix_something.3F
HTH,
Alex.
> 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=
> <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
> <mailto: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
> <http://arsenal.us-west-2.amazonaws.com> splice
> /CN=arsenal.us-west-2.amazonaws.com
> <http://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 <mailto: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
> <http://arsenal.us-west-2.amazonaws.com> splice
> /CN=arsenal.us-west-2.amazonaws.com
> <http://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 <mailto: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 <mailto: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 <http://54.240.253.128:443> -
> ORIGINAL_DST/54.240.253.128 <http://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
> <http://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 <http://104.26.0.234:443> -
> ORIGINAL_DST/104.26.0.234 <http://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
> <http://arsenal.us-west-2.amazonaws.com> to certificate
> name/subjectAltName arsenal.us-west-2.amazonaws.com
> <http://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 <http://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
> <http://arsenal.us-west-2.amazonaws.com> bumped: conn99
> local=SQUID-INTERNAL-IP:44264 remote=54.240.251.223:443
> <http://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
> <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...
>
>
> _______________________________________________
> squid-users mailing list
> squid-users at lists.squid-cache.org
> http://lists.squid-cache.org/listinfo/squid-users
More information about the squid-users
mailing list