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

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.

Replies are listed 'Best First'.
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]
      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]
        How do you restart new?

        What does the module user get for being able to handle EINTR errors himself that justifies not hidden those events inside the library?

        IMO, leaving EINTR handling to the user just makes writing reliable software with this module much harder. I am sure almost no code using IO::Socket::SSL out there actually handles EINTR correctly, and for those few cases, probably none does anything besides just retrying the last operation.

[reply]
[d/l]
[select]

In Section Seekers of Perl Wisdom