in reply to IO::Socket::SSL sometimes says 'SSL wants a read first'

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.
  • Comment on Re: IO::Socket::SSL sometimes says 'SSL wants a read first'

Replies are listed 'Best First'.
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]
      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]
        I'm not sure what you expect as the correct behavior for EINTR. In my experience the correct behavior is that the program has to explicitly deal with this case, typically by restarting the operation. This is the case for both non-SSL and SSL sockets.
[reply]

In Section Seekers of Perl Wisdom