samba - Sep 2011 - cli_push returned NT_STATUS_IO_TIMEOUT

Hello all,


I'm having a problem with smbclient after an upgrade from 3.0.37 to  
3.5.3 (I also tested 3.5.11 and 3.6.0).

The client uses a command similar to:

   tar -cz /some/directory | smbclient '\\server_ip\share' -N -c
'put
- "\directory\filename"'

After that the client checks the exit status to determine if the  
transfer succeeded or failed.

The server is running samba 3.2.5.


With samba-3.0.37 this worked without problem;

With samba-3.5.3 the transfer regularly fails. The moment that is  
fails is different... normally it should transfer about 16GB of data  
but I have seen it fail after 2GB, 8GB and after 13GB.


Looking at a tcpdump shows:
- at 04:00:07: a packet is send from the client to the server that  
contains data (wireshark identifies it as 'Write AndX Request')
- at 04:00:07: a packet is send from the server to the client to  
confirm the data (wireshark identifies it as 'Write AndX Response')
- at 04:00:14: a packet is send from the client to the server which  
contains a 'Close Request'.

Reproducing it is somewhat successful and somewhat unsuccessful:

When I replace the 'tar -cz' command with a command that sleeps 20  
seconds then I'm able to reproduce the error. With a delay of 19  
seconds this is not reproducible;
But this is not the same as the real command since this shows a delay  
of only 7 seconds.


The test script used is attached to this mail.
What it does:
* It outputs a list of 'a'
* It sleeps 20 seconds
* It outputs a list of 'b'.


Running it with samba-3.5.3:
$ perl test.pl 20  | smbclient '\\server_ip\share' -N -c 'put -  
"\directory\filename"' ; echo $?
Sending data 'a'
Anonymous login successful
Domain=[......] OS=[Unix] Server=[Samba 3.2.5]
Sending data 'a' done
Sleep done
Sending data 'b'
cli_push returned NT_STATUS_IO_TIMEOUT
putting file - as \directory\filename (100.4 kb/s) (average 100.4 kb/s)


The last lines of a smbclient -d10:

dos_clean_name [\\directory\filename]
unix_clean_name [\directory\filename]
Sending data 'a' done
Sleep done
Sending data 'b'
putting file - as \directory\filename Running timed event  
"tevent_req_timedout" 0xb8032c58
cli_push returned NT_STATUS_IO_TIMEOUT
(99.6 kb/s) (average 99.6 kb/s)
write_socket(4,39)
write_socket(4,39) wrote 39



Running it with samba-3.6.0:

$ perl test.pl 20  | smbclient '\\server_ip\share' -N -c 'put -  
"\directory\filename"' ; echo $?
Sending data 'a'
WARNING: The security=share option is deprecated
Anonymous login successful
Domain=[......] OS=[Unix] Server=[Samba 3.2.5]
Sending data 'a' done
Sleep done
Sending data 'b'
cli_push returned NT_STATUS_IO_TIMEOUT
putting file - as \directory\filename (100.1 kb/s) (average 100.1 kb/s)



The last lines of a smbclient -d10:
[2011/09/19 12:02:20,  0] libsmb/clidfs.c:227(do_connect)
   Domain=[.....] OS=[Unix] Server=[Samba 3.2.5]
[2011/09/19 12:02:20,  4] libsmb/clidfs.c:233(do_connect)
    session setup ok
[2011/09/19 12:02:20, 10] libsmb/clitrans.c:299(cli_trans_format)
   num_setup=1, max_setup=0, param_total=44, this_param=44,  
max_param=2, data_total=0, this_data=0, max_data=16644,  
param_offset=68, param_pad=0, param_disp=0, data_offset=112,  
data_pad=0, data_disp=0
[2011/09/19 12:02:20,  4] libsmb/clidfs.c:276(do_connect)
    tconx ok
[2011/09/19 12:02:20,  3] lib/util.c:435(dos_clean_name)
   dos_clean_name [\\directory\filename]
[2011/09/19 12:02:20,  3] lib/util.c:487(unix_clean_name)
   unix_clean_name [\directory\filename]
[2011/09/19 12:02:20,  1] client/client.c:1872(do_put)
   putting file - as \ndirectory\filename Running timed event  
"tevent_req_timedout" 0xb80399a0
cli_push returned NT_STATUS_IO_TIMEOUT
[2011/09/19 12:02:40,  1] client/client.c:1911(do_put)
   (100.3 kb/s) (average 100.3 kb/s)



Some questions:

a) can others reproduce this?

b) is it expected that the exit status of smbclient is 0?
The transfer failed so I, sort of, expected an exit status of 1 (or at  
least != 0)

c) is this timeout expected?
To me 'tevent_req_timedout' suggest that it is a timeout added when  
sending a request.
Shouldn't the timeout/timer/.. be cleared when the response on the  
request is received?

d) is it possible to change the value of the timeout?



Best regards,

Bram

>
> The test script used is attached to this mail.
> What it does:
> * It outputs a list of 'a'
> * It sleeps 20 seconds
> * It outputs a list of 'b'.
It appears that the list server removed the attachment..
inline version of the test script:

$ cat test.pl
#!/usr/bin/perl -l

use strict;
use warnings;

$|++;

my $sleep = shift;
print STDERR "Sending data 'a'";
print "a" x 2048000;
print STDERR "Sending data 'a' done";
sleep $sleep;
print STDERR "Sleep done";
print STDERR "Sending data 'b'";
print "b" x 2048000;
print STDERR "Sending data 'b' done";

Quoting Bram <fnzon at lists.wizbit.be>:
> I'm having a problem with smbclient after an upgrade from 3.0.37 to
> 3.5.3 (I also tested 3.5.11 and 3.6.0).
>
> The client uses a command similar to:
>
>   tar -cz /some/directory | smbclient '\\server_ip\share' -N -c
'put  -
> "\directory\filename"'
>
...
>
> Some questions:
>
...
>
> b) is it expected that the exit status of smbclient is 0?
> The transfer failed so I, sort of, expected an exit status of 1 (or at
> least != 0)
This is not expected;
A bug for this already exists:

   Bug 7551 - smbclient does not return proper exit code
   https://bugzilla.samba.org/show_bug.cgi?id=7551

>
> c) is this timeout expected?
After discussing it on #samba-technical it was suggested that a bug  
report be created for it:

   Bug 8498 - smbclient: cli_push returned NT_STATUS_IO_TIMEOUT
   https://bugzilla.samba.org/show_bug.cgi?id=8498


Best regards,

Bram