#StackBounty: #squid #stunnel stunnel + squid = 1 request for 5minutes (rest connection reset by peer)

Bounty: 100

tl;dr;

Configuration with stunnel on client which connect to squid proxy with x509 certificate authentication work only for one request per 5minutes. Scenario:

  • Squid and stunnel configured and started
  • wget configured to use localhost as proxy (stunnel)
  • Only 1 request (e.g. wget https://github.com) per 5 minutes (or stunnel restart) work rest got connection reset by peer
  • Using raw connection e.g openssl s_client -key -cert -connect using direct communication to squid works properly

Description

I am setting up architecture of stunnel installed on client which leads to squid proxy with x509 Certificate authentication.

Client setup stunnel with his certificate which connects to squid, then set up HTTP_PROXY to aim for stunnel endpoint at localhost.

Trust path is correctly configured on each side, so both squid trust certificates from client, and client trust squid’s certificate on each level – Root CA and intermediate CA.

Configuration of stunnel:

sslVersion=TLSv1.2
output=/var/log/stunnel4/stunnel.log
[squid-gcp]
cert = /etc/letsencrypt/live/test.internal/fullchain.pem
key = /etc/letsencrypt/live/test.internal/privkey.pem
CAFile = /usr/local/share/ca-certificates/root.crt
client = yes
debug=7
accept = 127.0.0.1:3128
connect = squid.internal:3128

Configuration of squid

acl localnet src 0.0.0.1-0.255.255.255  # RFC 1122 "this" network (LAN)
acl localnet src 10.0.0.0/8             # RFC 1918 local private network (LAN)
acl localnet src 100.64.0.0/10          # RFC 6598 shared address space (CGN)
acl localnet src 169.254.0.0/16         # RFC 3927 link-local (directly plugged) machines
acl localnet src 172.16.0.0/12          # RFC 1918 local private network (LAN)
acl localnet src 192.168.0.0/16         # RFC 1918 local private network (LAN)
acl localnet src fc00::/7               # RFC 4193 local private network range
acl localnet src fe80::/10              # RFC 4291 link-local (directly plugged) machines
acl SSL_ports port 443
acl Safe_ports port 80          # http
acl Safe_ports port 21          # ftp
acl Safe_ports port 443         # https
acl Safe_ports port 70          # gopher
acl Safe_ports port 210         # wais
acl Safe_ports port 1025-65535  # unregistered ports
acl Safe_ports port 280         # http-mgmt
acl Safe_ports port 488         # gss-http
acl Safe_ports port 591         # filemaker
acl Safe_ports port 777         # multiling http
acl CONNECT method CONNECT
acl cert user_cert CN test.internal
http_access allow localhost manager
http_access deny manager
http_access deny to_localhost
http_access allow cert
http_access allow localhost
http_access allow servicedesk
http_access deny all
https_port 3128 tls-cert=/etc/letsencrypt/live/squid.internal/cert.pem tls-key=/etc/letsencrypt/live/squid.internal/privkey.pem options=NO_SSLv3:NO_TLSv1:NO_TLSv1_1:NO_TLSv1_3:NO_TICKET clientca=/usr/local/share/ca-certificates/root.crt cafile=/usr/local/share/ca-certificates/root.crt tls-default-ca=off
client_idle_pconn_timeout 5 minutes
client_persistent_connections on
pconn_lifetime 0
logformat squidtls %tl %ts.%03tu %6tr %>a %Ss/%03>Hs %<st %rm %ru %[un %Sh/%<a %mt "%ssl::>cert_subject"
access_log daemon:/var/log/squid/access-tls.log squidtls
cache deny all
cache_dir null /tmp
shutdown_lifetime 1 seconds
coredump_dir /var/cache/squid

Now what happens on client, having configured properly HTTPS_PROXY=localhost:3128, first request through squid is accepted, and next are rejected with connection reset by peer. After 5minutes or stunnel restart next request is handled properly.

Logs from stunnel when this occure, first reqeust ok, second one rejected:

2021.07.07 14:27:59 LOG7[0]: Service [squid-gcp] started
2021.07.07 14:27:59 LOG7[0]: Setting local socket options (FD=3)
2021.07.07 14:27:59 LOG7[0]: Option TCP_NODELAY set on local socket
2021.07.07 14:27:59 LOG5[0]: Service [squid-gcp] accepted connection from 127.0.0.1:50142
2021.07.07 14:27:59 LOG6[0]: s_connect: connecting 100.112.0.62:3128
2021.07.07 14:27:59 LOG7[0]: s_connect: s_poll_wait 100.112.0.62:3128: waiting 10 seconds
2021.07.07 14:27:59 LOG7[0]: FD=6 events=0x2001 revents=0x0
2021.07.07 14:27:59 LOG7[0]: FD=11 events=0x2005 revents=0x0
2021.07.07 14:27:59 LOG5[0]: s_connect: connected 100.112.0.62:3128
2021.07.07 14:27:59 LOG5[0]: Service [squid-gcp] connected remote server from 100.112.0.63:50392
2021.07.07 14:27:59 LOG7[0]: Setting remote socket options (FD=11)
2021.07.07 14:27:59 LOG7[0]: Option TCP_NODELAY set on remote socket
2021.07.07 14:27:59 LOG7[0]: Remote descriptor (FD=11) initialized
2021.07.07 14:27:59 LOG6[0]: SNI: sending servername: squid.internal
2021.07.07 14:27:59 LOG6[0]: Peer certificate not required
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): before SSL initialization
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write client hello
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write client hello
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS read server hello
2021.07.07 14:27:59 LOG6[0]: Certificate verification disabled
2021.07.07 14:27:59 LOG6[0]: Certificate verification disabled
2021.07.07 14:27:59 LOG6[0]: Certificate verification disabled
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS read server certificate
2021.07.07 14:27:59 LOG6[0]: Client CA: O=GCP Internal CA, CN=GCP Internal CA Root CA
2021.07.07 14:27:59 LOG6[0]: Client CA: O=GCP Internal CA, CN=GCP Internal CA Intermediate CA
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS read server certificate request
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS read server done
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write client certificate
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write client key exchange
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write certificate verify
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write change cipher spec
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write finished
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS write finished
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS read change cipher spec
2021.07.07 14:27:59 LOG7[0]: TLS state (connect): SSLv3/TLS read finished
2021.07.07 14:27:59 LOG7[0]: New session callback
2021.07.07 14:27:59 LOG7[0]: Peer certificate was cached (2601 bytes)
2021.07.07 14:27:59 LOG6[0]: Session id: 383CDD4E8AA87AC2ED148172C025D1A5ECE0A1FF114362503BCDED36B9BB44B0
2021.07.07 14:27:59 LOG7[0]:      1 client connect(s) requested
2021.07.07 14:27:59 LOG7[0]:      1 client connect(s) succeeded
2021.07.07 14:27:59 LOG7[0]:      0 client renegotiation(s) requested
2021.07.07 14:27:59 LOG7[0]:      0 session reuse(s)
2021.07.07 14:27:59 LOG6[0]: TLS connected: new session negotiated
2021.07.07 14:27:59 LOG6[0]: TLSv1.2 ciphersuite: AES256-GCM-SHA384 (256-bit encryption)
2021.07.07 14:27:59 LOG7[0]: Compression: null, expansion: null
2021.07.07 14:27:59 LOG6[0]: Read socket closed (readsocket)
2021.07.07 14:27:59 LOG7[0]: Sending close_notify alert
2021.07.07 14:27:59 LOG7[0]: TLS alert (write): warning: close notify
2021.07.07 14:27:59 LOG6[0]: SSL_shutdown successfully sent close_notify alert
2021.07.07 14:27:59 LOG7[0]: TLS alert (read): warning: close notify
2021.07.07 14:27:59 LOG6[0]: TLS closed (SSL_read)
2021.07.07 14:27:59 LOG7[0]: Sent socket write shutdown
2021.07.07 14:27:59 LOG5[0]: Connection closed: 737 byte(s) sent to TLS, 234207 byte(s) sent to socket
2021.07.07 14:27:59 LOG7[0]: Remote descriptor (FD=11) closed
2021.07.07 14:27:59 LOG7[0]: Local descriptor (FD=3) closed
2021.07.07 14:27:59 LOG7[0]: Service [squid-gcp] finished (0 left)
2021.07.07 14:28:01 LOG7[1]: Service [squid-gcp] started
2021.07.07 14:28:01 LOG7[1]: Setting local socket options (FD=3)
2021.07.07 14:28:01 LOG7[1]: Option TCP_NODELAY set on local socket
2021.07.07 14:28:01 LOG5[1]: Service [squid-gcp] accepted connection from 127.0.0.1:50146
2021.07.07 14:28:01 LOG6[1]: s_connect: connecting 100.112.0.62:3128
2021.07.07 14:28:01 LOG7[1]: s_connect: s_poll_wait 100.112.0.62:3128: waiting 10 seconds
2021.07.07 14:28:01 LOG7[1]: FD=6 events=0x2001 revents=0x0
2021.07.07 14:28:01 LOG7[1]: FD=11 events=0x2005 revents=0x0
2021.07.07 14:28:01 LOG5[1]: s_connect: connected 100.112.0.62:3128
2021.07.07 14:28:01 LOG5[1]: Service [squid-gcp] connected remote server from 100.112.0.63:50396
2021.07.07 14:28:01 LOG7[1]: Setting remote socket options (FD=11)
2021.07.07 14:28:01 LOG7[1]: Option TCP_NODELAY set on remote socket
2021.07.07 14:28:01 LOG7[1]: Remote descriptor (FD=11) initialized
2021.07.07 14:28:01 LOG6[1]: SNI: sending servername: squid.internal
2021.07.07 14:28:01 LOG6[1]: Peer certificate not required
2021.07.07 14:28:01 LOG7[1]: TLS state (connect): before SSL initialization
2021.07.07 14:28:01 LOG7[1]: TLS state (connect): SSLv3/TLS write client hello
2021.07.07 14:28:01 LOG3[1]: SSL_connect: Peer suddenly disconnected
2021.07.07 14:28:01 LOG5[1]: Connection reset: 0 byte(s) sent to TLS, 0 byte(s) sent to socket
2021.07.07 14:28:01 LOG7[1]: Remote descriptor (FD=11) closed
2021.07.07 14:28:01 LOG7[1]: Local descriptor (FD=3) closed
2021.07.07 14:28:01 LOG7[1]: Service [squid-gcp] finished (0 left)

it clearly looks like first request TLS negotiation succeed while second one is not even started.

logs from squid access log:

07/Jul/2021:14:27:59 +0000 1625668079.646    496 100.112.0.63 TCP_TUNNEL/200 234207 CONNECT github.com:443 - HIER_DIRECT/140.82.121.4 - "/CN=test.internal"
07/Jul/2021:14:28:01 +0000 1625668081.958      0 100.112.0.63 NONE/000 0 NONE error:transaction-end-before-headers - HIER_NONE/- - "-"

Logs from cache:

2021/07/07 14:28:01 kid1| Error negotiating SSL connection on FD 11: error:00000001:lib(0):func(0):reason(1) (1/-1)

BONUS

When I try to use openssl s_client and then GET https://github.com like this:

openssl s_client -cert /etc/letsencrypt/live/test.internal/cert.pem -key /etc/letsencrypt/live/test.internal/privkey.pem -connect squid.internal:3128

each request is successful:

log from squid:

07/Jul/2021:14:33:24 +0000 1625668404.188    369 100.112.0.63 TCP_MISS/200 227308 GET https://github.com/ - HIER_DIRECT/140.82.121.4 text/html "/CN=test.internal"
07/Jul/2021:14:33:50 +0000 1625668430.041     25 100.112.0.63 TCP_MISS/200 227578 GET https://github.com/ - HIER_DIRECT/140.82.121.4 text/html "/CN=test.internal"
07/Jul/2021:14:33:55 +0000 1625668435.218     39 100.112.0.63 TCP_MISS/200 227580 GET https://github.com/ - HIER_DIRECT/140.82.121.4 text/html "/CN=test.internal"

I am loosing my mind with this problem. I would appreciate any help with this.


Get this bounty!!!

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.