IO::Socket::SSL sometimes says 'SSL wants a read first'

FloydATC has asked for the wisdom of the Perl Monks concerning the following question:

Hi,

I'm trying to write an SSL proxy using IO::Socket::SSL::Intercept in order to do DNS based inspection of traffic to a specific host, and it's mostly working except I'm seeing strange intermittent failures when trying to connect to the real SSL server on behalf of the client. Here is the relevant code:

    # SSL connect to server
    my $retry = 10;
    my $server = undef;
    while ($retry > 0) {
        $server = IO::Socket::SSL->new(
            PeerAddr    => $host,
            PeerPort    => "https",
        );
        if ($server && $server->connected()) {
            print "proxy $$ connected to server\n";
            last;
        } else {
            $retry--;
            warn "proxy $$ connect to server failed: $!,".IO::Socket::
+SSL::errstr();
            warn "proxy $$ ".($retry ? 'will retry' : 'giving up')."\n
+";
        }
    }
[download]

And here is a typical result. Sometimes it will work the first time, sometimes it has to retry a few times:

proxy 4730 connect to server failed: Interrupted system call,SSL wants
+ a read first at ./proxy line 110.
proxy 4730 will retry
proxy 4730 connected to server
[download]

I'm not seeing this against all hosts, which leads me to believe that there may be something strange going on at the far end, but I'd rather have some input from people who have done this sort of thing before I start pointing fingers.

# uname -a
Linux redacted 4.6.0-kali1-amd64 #1 SMP Debian 4.6.4-1kali1 (2016-07-2
+1) x86_64 GNU/Linux

This is perl 5, version 22, subversion 2 (v5.22.2) built for x86_64-li
+nux-gnu-thread-multi
IO::Socket::SSL    2.037
Net::SSLeay 1.77
[download]

Interestingly, IO::Socket::SSL debugging seems to indicate it is 'ignoring' this as a 'less severe local error' but in fact the connection fails:

DEBUG: .../IO/Socket/SSL.pm:753: done Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:763: ssl handshake in progress
DEBUG: ...5.22/IO/Socket.pm:48: ignoring less severe local error 'IO::
+Socket::IP configuration failed', keep 'SSL wants a read first'
DEBUG: .../IO/Socket/SSL.pm:2777: free ctx 44390832 open=44390832 4401
+1664 43990720
DEBUG: .../IO/Socket/SSL.pm:2782: free ctx 44390832 callback
DEBUG: .../IO/Socket/SSL.pm:2789: OK free ctx 44390832
proxy 4824 connect to server failed: Interrupted system call,SSL wants
+ a read first at ./proxy line 110.
[download]

Any thoughts on how to fix this?

-- FloydATC

I got 99 problems, most of them have to do with printers.

Comment on IO::Socket::SSL sometimes says 'SSL wants a read first' Select or Download Code

