Large File Transfers on OpenBSD
Jason Coene
jason at datahiveserver.com
Tue Apr 2 14:15:01 GMT 2002
I did a level 10 debug log, and found something somewhat interesting...
Transferring a 1.5g file, the following pattern is logged (level 10):
......... (a bunch of dump-data stuff) .........
[2002/04/02 08:52:58, 10] lib/util.c:dump_data(1492)
[1F0] D4 6F F2 9C AC 52 54 1C 7B C9 1B 76 CB EC 74 D0 Ôoò.¬RT. {É.vËìtÐ
[2002/04/02 08:52:58, 6] lib/util_sock.c:write_socket(518)
write_socket(12,61503)
[2002/04/02 08:52:58, 6] lib/util_sock.c:write_socket(521)
write_socket(12,61503) wrote 61503
[2002/04/02 08:52:58, 10] lib/util_sock.c:read_smb_length_return_keepalive(560)
got smb length of 59
[2002/04/02 08:52:58, 6] smbd/process.c:process_smb(859)
got message type 0x0 of len 0x3b
[2002/04/02 08:52:58, 3] smbd/process.c:process_smb(860)
Transaction 3274 of length 63
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(275)
size=59
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=24
smb_flg2=26631
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(281)
smb_tid=1
smb_pid=65279
smb_uid=100
smb_mid=31232
smt_wct=12
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[0]=255 (0xFF)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[1]=57054 (0xDEDE)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[2]=5527 (0x1597)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[3]=28672 (0x7000)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[4]=2483 (0x9B3)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[5]=36864 (0x9000)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[6]=36864 (0x9000)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[7]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[8]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[9]=36864 (0x9000)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[10]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[11]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(291)
smb_bcc=0
[2002/04/02 08:52:58, 3] smbd/process.c:switch_message(667)
switch message SMBreadX (pid 228)
[2002/04/02 08:52:58, 4] smbd/uid.c:change_to_user(118)
change_to_user: Skipping user change - already user
[2002/04/02 08:52:58, 10] smbd/fileio.c:seek_file(61)
seek_file: requested pos = 162754560, new pos = 162754560
[2002/04/02 08:52:58, 3] smbd/reply.c:reply_read_and_X(2382)
readX fnum=5527 min=36864 max=36864 nread=36864
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(275)
size=36923
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=136
smb_flg2=1
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(281)
smb_tid=1
smb_pid=65279
smb_uid=100
smb_mid=31232
smt_wct=12
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[0]=255 (0xFF)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[1]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[2]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[3]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[4]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[5]=36864 (0x9000)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[6]=59 (0x3B)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[7]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[8]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[9]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[10]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[11]=0 (0x0)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(291)
smb_bcc=36864
However, on the last transmit (where it stops), it only gets this far:
[2002/04/02 08:52:58, 10] lib/util.c:dump_data(1492)
[1F0] 25 8D 0A 0B 9C 3D A5 54 09 F1 30 A9 30 0B EE A6 %....=¥T .ñ0©0.î¦
[2002/04/02 08:52:58, 6] lib/util_sock.c:write_socket(518)
write_socket(12,36927)
[2002/04/02 08:52:58, 6] lib/util_sock.c:write_socket(521)
write_socket(12,36927) wrote 36927
[2002/04/02 08:52:58, 10] lib/util_sock.c:read_smb_length_return_keepalive(560)
got smb length of 59
[2002/04/02 08:52:58, 6] smbd/process.c:process_smb(859)
got message type 0x0 of len 0x3b
[2002/04/02 08:52:58, 3] smbd/process.c:process_smb(860)
Transaction 3275 of length 63
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(275)
size=59
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=24
smb_flg2=26631
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(281)
smb_tid=1
smb_pid=65279
smb_uid=100
smb_mid=31296
smt_wct=12
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[0]=255 (0xFF)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
smb_vwv[1]=57054 (0xDEDE)
[2002/04/02 08:52:58, 5] lib/util.c:show_msg(286)
(does NOT say smb_vwv[2]....)
then it goes directly into:
[2002/04/02 08:53:00, 5] lib/util_sock.c:print_socket_options(109)
socket option SO_KEEPALIVE = 8
[2002/04/02 08:53:00, 5] lib/util_sock.c:print_socket_options(109)
socket option SO_REUSEADDR = 4
....more socket options....
....read config....
....dir list and idle....
Looking at the code itself, it seems like its a for loop with a finite end, and no breaking point in the loop, therefore the process is getting killed from somewhere (unless im missing something). Anyone know what would be the possible causes? I did a panic action=, and there was no panic.
Regards,
Jason
> -----Original Message-----
> From: "Esh, Andrew" <AEsh at tricord.com>
> Sent: April 2, 2002, 11:09 AM
> Subject: RE: Large File Transfers on OpenBSD
>
>This has to be a local compilation, configuration, or runtime environment
>problem. I've been a part of a large-file testing effort, and Samba is
>capable of storing them. My platform is Redhat 7.1, i386.
>
>In your log, it looks like the daemon is picking up fresh connections after
>the pause. Maybe it crashed and was restarted. Notice the bind, and the
>negProt. Did the level 10 logs show anything from loadparam after the pause,
>or "Closing connections" or "panic" before it?
>
>Another thing to try is run Ethereal (www.ethereal.com) on one end of the
>network connection. Then look at the packet delta times in the packet trace,
>and find out which end failed to transmit prior to the pause. If it was
>Windows, then I would look at what the last thing Samba sent to Windows. If
>it was Samba, then I look in the logs to find out what caused Samba to stop.
>(Get an update of Ethereal if you haven't in a while. The SMB packet decodes
>have improved immensely, lately.)
>
>Also, compare a transfer with the same files from Windows to Windows. Use
>Ethereal to find the pattern of the transfer. What breaks that pattern when
>Samba is on one end? How is the pattern different?
>
>-----Original Message-----
>From: Jason Coene [mailto:jason at datahiveserver.com]
>Sent: Sunday, March 31, 2002 7:25 PM
>To: samba-technical at lists.samba.org
>Subject: Large File Transfers on OpenBSD
>
>
>
>Ive been debugging some problems with transferring large amounts of data on
>OpenBSD+Samba. Getting or Putting files upwards of 500 MB just seem to stop
>randomly, this is on OpenBSD systems 2.8, 2.9, and 3.0 acting as the server.
>
>I've tried transferring files using:
> - smbclient put file from openbsd to openbsd
> - smbclient put file from openbsd to win2k
> - win2k get file from openbsd
> - win2k copy file from openbsd to openbsd
>
>The copies from win explorer return error "The specified network name is no
>longer available"
>
>The puts from smbclient die with "Profiling timer expired"
>
>Modifying socket options in smb.conf do effect when it happens, the lower
>SNDBUF/RCVBUF, the shorter it takes to time out.
>
>Using debug level = 4, here is what happens just as windows gives the error:
>
>[2002/03/31 12:14:43, 4] smbd/uid.c:change_to_user(118)
> change_to_user: Skipping user change - already user
>[2002/03/31 12:14:43, 3] smbd/reply.c:reply_read_and_X(2382)
> readX fnum=4442 min=61440 max=61440 nread=61440
>[2002/03/31 12:14:43, 3] smbd/process.c:process_smb(860)
> Transaction 9557 of length 63
>[2002/03/31 12:14:43, 3] smbd/process.c:switch_message(667)
> switch message SMBreadX (pid 3330)
>[2002/03/31 12:14:43, 4] smbd/uid.c:change_to_user(118)
> change_to_user: Skipping user change - already user
>[2002/03/31 12:14:43, 3] smbd/reply.c:reply_read_and_X(2382)
> readX fnum=4442 min=61440 max=61440 nread=61440
>[2002/03/31 12:14:43, 3] smbd/process.c:process_smb(860)
> Transaction 9558 of length 63
>[2002/03/31 12:14:43, 3] smbd/process.c:switch_message(667)
> switch message SMBreadX (pid 3330)
>[2002/03/31 12:14:43, 4] smbd/uid.c:change_to_user(118)
> change_to_user: Skipping user change - already user
>[2002/03/31 12:14:43, 3] smbd/reply.c:reply_read_and_X(2382)
> readX fnum=4442 min=20480 max=20480 nread=20480
>
>Then 2 seconds later:
>
>[2002/03/31 12:14:45, 3] smbd/oplock.c:init_oplocks(1184)
> open_oplock_ipc: opening loopback UDP socket.
>[2002/03/31 12:14:45, 3] lib/util_sock.c:open_socket_in(798)
> bind succeeded on port 0
>[2002/03/31 12:14:45, 3] smbd/oplock.c:init_oplocks(1215)
> open_oplock ipc: pid = 3331, global_oplock_port = 42042
>[2002/03/31 12:14:45, 4] lib/time.c:get_serverzone(122)
> Serverzone is 18000
>[2002/03/31 12:14:45, 3] smbd/process.c:process_smb(860)
> Transaction 0 of length 72
>[2002/03/31 12:14:45, 2] smbd/reply.c:reply_special(92)
> netbios connect: name1=OBSD30T name2=JASON2
>[2002/03/31 12:14:45, 2] smbd/reply.c:reply_special(111)
> netbios connect: local=obsd30t remote=jason2
>[2002/03/31 12:14:45, 3] smbd/process.c:process_smb(860)
> Transaction 1 of length 137
>[2002/03/31 12:14:45, 3] smbd/process.c:switch_message(667)
> switch message SMBnegprot (pid 3331)
>[2002/03/31 12:14:45, 3] smbd/sec_ctx.c:set_sec_ctx(314)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
>[2002/03/31 12:14:45, 3] smbd/negprot.c:reply_negprot(348)
> Requested protocol [PC NETWORK PROGRAM 1.0]
>
>[More protocol negotiation stuff, and directory refresh by windows]
>
>I bumped log level up to 5, but nothing stuck out at me. Does anyone know of
>anything that might be creating this problem?
>
>Here are some additional tidbits of potentially useful information:
>
> - If we try the file copy more than 1 time without restarting smbd, it
>seems to die quicker on additional tries.
>
> - Sometimes I can copy a 500mb file fine, but not 1/3 of a 1g file.
>
> - Hardware differs:
> 2.8: via 686a chipset, intel 1g cpu, realtek ethernet
> 2.9: 440bx chipset, intel 500m cpu, intel ethernet
> 3.0: via 686b chipset, intel 1g cpu, intel ethernet
>
> - all 100mbps ethernet, however note that this problem does NOT happen when
>on a 10mbit hub.
>
>Any ideas of what this could be?
>
>
>Thanks,
>
>Jason
>
More information about the samba-technical
mailing list