samba server log level 10 data interpretation help
Shirish Pargaonkar
shirishpargaonkar at gmail.com
Mon Jun 23 01:13:38 GMT 2008
Hi,
I have this part of the samba server log at log level 10.
Based on the log, I was looking for the confirmation that the whether
samba server
received a request Write Andx (0x2f 47) with mid 0xB634 and pid 0x56D5
and responded to that request and that was the last request it received and
responded before client to this samba server disconnected.
[2008/06/16 08:40:15, 6] smbd/process.c:process_smb(1067)
got message type 0x0 of len 0xe040
[2008/06/16 08:40:15, 3] smbd/process.c:process_smb(1068)
Transaction 13724 of length 57412
[2008/06/16 08:40:15, 5] lib/util.c:show_msg(506)
[2008/06/16 08:40:15, 5] lib/util.c:show_msg(516)
size=57408
smb_com=0x2f
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=0
smb_flg2=49153
smb_tid=4
smb_pid=22229
smb_uid=0
smb_mid=46644
smt_wct=14
smb_vwv[ 0]= 255 (0xFF)
smb_vwv[ 1]= 0 (0x0)
smb_vwv[ 2]= 5755 (0x167B)
smb_vwv[ 3]=49152 (0xC000)
smb_vwv[ 4]= 6 (0x6)
smb_vwv[ 5]=65535 (0xFFFF)
smb_vwv[ 6]=65535 (0xFFFF)
smb_vwv[ 7]= 0 (0x0)
smb_vwv[ 8]= 0 (0x0)
smb_vwv[ 9]= 0 (0x0)
smb_vwv[10]=57344 (0xE000)
smb_vwv[11]= 64 (0x40)
smb_vwv[12]= 0 (0x0)
smb_vwv[13]= 0 (0x0)
smb_bcc=57345
[2008/06/16 08:40:15, 10] lib/util.c:dump_data(2286)
[000] 00 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F ./////// ////////
[010] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[020] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[030] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[040] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[050] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[060] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[070] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[080] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[090] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[0A0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[0B0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[0C0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[0D0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[0E0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[0F0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[100] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[110] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[120] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[130] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[140] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[150] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[160] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[170] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[180] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[190] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[1A0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[1B0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[1C0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[1D0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[1E0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[1F0] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// ////////
[2008/06/16 08:40:15, 3] smbd/process.c:switch_message(926)
switch message SMBwriteX (pid 26808) conn 0x2aaaafd4a50
[2008/06/16 08:40:15, 3] smbd/sec_ctx.c:set_sec_ctx(241)
setting sec ctx (99, 99) - sec_ctx_stack_ndx = 0
[2008/06/16 08:40:15, 5] auth/auth_util.c:debug_nt_user_token(454)
NT user token of user S-1-22-1-99
contains 5 SIDs
SID[ 0]: S-1-22-1-99
SID[ 1]: S-1-22-2-99
SID[ 2]: S-1-1-0
SID[ 3]: S-1-5-2
SID[ 4]: S-1-5-32-546
SE_PRIV 0x0 0x0 0x0 0x0
[2008/06/16 08:40:15, 5] auth/auth_util.c:debug_unix_user_token(474)
UNIX token of user 99
Primary group is 99 and contains 1 supplementary groups
Group[ 0]: 99
[2008/06/16 08:40:15, 5] smbd/uid.c:change_to_user(273)
change_to_user uid=(99,99) gid=(0,99)
[2008/06/16 08:40:15, 4] smbd/vfs.c:vfs_ChDir(665)
vfs_ChDir to /SAMBA4
[2008/06/16 08:40:15, 10] locking/locking.c:is_locked(99)
is_locked: optimisation - exclusive oplock on file
p1/d1/dcXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/d11/d12XXXXXXXXXXX/
d27XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
/f1aXXXXX
[2008/06/16 08:40:15, 10] locking/locking.c:is_locked(137)
is_locked: flavour = POSIX_LOCK brl start=442368 len=57344 unlocked for fnum
5755 file
p1/d1/dcXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/d11/d12XXXXXXXXXXX/
d27XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
/f1aXXXXX
[2008/06/16 08:40:15, 10] smbd/fileio.c:real_write_file(137)
real_write_file
(p1/d1/dcXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/d11/d12XXXXXXXXXXX
/d27XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
X/f1aXXXXX): pos = 442368, size = 57344, returned 57344
[2008/06/16 08:40:15, 3] smbd/reply.c:reply_write_and_X(3154)
writeX fnum=5755 num=57344 wrote=57344
[2008/06/16 08:40:15, 5] lib/util.c:show_msg(506)
[2008/06/16 08:40:15, 5] lib/util.c:show_msg(516)
size=47
smb_com=0x2f
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=128
smb_flg2=49153
smb_tid=4
smb_pid=22229
smb_uid=0
smb_mid=46644
smt_wct=6
smb_vwv[ 0]= 255 (0xFF)
smb_vwv[ 1]= 0 (0x0)
smb_vwv[ 2]=57344 (0xE000)
smb_vwv[ 3]= 0 (0x0)
smb_vwv[ 4]= 0 (0x0)
smb_vwv[ 5]= 0 (0x0)
smb_bcc=0
[2008/06/16 08:40:15, 10] lib/util_sock.c:read_smb_length_return_keepalive(623)
got smb length of 70419
[2008/06/16 08:40:36, 10] lib/util_sock.c:read_data(525)
read_data: read of 15700 returned 0. Error = Success
[2008/06/16 08:40:36, 3] smbd/process.c:timeout_processing(1328)
timeout_processing: End of file from client (client has disconnected).
There is a corrosponding cifs client log to go with this.
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: sends on sock 00000000021b4d00,
sndbuf 34776, rcvbuf 87380 of length 57408 stuck for 15 seconds, mid: 13494
pid: 22229, cmd: 47,
error: -11
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: No task to wake, unknown frame
received! NumMids 19, Mid 13494, Pid: 54614, cmd: 47
Jun 16 08:40:35 LAC0039 kernel: CIFS VFS: server not responding
Jun 16 08:40:36 LAC0039 kernel: CIFS VFS: Reconnect after server stopped
responding
Jun 16 08:40:36 LAC0039 kernel: CIFS VFS: Reconnecting tcp session
So I am suspecting there is a bug in either cifs client or the tcp/ip layer
on the client machine where it looks like a request is not sent over
the socket with
error EAGAIN yet it ends up on the samba server and gets a response.
Regards,
Shirish
More information about the samba-technical
mailing list