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.