Replies are listed 'Best First'.
Re: IO::Socket::SSL sometimes says 'SSL wants a read first' by salva (Canon) on Apr 20, 2017 at 07:29 UTC
It seems to me that some signal is interrupting a socket read operation and the module is unable to recover from that (a bug). Try running your program with strace.	[reply]
Re^2: IO::Socket::SSL sometimes says 'SSL wants a read first' by FloydATC (Deacon) on Apr 20, 2017 at 15:40 UTC
Hmm. I played around with strace for a little while and caught something: connect(5, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr +("xxx.xxx.xxx.xxx")}, 16) = 0 write(2, "DEBUG: .../IO/Socket/SSL.pm:626:"..., 50) = 50 write(2, "DEBUG: .../IO/Socket/SSL.pm:648:"..., 59) = 59 write(2, "DEBUG: .../IO/Socket/SSL.pm:681:"..., 73) = 73 write(2, "DEBUG: .../IO/Socket/SSL.pm:750:"..., 59) = 59 write(5, "\26\3\1\0\304\1\0\0\300\3\3\330\244`@\317nOS\365\211\236\367 +\1jW\232\224\227u\2\232"..., 201) = 201 read(5, "\26\3\3\0B\2\0", 7) = 7 read(5, "\0>\3\3D\1\312\225\362\33'$S;\0362~m{\177\324\230\246\24\223\ +270\"Zx\273\207\331"..., 64) = 64 read(5, "\26\3\3\24q", 5) = 5 read(5, "\v\0\24m\0\24j\0\4\2770\202\4\2730\202\3\243\240\3\2\1\2\2\20 +\20\263n\214j\232\263"..., 5233) = 1372 read(5, "\4\3\23%USERTrust RSA Certification "..., 3861) = 1448 read(5, "Trust AB1&0$\6\3U\4\v\23\35AddTrust Exte"..., 2413) = 1200 read(5, "\217\213\300nC}\303\241\200l\262\36\274S\205}\334\220\241\244 +\274-\357FrW5\5\277\273F\273"..., 1213) = 1213 stat("/usr/lib/ssl/certs/3e205b44.0", 0x7fffba55b620) = -1 ENOENT (No +such file or directory) stat("/usr/lib/ssl/certs/fc5a8f99.0", {st_mode=S_IFREG\|0644, st_size=2 +094, ...}) = 0 open("/usr/lib/ssl/certs/fc5a8f99.0", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG\|0644, st_size=2094, ...}) = 0 read(6, "-----BEGIN CERTIFICATE-----\nMIIF"..., 4096) = 2094 read(6, "", 4096) = 0 close(6) = 0 stat("/usr/lib/ssl/certs/fc5a8f99.1", 0x7fffba55b620) = -1 ENOENT (No +such file or directory) write(2, "DEBUG: .../IO/Socket/SSL.pm:2609"..., 240) = 240 write(2, "DEBUG: .../IO/Socket/SSL.pm:2609"..., 189) = 189 write(2, "DEBUG: .../IO/Socket/SSL.pm:2609"..., 154) = 154 write(2, "DEBUG: .../IO/Socket/SSL.pm:1679"..., 63) = 63 write(2, "DEBUG: .../IO/Socket/SSL.pm:1689"..., 114) = 114 read(5, "\26\3\3\1M", 5) = 5 read(5, "\f\0\1I\3\0\27A\4\300@N\245jt\235\371\227\346\221\250\261\242 +H\36\f\321\323\235\n\316X"..., 333) = 230 read(5, 0x1b4596e, 103) = ? ERESTARTSYS (To be restart +ed if SA_RESTART is set) --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=13871, si_ui +d=0, si_status=0, si_utime=0, si_stime=0} --- rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system + call) rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 rt_sigaction(SIGCHLD, NULL, {sa_handler=0x4a1a50, sa_mask=[], sa_flags +=SA_RESTORER, sa_restorer=0x7f5c5131deb0}, 8) = 0 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 13 +871 write(1, "proxy 13751 child 13871 terminat"..., 35) = 35 wait4(-1, 0x7fffba55b824, WNOHANG, NULL) = -1 ECHILD (No child process +es) rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0 rt_sigaction(SIGCHLD, {sa_handler=0x4a1a50, sa_mask=[], sa_flags=SA_RE +STORER, sa_restorer=0x7f5c5131deb0}, {sa_handle r=0x4a1a50, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f5c5131de +b0}, 8) = 0 rt_sigprocmask(SIG_SETMASK, [CHLD], NULL, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [CHLD], NULL, 8) = 0 write(2, "DEBUG: .../IO/Socket/SSL.pm:753:"..., 65) = 65 write(2, "DEBUG: .../IO/Socket/SSL.pm:763:"..., 59) = 59 write(2, "DEBUG: ...5.22/IO/Socket.pm:48: "..., 134) = 134 write(2, "DEBUG: .../IO/Socket/SSL.pm:2777"..., 84) = 84 write(2, "DEBUG: .../IO/Socket/SSL.pm:2782"..., 61) = 61 write(2, "DEBUG: .../IO/Socket/SSL.pm:2789"..., 55) = 55 close(5) = 0 write(2, "proxy 13751 connect to server fa"..., 106) = 106 write(2, "proxy 13751 will retry\n", 23) = 23 [download] The problem does indeed seem to coincide with an incoming SIGCHLD from a forked process, this would explain why it seems to occur randomly. I don't really need that signal handler for anything else than to see what's going on so I tried to set $SIG{CHLD}='IGNORE' and... although I don't understand why it should matter, the problem appears to have gone away. `$SIG{CHLD} = 'IGNORE'; #$SIG{CHLD} = \&reaper; #my %children = (); #sub reaper { # while( ( my $child = waitpid( -1, &WNOHANG ) ) > 0 ) { # print "proxy $$ child $child terminated\n"; # } # $SIG{CHLD} = \&reaper; #}` [download] Huh... Thank you!! :-) -- FloydATC I got 99 problems, most of them have to do with printers.	[reply] [d/l] [select]
Re^3: IO::Socket::SSL sometimes says 'SSL wants a read first' by salva (Canon) on Apr 20, 2017 at 17:22 UTC
That is surely a bug on IO::Socket::SSL or in IO::Socket::IP not handling `EINTR` errors correctly. You should report it!	[reply] [d/l]
Re^4: IO::Socket::SSL sometimes says 'SSL wants a read first' by noxxi (Pilgrim) on Apr 20, 2017 at 19:41 UTC
Re^5: IO::Socket::SSL sometimes says 'SSL wants a read first' by salva (Canon) on Apr 20, 2017 at 20:22 UTC
Some notes below your chosen depth have not been shown here
Re: IO::Socket::SSL sometimes says 'SSL wants a read first' by zentara (Cardinal) on Apr 20, 2017 at 16:23 UTC
Hi, I was looking at this in a similar situation in IO::Socket::SSL GTk2 server and multiple clients, and I'll mention it just to help shed light on WHY the error may be happening. As the expert noxxi pointed out in the comments, the ssh_context $ctx is useful when having multiple clients. In my testing, I would get your same error about "needing a read first" when the ssh handshake failed, as when trying to connect with a non-ssl enabled client. Look at my code there. Applying an individual context to your forks may narrow down why the handshake fails, or whatever happens. Hope it helps, and this code is pretty much what the examples of IO::Socket::SSL do. my $server = IO::Socket::SSL->can_ipv6 ->new( Listen => 5, LocalAddr => $address, Reuse => 1, timeout => .1 ) or die "failed to create SSL server at $address : $!"; my $ctx = IO::Socket::SSL::SSL_Context->new( SSL_server => 1, SSL_cert_file => './host.crt', SSL_key_file => './host.key', SSL_verify_mode => 0x00, #SSL_VERIFY_PEER \| SSL_VERIFY_FAIL_IF_NO +_PEER_CERT ) or die "cannot create context: $SSL_ERROR"; # in your forked child start the ssl with the $ctx context # test for SSL connection, if not close client IO::Socket::SSL->start_SSL($client, SSL_server => 1, SSL_reuse_ct +x => $ctx) or do { warn "ssl handshake failed: $SSL_ERROR\n"; my $peerAddress = $client->peerhost(); my $peerPort = $client->peerport(); warn "bad incoming from $peerAddress $peerPort\n"; [download] I'm not really a human, but I play one on earth. ..... an animated JAPH	[reply] [d/l]
Re: IO::Socket::SSL sometimes says 'SSL wants a read first' by noxxi (Pilgrim) on Apr 20, 2017 at 19:28 UTC
I don't think the code you show is enough to explain the problem. SSL wants to read first happens if non-blocking sockets are used or if you specify a timeout for the connection. The last case should be handled transparently for the user but in the first case you have to deal with want read first (SSL_WANT_READ) and want write first (SSL_WANT_WRITE) explicitly by waiting for the socket to be readable or writable using select or similar and then re-doing the failed action (read, write, connect_SSL, accept_SSL...) again. There is a part in the documentation of IO::Socket::SSL which deals with non-blocking sockets and describes how the handling differs from non-SSL sockets and what SSL_WANT_READ and SSL_WANT_WRITE mean. As for the error about Interrupted system call: I think the origin of this must be somewhere in the code you did not show. The strace you show indicates that there happens a SIGCHLD, so an exit of a sub-process might be the cause of this problem. As with SSL_WANT_* you need to continue with the current operation if EINTR happens but this is expected when dealing with non-SSL sockets too.	[reply]
Re: IO::Socket::SSL sometimes says 'SSL wants a read first' by Anonymous Monk on Apr 20, 2017 at 18:28 UTC
"I'm trying to write an SSL proxy using IO::Socket::SSL::Intercept in order to do DNS based inspection of traffic to a specific host" I just wanted to thank you for taking the time to show us what your intentions are. This goes a long way in understanding how to give you the BEST solution possible. Too many people will answer your question without regard to its consequence, leading to the continuation of bad practices and bad code.	[reply]