Re^2: 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.

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

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]
Re^4: IO::Socket::SSL sometimes says 'SSL wants a read first' by noxxi (Pilgrim) on Apr 20, 2017 at 19:41 UTC
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]
Re^5: IO::Socket::SSL sometimes says 'SSL wants a read first' by salva (Canon) on Apr 20, 2017 at 20:22 UTC
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]
Re^6: IO::Socket::SSL sometimes says 'SSL wants a read first' by noxxi (Pilgrim) on Apr 21, 2017 at 05:03 UTC
Re^7: IO::Socket::SSL sometimes says 'SSL wants a read first' by salva (Canon) on Apr 21, 2017 at 07:46 UTC
Some notes below your chosen depth have not been shown here


There's more than one way to do things
	PerlMonks