[stunnel-users] transfer() loop executes not transferring any data and truncated data when using unix sockets
Stephen Balukoff
sbalukoff at bluebox.net
Tue Feb 5 02:39:18 CET 2013
Hello, y'all!
I've recruited the help of my colleague Dustin Lundquist, and he's
been able to create a reproducible test case for this bug, which will
hopefully shed some more light on this. We're specifically seeing two
error behaviors which we haven't yet been able to determine whether
they're related. These are:
1. transfer() loop error, generating an error code telling us to
contact Michal.Trojnara at mirt.net
2. truncated response from the web server (always at byte 46693, for
whatever reason).
These errors can occur independently or simultaneously, and
occasionally not at all on different runs of the same script on the
same machine. When we attempt to strace the stunnel process, the
problem goes away entirely, which screams to me of a timing issue or
race condition. In any case, it's a bit of a heisenbug, which is
annoying in and of itself.
And, again, these go away when we communicate to the back-end web
server process using TCP sockets instead of unix sockets.
Attached are output from the four permutations of the above bug, as
well as the sample perl script used to generate them.
If anyone has any ideas of how we might go about fixing this one, or
knows what significant difference between TCP and unix sockets might
be causing the error here, we'd love to hear it!
Stephen
On Thu, Jan 24, 2013 at 6:18 PM, Stephen Balukoff <sbalukoff at bluebox.net> wrote:
> Hello!
>
> Recently we started seeing some erroneous behavior in one of our load
> balancer configurations in which we're using stunnel for SSL tunnel
> termination with web clients. Specifically, the setup looks like the
> following:
>
>
> Web client ---(SSL)---> stunnel ---(unix socket)--> haproxy
> ---(tcp/http)---> web server
>
> After extensive troubleshooting we were able to determine that when
> the following parameters are present:
>
> * Client forces non-keepalive connection
> * Client generates a POST request, the response to which (generated by
> the back-end web server) is greater than about 8k
> * stunnel and haproxy communicate via unix socket
>
> ...then most responses end up being truncated by an extraneous TCP RST
> packet from stunnel, and the following log lines are generated:
>
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> transfer() loop executes not transferring any data
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]: please
> report the problem to Michal.Trojnara at mirt.net
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]: stunnel
> 4.54 on x86_64-unknown-linux-gnu platform
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> Compiled/running with OpenSSL 1.0.0-fips 29 Mar 2010
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> Threading:PTHREAD SSL:+ENGINE+OCSP+FIPS Auth:none Sockets:POLL+IPv6
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> protocol=TLSv1, SSL_pending=0
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> sock_open_rd=n, sock_open_wr=Y
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> SSL_RECEIVED_SHUTDOWN=n, SSL_SENT_SHUTDOWN=Y
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> sock_can_rd=Y, sock_can_wr=n
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> ssl_can_rd=n, ssl_can_wr=n
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> read_wants_read=Y, read_wants_write=n
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> write_wants_read=n, write_wants_write=n
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]:
> shutdown_wants_read=n, shutdown_wants_write=n
> Jan 23 15:24:17 ds420a stunnel: LOG3[22586:139835614443264]: socket
> input buffer: 0 byte(s), ssl input buffer: 0 byte(s)
>
> The work arounds we have found are either:
>
> 1. Make stunnel and haproxy communicate over a TCP socket bound to
> the loopback interface (less ideal, as then we're limited to 65k
> connections)
> 2. Add the "reset=no" parameter to our stunnel.conf (which seems to
> fix the problem, but makes me wonder if we're not opening ourselves up
> to other problems-- like really getting stuck in an infinite loop
> that that watchdog is intended to avoid.)
>
> In any case based on what "reset=no" is supposed to do as well as
> where that first line of the error output above is being generated in
> the code, it's clear that the main client data transfer loop in
> client.c (starting line 519) is being called too often with no data to
> transfer, which triggers the infinite loop detection in the transfer()
> function (client.c, starting line 832).
>
> My best hypothesis at this point is that the transfer() code was
> written only with TCP sockets in mind, and that something about the
> unix socket in use here is triggering that loop too often. Maybe
> s_poll_wait on line 541 is being called with parameters which are
> right for a TCP socket but inappropriate for a unix socket? At this
> point though, we're at the limit of my socket programming ability, so
> I'm a little stuck. (Would like to have simply fixed this and
> submitted a patch... but cest la vie, eh.)
>
> We'd like to avoid using a TCP socket to communicate between stunnel
> and haproxy simply because it's a little less efficient, and because
> there's an artificial 65k limit on the number of back-end connections
> we can support per loopback IP if we do that. Alternatively, if
> someone could verify that "reset=no" is an acceptable / safe work
> around in this case, I'd appreciate that (though, of course, I'd
> prefer my logs not to get spammed on every connection. :P )
>
> Is there any other data I can provide to help troubleshoot and fix this?
>
> Thanks,
> Stephen
>
>
>
> --
> Stephen Balukoff
> Blue Box Group, LLC
> (800)613-4305 x807
--
Stephen Balukoff
Blue Box Group, LLC
(800)613-4305 x807
-------------- next part --------------
# failure-transfer_loop_not_transferring_only.txt
[dustin at lilthing stunnel_test (master)]$ ./test_truncated_response.pl q
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Clients allowed=500
2013.02.04 16:49:25 LOG5[10172:140602188109568]: stunnel 4.54 on x86_64-unknown-linux-gnu platform
2013.02.04 16:49:25 LOG5[10172:140602188109568]: Compiled/running with OpenSSL 1.0.1c 10 May 2012
2013.02.04 16:49:25 LOG5[10172:140602188109568]: Threading:PTHREAD SSL:+ENGINE+OCSP Auth:none Sockets:POLL+IPv6
2013.02.04 16:49:25 LOG5[10172:140602188109568]: Reading configuration from file /tmp/stunnel.conf-Jp7kuB
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Compression not enabled
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Snagged 64 random bytes from /home/dustin/.rnd
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Wrote 1024 new random bytes to /home/dustin/.rnd
2013.02.04 16:49:25 LOG7[10172:140602188109568]: PRNG seeded successfully
2013.02.04 16:49:25 LOG6[10172:140602188109568]: Initializing service [127.0.0.1]
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Certificate: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Certificate loaded
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Key file: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Private key loaded
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Could not load DH parameters from /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Using hardcoded DH parameters
2013.02.04 16:49:25 LOG7[10172:140602188109568]: DH initialized with 2048-bit key
2013.02.04 16:49:25 LOG7[10172:140602188109568]: ECDH initialized with curve prime256v1
2013.02.04 16:49:25 LOG7[10172:140602188109568]: SSL options set: 0x01400004
2013.02.04 16:49:25 LOG5[10172:140602188109568]: Configuration successful
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Service [127.0.0.1] (FD=7) bound to 127.0.0.1:4443
2013.02.04 16:49:25 LOG7[10172:140602188109568]: Created pid file /tmp/ATa4qfkteO.pid
2013.02.04 16:49:26 LOG7[10172:140602188109568]: Service [127.0.0.1] accepted (FD=3) from 127.0.0.1:53712
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Service [127.0.0.1] started
2013.02.04 16:49:26 LOG5[10172:140602188240640]: Service [127.0.0.1] accepted connection from 127.0.0.1:53712
2013.02.04 16:49:26 LOG6[10172:140602188240640]: connect_blocking: connecting localhost:/tmp/oG0Om_dihw.sock
2013.02.04 16:49:26 LOG5[10172:140602188240640]: connect_blocking: connected localhost:/tmp/oG0Om_dihw.sock
2013.02.04 16:49:26 LOG5[10172:140602188240640]: Service [127.0.0.1] connected remote server from unnamed socket
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Remote socket (FD=8) initialized
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Option TCP_NODELAY not supported on remote socket
2013.02.04 16:49:26 LOG6[10172:140602188240640]: Server-mode proxy protocol negotiations started
2013.02.04 16:49:26 LOG7[10172:140602188240640]: -> PROXY TCP4 127.0.0.1 127.0.0.1 53712 4443
2013.02.04 16:49:26 LOG6[10172:140602188240640]: Server-mode proxy protocol negotiations succeeded
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): before/accept initialization
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 read client hello A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 write server hello A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 write certificate A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 write key exchange A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 write server done A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 flush data
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 read client key exchange A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 read finished A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 write change cipher spec A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 write finished A
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL state (accept): SSLv3 flush data
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 1 items in the session cache
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 client connects (SSL_connect())
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 client connects that finished
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 client renegotiations requested
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 1 server connects (SSL_accept())
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 1 server connects that finished
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 server renegotiations requested
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 session cache hits
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 external session cache hits
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 session cache misses
2013.02.04 16:49:26 LOG7[10172:140602188240640]: 0 session cache timeouts
2013.02.04 16:49:26 LOG6[10172:140602188240640]: SSL accepted: new session negotiated
2013.02.04 16:49:26 LOG6[10172:140602188240640]: Negotiated TLSv1/SSLv3 ciphersuite: ECDHE-RSA-RC4-SHA (128-bit encryption)
2013.02.04 16:49:26 LOG6[10172:140602188240640]: Compression: null, expansion: null
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Socket closed on read
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Sending close_notify alert
2013.02.04 16:49:26 LOG7[10172:140602188240640]: SSL alert (write): warning: close notify
2013.02.04 16:49:26 LOG6[10172:140602188240640]: SSL_shutdown successfully sent close_notify alert
2013.02.04 16:49:26 LOG3[10172:140602188240640]: transfer() loop executes not transferring any data
2013.02.04 16:49:26 LOG3[10172:140602188240640]: please report the problem to Michal.Trojnara at mirt.net
2013.02.04 16:49:26 LOG3[10172:140602188240640]: stunnel 4.54 on x86_64-unknown-linux-gnu platform
2013.02.04 16:49:26 LOG3[10172:140602188240640]: Compiled/running with OpenSSL 1.0.1c 10 May 2012
2013.02.04 16:49:26 LOG3[10172:140602188240640]: Threading:PTHREAD SSL:+ENGINE+OCSP Auth:none Sockets:POLL+IPv6
2013.02.04 16:49:26 LOG3[10172:140602188240640]: protocol=TLSv1.2, SSL_pending=0
2013.02.04 16:49:26 LOG3[10172:140602188240640]: sock_open_rd=n, sock_open_wr=Y
2013.02.04 16:49:26 LOG3[10172:140602188240640]: SSL_RECEIVED_SHUTDOWN=n, SSL_SENT_SHUTDOWN=Y
2013.02.04 16:49:26 LOG3[10172:140602188240640]: sock_can_rd=Y, sock_can_wr=n
2013.02.04 16:49:26 LOG3[10172:140602188240640]: ssl_can_rd=n, ssl_can_wr=n
2013.02.04 16:49:26 LOG3[10172:140602188240640]: read_wants_read=Y, read_wants_write=n
2013.02.04 16:49:26 LOG3[10172:140602188240640]: write_wants_read=n, write_wants_write=n
2013.02.04 16:49:26 LOG3[10172:140602188240640]: shutdown_wants_read=n, shutdown_wants_write=n
2013.02.04 16:49:26 LOG3[10172:140602188240640]: socket input buffer: 0 byte(s), ssl input buffer: 0 byte(s)
2013.02.04 16:49:26 LOG5[10172:140602188240640]: Connection reset: 56459 byte(s) sent to SSL, 78 byte(s) sent to socket
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Remote socket (FD=8) closed
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Local socket (FD=3) closed
2013.02.04 16:49:26 LOG7[10172:140602188240640]: Service [127.0.0.1] finished (0 left)
Cleaning up ...
2013.02.04 16:49:27 LOG7[10172:140602188109568]: Dispatching signals from the signal pipe
2013.02.04 16:49:27 LOG7[10172:140602188109568]: Processing SIGNAL_TERMINATE
2013.02.04 16:49:27 LOG5[10172:140602188109568]: Terminated
2013.02.04 16:49:27 LOG7[10172:140602188109568]: Closing service [127.0.0.1]
2013.02.04 16:49:27 LOG7[10172:140602188109568]: Service [127.0.0.1] closed (FD=7)
2013.02.04 16:49:27 LOG7[10172:140602188109568]: Sessions cached before flush: 1
2013.02.04 16:49:27 LOG7[10172:140602188109568]: Sessions cached after flush: 0
2013.02.04 16:49:27 LOG7[10172:140602188109568]: Service [127.0.0.1] closed
2013.02.04 16:49:27 LOG7[10172:140602188109568]: str_stats: 12 block(s), 1069 data byte(s), 696 control byte(s)
2013.02.04 16:49:27 LOG7[10172:140602188109568]: removing pid file /tmp/ATa4qfkteO.pid
-------------- next part --------------
# failure-truncated_response_and_transfer_loop_not_transferring.txt
[dustin at lilthing stunnel_test]$ ./test_truncated_response.pl
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Clients allowed=500
2013.02.04 16:16:45 LOG5[9097:140657847547648]: stunnel 4.54 on x86_64-unknown-linux-gnu platform
2013.02.04 16:16:45 LOG5[9097:140657847547648]: Compiled/running with OpenSSL 1.0.1c 10 May 2012
2013.02.04 16:16:45 LOG5[9097:140657847547648]: Threading:PTHREAD SSL:+ENGINE+OCSP Auth:none Sockets:POLL+IPv6
2013.02.04 16:16:45 LOG5[9097:140657847547648]: Reading configuration from file /tmp/stunnel.conf-ML5VqX
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Compression not enabled
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Snagged 64 random bytes from /home/dustin/.rnd
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Wrote 1024 new random bytes to /home/dustin/.rnd
2013.02.04 16:16:45 LOG7[9097:140657847547648]: PRNG seeded successfully
2013.02.04 16:16:45 LOG6[9097:140657847547648]: Initializing service [127.0.0.1]
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Certificate: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Certificate loaded
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Key file: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Private key loaded
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Could not load DH parameters from /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Using hardcoded DH parameters
2013.02.04 16:16:45 LOG7[9097:140657847547648]: DH initialized with 2048-bit key
2013.02.04 16:16:45 LOG7[9097:140657847547648]: ECDH initialized with curve prime256v1
2013.02.04 16:16:45 LOG7[9097:140657847547648]: SSL options set: 0x01400004
2013.02.04 16:16:45 LOG5[9097:140657847547648]: Configuration successful
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Service [127.0.0.1] (FD=7) bound to 127.0.0.1:4443
2013.02.04 16:16:45 LOG7[9097:140657847547648]: Created pid file /tmp/fldctGzcQA.pid
2013.02.04 16:16:46 LOG7[9097:140657847547648]: Service [127.0.0.1] accepted (FD=3) from 127.0.0.1:53670
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Service [127.0.0.1] started
2013.02.04 16:16:46 LOG5[9097:140657847678720]: Service [127.0.0.1] accepted connection from 127.0.0.1:53670
2013.02.04 16:16:46 LOG6[9097:140657847678720]: connect_blocking: connecting localhost:/tmp/uH7sHKe5cs.sock
2013.02.04 16:16:46 LOG5[9097:140657847678720]: connect_blocking: connected localhost:/tmp/uH7sHKe5cs.sock
2013.02.04 16:16:46 LOG5[9097:140657847678720]: Service [127.0.0.1] connected remote server from unnamed socket
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Remote socket (FD=8) initialized
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Option TCP_NODELAY not supported on remote socket
2013.02.04 16:16:46 LOG6[9097:140657847678720]: Server-mode proxy protocol negotiations started
2013.02.04 16:16:46 LOG7[9097:140657847678720]: -> PROXY TCP4 127.0.0.1 127.0.0.1 53670 4443
2013.02.04 16:16:46 LOG6[9097:140657847678720]: Server-mode proxy protocol negotiations succeeded
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): before/accept initialization
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 read client hello A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 write server hello A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 write certificate A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 write key exchange A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 write server done A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 flush data
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 read client key exchange A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 read finished A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 write change cipher spec A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 write finished A
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL state (accept): SSLv3 flush data
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 1 items in the session cache
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 client connects (SSL_connect())
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 client connects that finished
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 client renegotiations requested
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 1 server connects (SSL_accept())
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 1 server connects that finished
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 server renegotiations requested
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 session cache hits
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 external session cache hits
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 session cache misses
2013.02.04 16:16:46 LOG7[9097:140657847678720]: 0 session cache timeouts
2013.02.04 16:16:46 LOG6[9097:140657847678720]: SSL accepted: new session negotiated
2013.02.04 16:16:46 LOG6[9097:140657847678720]: Negotiated TLSv1/SSLv3 ciphersuite: ECDHE-RSA-RC4-SHA (128-bit encryption)
2013.02.04 16:16:46 LOG6[9097:140657847678720]: Compression: null, expansion: null
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Socket closed on read
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Sending close_notify alert
2013.02.04 16:16:46 LOG7[9097:140657847678720]: SSL alert (write): warning: close notify
2013.02.04 16:16:46 LOG6[9097:140657847678720]: SSL_shutdown successfully sent close_notify alert
2013.02.04 16:16:46 LOG3[9097:140657847678720]: transfer() loop executes not transferring any data
2013.02.04 16:16:46 LOG3[9097:140657847678720]: please report the problem to Michal.Trojnara at mirt.net
2013.02.04 16:16:46 LOG3[9097:140657847678720]: stunnel 4.54 on x86_64-unknown-linux-gnu platform
2013.02.04 16:16:46 LOG3[9097:140657847678720]: Compiled/running with OpenSSL 1.0.1c 10 May 2012
2013.02.04 16:16:46 LOG3[9097:140657847678720]: Threading:PTHREAD SSL:+ENGINE+OCSP Auth:none Sockets:POLL+IPv6
2013.02.04 16:16:46 LOG3[9097:140657847678720]: protocol=TLSv1.2, SSL_pending=0
2013.02.04 16:16:46 LOG3[9097:140657847678720]: sock_open_rd=n, sock_open_wr=Y
2013.02.04 16:16:46 LOG3[9097:140657847678720]: SSL_RECEIVED_SHUTDOWN=n, SSL_SENT_SHUTDOWN=Y
2013.02.04 16:16:46 LOG3[9097:140657847678720]: sock_can_rd=Y, sock_can_wr=n
2013.02.04 16:16:46 LOG3[9097:140657847678720]: ssl_can_rd=n, ssl_can_wr=n
2013.02.04 16:16:46 LOG3[9097:140657847678720]: read_wants_read=Y, read_wants_write=n
2013.02.04 16:16:46 LOG3[9097:140657847678720]: write_wants_read=n, write_wants_write=n
2013.02.04 16:16:46 LOG3[9097:140657847678720]: shutdown_wants_read=n, shutdown_wants_write=n
2013.02.04 16:16:46 LOG3[9097:140657847678720]: socket input buffer: 0 byte(s), ssl input buffer: 0 byte(s)
2013.02.04 16:16:46 LOG5[9097:140657847678720]: Connection reset: 46693 byte(s) sent to SSL, 78 byte(s) sent to socket
curl exited with 4608
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Remote socket (FD=8) closed
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Local socket (FD=3) closed
2013.02.04 16:16:46 LOG7[9097:140657847678720]: Service [127.0.0.1] finished (0 left)
-------------- next part --------------
# failure-truncated_response_only.txt
[dustin at lilthing stunnel_test (master)]$ ./test_truncated_response.pl q
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Clients allowed=500
2013.02.04 16:20:30 LOG5[9490:140257671452416]: stunnel 4.54 on x86_64-unknown-linux-gnu platform
2013.02.04 16:20:30 LOG5[9490:140257671452416]: Compiled/running with OpenSSL 1.0.1c 10 May 2012
2013.02.04 16:20:30 LOG5[9490:140257671452416]: Threading:PTHREAD SSL:+ENGINE+OCSP Auth:none Sockets:POLL+IPv6
2013.02.04 16:20:30 LOG5[9490:140257671452416]: Reading configuration from file /tmp/stunnel.conf-SyQ1Pv
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Compression not enabled
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Snagged 64 random bytes from /home/dustin/.rnd
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Wrote 1024 new random bytes to /home/dustin/.rnd
2013.02.04 16:20:30 LOG7[9490:140257671452416]: PRNG seeded successfully
2013.02.04 16:20:30 LOG6[9490:140257671452416]: Initializing service [127.0.0.1]
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Certificate: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Certificate loaded
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Key file: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Private key loaded
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Could not load DH parameters from /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Using hardcoded DH parameters
2013.02.04 16:20:30 LOG7[9490:140257671452416]: DH initialized with 2048-bit key
2013.02.04 16:20:30 LOG7[9490:140257671452416]: ECDH initialized with curve prime256v1
2013.02.04 16:20:30 LOG7[9490:140257671452416]: SSL options set: 0x01400004
2013.02.04 16:20:30 LOG5[9490:140257671452416]: Configuration successful
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Service [127.0.0.1] (FD=7) bound to 127.0.0.1:4443
2013.02.04 16:20:30 LOG7[9490:140257671452416]: Created pid file /tmp/PIgTvMCbGo.pid
2013.02.04 16:20:31 LOG7[9490:140257671452416]: Service [127.0.0.1] accepted (FD=3) from 127.0.0.1:53695
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Service [127.0.0.1] started
2013.02.04 16:20:31 LOG5[9490:140257671583488]: Service [127.0.0.1] accepted connection from 127.0.0.1:53695
2013.02.04 16:20:31 LOG6[9490:140257671583488]: connect_blocking: connecting localhost:/tmp/30WftvWzoe.sock
2013.02.04 16:20:31 LOG5[9490:140257671583488]: connect_blocking: connected localhost:/tmp/30WftvWzoe.sock
2013.02.04 16:20:31 LOG5[9490:140257671583488]: Service [127.0.0.1] connected remote server from unnamed socket
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Remote socket (FD=8) initialized
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Option TCP_NODELAY not supported on remote socket
2013.02.04 16:20:31 LOG6[9490:140257671583488]: Server-mode proxy protocol negotiations started
2013.02.04 16:20:31 LOG7[9490:140257671583488]: -> PROXY TCP4 127.0.0.1 127.0.0.1 53695 4443
2013.02.04 16:20:31 LOG6[9490:140257671583488]: Server-mode proxy protocol negotiations succeeded
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): before/accept initialization
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 read client hello A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 write server hello A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 write certificate A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 write key exchange A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 write server done A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 flush data
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 read client key exchange A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 read finished A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 write change cipher spec A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 write finished A
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL state (accept): SSLv3 flush data
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 1 items in the session cache
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 client connects (SSL_connect())
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 client connects that finished
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 client renegotiations requested
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 1 server connects (SSL_accept())
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 1 server connects that finished
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 server renegotiations requested
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 session cache hits
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 external session cache hits
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 session cache misses
2013.02.04 16:20:31 LOG7[9490:140257671583488]: 0 session cache timeouts
2013.02.04 16:20:31 LOG6[9490:140257671583488]: SSL accepted: new session negotiated
2013.02.04 16:20:31 LOG6[9490:140257671583488]: Negotiated TLSv1/SSLv3 ciphersuite: ECDHE-RSA-RC4-SHA (128-bit encryption)
2013.02.04 16:20:31 LOG6[9490:140257671583488]: Compression: null, expansion: null
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Socket closed on read
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Sending close_notify alert
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL alert (write): warning: close notify
2013.02.04 16:20:31 LOG6[9490:140257671583488]: SSL_shutdown successfully sent close_notify alert
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL alert (read): warning: close notify
2013.02.04 16:20:31 LOG7[9490:140257671583488]: SSL closed on SSL_read
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Sent socket write shutdown
2013.02.04 16:20:31 LOG5[9490:140257671583488]: Connection closed: 46693 byte(s) sent to SSL, 78 byte(s) sent to socket
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Remote socket (FD=8) closed
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Local socket (FD=3) closed
2013.02.04 16:20:31 LOG7[9490:140257671583488]: Service [127.0.0.1] finished (0 left)
curl exited with 4608
Cleaning up ...
2013.02.04 16:20:32 LOG7[9490:140257671452416]: Dispatching signals from the signal pipe
2013.02.04 16:20:32 LOG7[9490:140257671452416]: Processing SIGNAL_TERMINATE
2013.02.04 16:20:32 LOG5[9490:140257671452416]: Terminated
2013.02.04 16:20:32 LOG7[9490:140257671452416]: Closing service [127.0.0.1]
2013.02.04 16:20:32 LOG7[9490:140257671452416]: Service [127.0.0.1] closed (FD=7)
2013.02.04 16:20:32 LOG7[9490:140257671452416]: Sessions cached before flush: 1
2013.02.04 16:20:32 LOG7[9490:140257671452416]: Sessions cached after flush: 0
2013.02.04 16:20:32 LOG7[9490:140257671452416]: Service [127.0.0.1] closed
2013.02.04 16:20:32 LOG7[9490:140257671452416]: str_stats: 12 block(s), 1069 data byte(s), 696 control byte(s)
2013.02.04 16:20:32 LOG7[9490:140257671452416]: removing pid file /tmp/PIgTvMCbGo.pid
-------------- next part --------------
# success.txt
[dustin at lilthing stunnel_test (master)]$ ./test_truncated_response.pl q
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Clients allowed=500
2013.02.04 16:23:01 LOG5[9612:140081952995072]: stunnel 4.54 on x86_64-unknown-linux-gnu platform
2013.02.04 16:23:01 LOG5[9612:140081952995072]: Compiled/running with OpenSSL 1.0.1c 10 May 2012
2013.02.04 16:23:01 LOG5[9612:140081952995072]: Threading:PTHREAD SSL:+ENGINE+OCSP Auth:none Sockets:POLL+IPv6
2013.02.04 16:23:01 LOG5[9612:140081952995072]: Reading configuration from file /tmp/stunnel.conf-wkKU3j
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Compression not enabled
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Snagged 64 random bytes from /home/dustin/.rnd
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Wrote 1024 new random bytes to /home/dustin/.rnd
2013.02.04 16:23:01 LOG7[9612:140081952995072]: PRNG seeded successfully
2013.02.04 16:23:01 LOG6[9612:140081952995072]: Initializing service [127.0.0.1]
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Certificate: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Certificate loaded
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Key file: /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Private key loaded
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Could not load DH parameters from /home/dustin/src/stunnel_test/snakeoil.pem
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Using hardcoded DH parameters
2013.02.04 16:23:01 LOG7[9612:140081952995072]: DH initialized with 2048-bit key
2013.02.04 16:23:01 LOG7[9612:140081952995072]: ECDH initialized with curve prime256v1
2013.02.04 16:23:01 LOG7[9612:140081952995072]: SSL options set: 0x01400004
2013.02.04 16:23:01 LOG5[9612:140081952995072]: Configuration successful
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Service [127.0.0.1] (FD=7) bound to 127.0.0.1:4443
2013.02.04 16:23:01 LOG7[9612:140081952995072]: Created pid file /tmp/Vg_C7a1sv5.pid
2013.02.04 16:23:02 LOG7[9612:140081952995072]: Service [127.0.0.1] accepted (FD=3) from 127.0.0.1:53702
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Service [127.0.0.1] started
2013.02.04 16:23:02 LOG5[9612:140081953126144]: Service [127.0.0.1] accepted connection from 127.0.0.1:53702
2013.02.04 16:23:02 LOG6[9612:140081953126144]: connect_blocking: connecting localhost:/tmp/ntX3qeXKnX.sock
2013.02.04 16:23:02 LOG5[9612:140081953126144]: connect_blocking: connected localhost:/tmp/ntX3qeXKnX.sock
2013.02.04 16:23:02 LOG5[9612:140081953126144]: Service [127.0.0.1] connected remote server from unnamed socket
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Remote socket (FD=8) initialized
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Option TCP_NODELAY not supported on remote socket
2013.02.04 16:23:02 LOG6[9612:140081953126144]: Server-mode proxy protocol negotiations started
2013.02.04 16:23:02 LOG7[9612:140081953126144]: -> PROXY TCP4 127.0.0.1 127.0.0.1 53702 4443
2013.02.04 16:23:02 LOG6[9612:140081953126144]: Server-mode proxy protocol negotiations succeeded
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): before/accept initialization
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 read client hello A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 write server hello A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 write certificate A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 write key exchange A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 write server done A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 flush data
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 read client key exchange A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 read finished A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 write change cipher spec A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 write finished A
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL state (accept): SSLv3 flush data
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 1 items in the session cache
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 client connects (SSL_connect())
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 client connects that finished
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 client renegotiations requested
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 1 server connects (SSL_accept())
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 1 server connects that finished
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 server renegotiations requested
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 session cache hits
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 external session cache hits
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 session cache misses
2013.02.04 16:23:02 LOG7[9612:140081953126144]: 0 session cache timeouts
2013.02.04 16:23:02 LOG6[9612:140081953126144]: SSL accepted: new session negotiated
2013.02.04 16:23:02 LOG6[9612:140081953126144]: Negotiated TLSv1/SSLv3 ciphersuite: ECDHE-RSA-RC4-SHA (128-bit encryption)
2013.02.04 16:23:02 LOG6[9612:140081953126144]: Compression: null, expansion: null
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Socket closed on read
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Sending close_notify alert
2013.02.04 16:23:02 LOG7[9612:140081953126144]: SSL alert (write): warning: close notify
2013.02.04 16:23:02 LOG6[9612:140081953126144]: SSL_shutdown successfully sent close_notify alert
2013.02.04 16:23:02 LOG5[9612:140081953126144]: Error detected on SSL (read) file descriptor: Connection reset by peer (104)
2013.02.04 16:23:02 LOG5[9612:140081953126144]: Connection reset: 56459 byte(s) sent to SSL, 78 byte(s) sent to socket
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Remote socket (FD=8) closed
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Local socket (FD=3) closed
2013.02.04 16:23:02 LOG7[9612:140081953126144]: Service [127.0.0.1] finished (0 left)
Cleaning up ...
2013.02.04 16:23:03 LOG7[9612:140081952995072]: Dispatching signals from the signal pipe
2013.02.04 16:23:03 LOG7[9612:140081952995072]: Processing SIGNAL_TERMINATE
2013.02.04 16:23:03 LOG5[9612:140081952995072]: Terminated
2013.02.04 16:23:04 LOG7[9612:140081952995072]: Closing service [127.0.0.1]
2013.02.04 16:23:04 LOG7[9612:140081952995072]: Service [127.0.0.1] closed (FD=7)
2013.02.04 16:23:04 LOG7[9612:140081952995072]: Sessions cached before flush: 1
2013.02.04 16:23:04 LOG7[9612:140081952995072]: Sessions cached after flush: 0
2013.02.04 16:23:04 LOG7[9612:140081952995072]: Service [127.0.0.1] closed
2013.02.04 16:23:04 LOG7[9612:140081952995072]: str_stats: 12 block(s), 1069 data byte(s), 696 control byte(s)
2013.02.04 16:23:04 LOG7[9612:140081952995072]: removing pid file /tmp/Vg_C7a1sv5.pid
-------------- next part --------------
A non-text attachment was scrubbed...
Name: test_truncated_response.pl
Type: application/octet-stream
Size: 3226 bytes
Desc: not available
URL: <http://www.stunnel.org/pipermail/stunnel-users/attachments/20130204/bdfe3820/attachment.obj>
More information about the stunnel-users
mailing list