Bug #43670 for Net-FTPSSL: hang and busy loop if premature EOF while reading response

Thu Feb 26 12:13:58 2009 agrow [...] thegotonerd.com - Ticket created

Subject:

hang and busy loop if premature EOF while reading response

Review the response sub -- if the read returns zero (EOF), we just keep looping.

Thu Feb 26 17:30:54 2009 CLEACH [...] cpan.org - Correspondence added

Alan, I'll need some sample code & the trace in order to reproduce the problem & see what's happening. Hopefully your FTP server isn't doing someting non-standard. To turn on the trace, you'll need to add "Debug => 1" to your call to new(). That will cause the trace to write to STDERR. You can either redirect STDERR to a file or modify your test program to just reopen STDERR to the file to dump to. If it's ./t/10- complex.t that's hanging, then just send me the ./t/test_trace_log_new.txt file that this test automatically generates. Just be aware that you are to never call response() yourself in your code. That's an internal method & calling it yourself will always hang your program. So call last_message() if you needed the response in your program. Curtis

Thu Feb 26 17:30:55 2009 The RT System itself - Status changed from 'new' to 'open'

Thu Feb 26 18:11:22 2009 agrow [...] thegotonerd.com - Correspondence added

Just consider what happens when an FTP server, for whatever reason, decides to shutdown the socket before writing back a response. The sysread below returns 0 but nothing handles this condition. To the contrary, $data remains the empty string, and we keep on looping and getting 0 from the sysread. while ($sep eq "-") { my $read = sysread( $self, $data, 4096); unless( defined $read ) { $self->_croak_or_return (0, "Can't read ftps socket: $!"); return ($code); } ... } On Thu Feb 26 17:30:54 2009, CLEACH wrote: Show quoted text

> Alan, > > I'll need some sample code & the trace in order to reproduce the > problem & see what's happening. Hopefully your FTP server isn't doing > someting non-standard. To turn on the trace, you'll need to > add "Debug => 1" to your call to new(). That will cause the trace to > write to STDERR. > > You can either redirect STDERR to a file or modify your test program > to just reopen STDERR to the file to dump to. If it's ./t/10- > complex.t that's hanging, then just send me > the ./t/test_trace_log_new.txt file that this test automatically > generates. > > Just be aware that you are to never call response() yourself in your > code. That's an internal method & calling it yourself will always > hang your program. So call last_message() if you needed the response > in your program. > > Curtis

Fri Feb 27 12:12:12 2009 CLEACH [...] cpan.org - Correspondence added

I believe that sysread() is supposed to return undef in that case, not zero. But since I can't reproduce what you are seeing, and I have no sample code with a trace or server to exploit it, please try out the following code change to see if it resolves your issue. If it does, I'll make it part of v0.08 if it works for you & doesn't hurt other servers I test against. Show quoted text

> while ($sep eq "-") { > my $read = sysread( $self, $data, 4096); > # unless( defined $read ) { > unless( $read ) { > $self->_croak_or_return (0, "Can't read ftps socket: $!"); > return ($code); > }

With this change it will treat either undef or a value of zero as an error. If it still hangs it means IO::Socket::SSL::sysread() and Net::SSLeay::read() are the culprits or how you wrote your code or you are working with a real flakey server. If your FTP server regularly returns zero byte records before continuing with valid data, we'll have to look into another option for new() to say after a specific # of sequential zero byte records to consider the connection hosed. The default being to just ignore them like it does today if the new option isn't used. Please let me know how your test goes with the above code change. Also please advise which FTPSSL method your program is calling when you hit this problem. I can't really give you any more help without sample code & it's trace or being able to connect to your server myself. Since all you've said is you've found a bug, but not given me a way to trigger it. Nor have you given me your environment & version of Perl.

Fri Feb 27 13:43:09 2009 agrow [...] thegotonerd.com - Correspondence added

On Fri Feb 27 12:12:12 2009, CLEACH wrote: Show quoted text

> I believe that sysread() is supposed to return undef in that case, not

zero. From perldoc -f sysread: "Returns the number of bytes actually read, 0 at end of file, or undef if there was an error (in the latter case $! is also set)." Both 0 and undef are error cases, albeit different ones. In the premature EOF case, $! will either not be set or will correspond to some earlier error, so it's misleading to print it out if you just see EOF. Show quoted text

> But since I can't reproduce what you are seeing, and I have no > sample code with a trace or server to exploit it, please try out the > following code change to see if it resolves your issue. If it does, > I'll make it part of v0.08 if it works for you & doesn't hurt other > servers I test against.

This should work with the above caveat about $!. From the start, I probably should have mentioned that this bug was actually encountered in the wild, and given you the patch I ended up applying--basically your change except that the error cases are distinguished. Debug logging was on when this occurred and a PBSZ command had just been issued. Not that it really matters...an FTP server could misbehave and shutdown prematurely in response to any command, and the client should report this error immediately. To add a little bit more concrete evidence to the busy loop claim, I decided to strace the process after noticing it was at 100% cpu usage. Here's what I saw: $ strace -p 32082 ... read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 read(3, ""..., 5) = 0 ... $ cd /proc/32082/fd/ $ ls -l total 0 lr-x------ 1 user user 64 Feb 26 11:37 0 -> pipe:[45840078] l-wx------ 1 user user 64 Feb 26 11:37 1 -> pipe:[11266942] l-wx------ 1 user user 64 Feb 26 11:37 2 -> pipe:[11266942] lrwx------ 1 user user 64 Feb 26 11:37 3 -> socket:[45840086]

Mon Mar 02 11:25:35 2009 CLEACH [...] cpan.org - Correspondence added

Thank you for the details provided. I have made the change in my base code to detect this error as a separate error condition and this fix will be included in v0.08. I'll be closing this ticket once v0.08 comes out. In the mean time the full work arround is fairly simple in v0.07. Posted here again for everyone else to see since this same piece of code in response() had another issue as well: while ($sep eq "-") { my $read = sysread( $self, $data, 4096); unless( $read ) { # Not called as an object member in case $self not FTPSSL obj _croak_or_return ($self, 0, (defined $read) ? "Can't read command channel socket: $!" : "Unexpected EOF on command channel socket!"); return ($code); }

Tue Mar 03 12:13:14 2009 agrow [...] thegotonerd.com - Correspondence added

Great, thanks Curtis. On Mon Mar 02 11:25:35 2009, CLEACH wrote: Show quoted text

> Thank you for the details provided. I have made the change in my base > code to detect this error as a separate error condition and this fix > will be included in v0.08. I'll be closing this ticket once v0.08 > comes out.

Mon Mar 23 18:09:10 2009 CLEACH [...] cpan.org - Status changed from 'open' to 'resolved'

Mon Mar 23 18:09:10 2009 CLEACH [...] cpan.org - Fixed in 0.08 added