samba server log level 10 data interpretation help
Shirish Pargaonkar
shirishpargaonkar at gmail.com
Mon Jun 23 12:54:18 GMT 2008
What seems to be happening is, cifs is sending commands whose mid
and pid in smb header can be seen on samba log. Then comes this
write andx command for which cifs logs 'stuck on socket error'
yet I see that request on samba server and a response sent by
samba server and there is a corrosponding "unknown frame received'
response logged by cifs (with matching mid and pid in smb header).
After this write andx command for which socket returned error EAGAIN,
cifs does send few more requests and receives success on the socket but
there is no log of these requests on samba server.
So cifs is thinking the requests have been sent successfully yet
samba server has not received any of those and does not respond and
cifs timesout and reconnects.
Here is the supporting cifs log entries and samba server log mixed
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid: 13490, pid: 22241,
cmd: 50
1670833 size=198
1670834 smb_com=0x32
1670835 smb_rcls=0
1670836 smb_reh=0
1670837 smb_err=0
1670838 smb_flg=0
1670839 smb_flg2=49153
1670840 smb_tid=4
1670841 smb_pid=22241
1670842 smb_uid=0
1670843 smb_mid=45620
1670844 smt_wct=15
1670845 smb_vwv[ 0]= 132 (0x84)
1670846 smb_vwv[ 1]= 0 (0x0)
1670847 smb_vwv[ 2]= 2 (0x2)
1670848 smb_vwv[ 3]= 4000 (0xFA0)
1670849 smb_vwv[ 4]= 0 (0x0)
1670850 smb_vwv[ 5]= 0 (0x0)
1670851 smb_vwv[ 6]= 0 (0x0)
1670852 smb_vwv[ 7]= 0 (0x0)
1670853 smb_vwv[ 8]= 0 (0x0)
1670854 smb_vwv[ 9]= 132 (0x84)
1670855 smb_vwv[10]= 66 (0x42)
1670856 smb_vwv[11]= 0 (0x0)
1670857 smb_vwv[12]= 0 (0x0)
1670858 smb_vwv[13]= 1 (0x1)
1670859 smb_vwv[14]= 5 (0x5)
1670860 smb_bcc=133
1670861 [2008/06/16 08:40:15, 10] lib/util.c:dump_data(2286)
1670862 [000] 00 00 02 00 00 00 00 2F 00 70 00 64 00 2F 00 64
......./ .p.d./.d
1670863 [010] 00 35 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.5.X.X.X .X.X.X.X
1670864 [020] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670865 [030] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670866 [040] 00 2F 00 64 00 31 00 61 00 58 00 58 00 2F 00 64
./.d.1.a .X.X./.d
1670867 [050] 00 31 00 63 00 58 00 58 00 58 00 58 00 58 00 58
.1.c.X.X .X.X.X.X
1670868 [060] 00 58 00 58 00 58 00 58 00 2F 00 66 00 33 00 33
.X.X.X.X ./.f.3.3
1670869 [070] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670870 [080] 00 58 00 00 00 .X...
1670871 [2008/06/16 08:40:15, 3] smbd/process.c:switch_message(926)
1670872 switch message SMBtrans2 (pid 26808) conn 0x2aaaafd4a50
1670906 size=35
1670907 smb_com=0x32
1670908 smb_rcls=52
1670909 smb_reh=0
1670910 smb_err=49152
1670911 smb_flg=128
1670912 smb_flg2=49217
1670913 smb_tid=4
1670914 smb_pid=22241
1670915 smb_uid=0
1670916 smb_mid=45620
1670917 smt_wct=0
1670918 smb_bcc=0
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid: 13491, pid: 22426,
cmd: 50
1670927 size=616
1670928 smb_com=0x32
1670929 smb_rcls=0
1670930 smb_reh=0
1670931 smb_err=0
1670932 smb_flg=0
1670933 smb_flg2=49153
1670934 smb_tid=2
1670935 smb_pid=22426
1670936 smb_uid=0
1670937 smb_mid=45876
1670938 smt_wct=15
1670939 smb_vwv[ 0]= 550 (0x226)
1670940 smb_vwv[ 1]= 0 (0x0)
1670941 smb_vwv[ 2]= 2 (0x2)
1670942 smb_vwv[ 3]= 4000 (0xFA0)
1670943 smb_vwv[ 4]= 0 (0x0)
1670944 smb_vwv[ 5]= 0 (0x0)
1670945 smb_vwv[ 6]= 0 (0x0)
1670946 smb_vwv[ 7]= 0 (0x0)
1670947 smb_vwv[ 8]= 0 (0x0)
1670948 smb_vwv[ 9]= 550 (0x226)
1670949 smb_vwv[10]= 66 (0x42)
1670950 smb_vwv[11]= 0 (0x0)
1670951 smb_vwv[12]= 0 (0x0)
1670952 smb_vwv[13]= 1 (0x1)
1670953 smb_vwv[14]= 5 (0x5)
1670954 smb_bcc=551
1670955 [2008/06/16 08:40:15, 10] lib/util.c:dump_data(2286)
1670956 [000] 00 00 02 00 00 00 00 2F 00 70 00 35 00 2F 00 64
......./ .p.5./.d
1670957 [010] 00 34 00 58 00 2F 00 64 00 61 00 58 00 58 00 58
.4.X./.d .a.X.X.X
1670958 [020] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670959 [030] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670960 [040] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670961 [050] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670962 [060] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670963 [070] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670964 [080] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670965 [090] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1670966 [0A0] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.X.X.X.X .X.X.X.X
1671034 [2008/06/16 08:40:15, 5] lib/util.c:show_msg(516)
1671035 size=160
1671036 smb_com=0x32
1671037 smb_rcls=0
1671038 smb_reh=0
1671039 smb_err=0
1671040 smb_flg=128
1671041 smb_flg2=49217
1671042 smb_tid=2
1671043 smb_pid=22426
1671044 smb_uid=0
1671045 smb_mid=45876
1671046 smt_wct=10
1671047 smb_vwv[ 0]= 2 (0x2)
1671048 smb_vwv[ 1]= 100 (0x64)
1671049 smb_vwv[ 2]= 0 (0x0)
1671050 smb_vwv[ 3]= 2 (0x2)
1671051 smb_vwv[ 4]= 56 (0x38)
1671052 smb_vwv[ 5]= 0 (0x0)
1671053 smb_vwv[ 6]= 100 (0x64)
1671054 smb_vwv[ 7]= 60 (0x3C)
1671055 smb_vwv[ 8]= 0 (0x0)
1671056 smb_vwv[ 9]= 0 (0x0)
1671057 smb_bcc=105
1671058 [2008/06/16 08:40:15, 10] lib/util.c:dump_data(2286)
1671059 [000] 00 00 00 00 00 AD 30 11 00 00 00 00 00 00 00 02
......0. ........
1671060 [010] 00 00 00 00 00 80 74 EA 1E AE CF C8 01 80 93 F4
......t. ........
1671061 [020] 18 AE CF C8 01 80 74 EA 1E AE CF C8 01 63 00 00
......t. .....c..
1671062 [030] 00 00 00 00 00 63 00 00 00 00 00 00 00 00 00 00
.....c.. ........
1671063 [040] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
........ ........
1671064 [050] 00 89 EA 01 00 00 00 00 00 F6 01 00 00 00 00 00
........ ........
1671065 [060] 00 01 00 00 00 00 00 00 00 ........ .
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid: 13492, pid: 22232,
cmd: 50,
1671073 [2008/06/16 08:40:15, 5] lib/util.c:show_msg(516)
1671074 size=114
1671075 smb_com=0x32
1671076 smb_rcls=0
1671077 smb_reh=0
1671078 smb_err=0
1671079 smb_flg=0
1671080 smb_flg2=49153
1671081 smb_tid=4
1671082 smb_pid=22232
1671083 smb_uid=0
1671084 smb_mid=46132
1671085 smt_wct=15
1671086 smb_vwv[ 0]= 48 (0x30)
1671087 smb_vwv[ 1]= 0 (0x0)
1671088 smb_vwv[ 2]= 2 (0x2)
1671089 smb_vwv[ 3]= 4000 (0xFA0)
1671090 smb_vwv[ 4]= 0 (0x0)
1671091 smb_vwv[ 5]= 0 (0x0)
1671092 smb_vwv[ 6]= 0 (0x0)
1671093 smb_vwv[ 7]= 0 (0x0)
1671094 smb_vwv[ 8]= 0 (0x0)
1671095 smb_vwv[ 9]= 48 (0x30)
1671096 smb_vwv[10]= 66 (0x42)
1671097 smb_vwv[11]= 0 (0x0)
1671098 smb_vwv[12]= 0 (0x0)
1671099 smb_vwv[13]= 1 (0x1)
1671100 smb_vwv[14]= 5 (0x5)
1671101 smb_bcc=49
1671102 [2008/06/16 08:40:15, 10] lib/util.c:dump_data(2286)
1671103 [000] 00 00 02 00 00 00 00 2F 00 70 00 34 00 2F 00 64
......./ .p.4./.d
1671104 [010] 00 34 00 58 00 58 00 58 00 58 00 58 00 58 00 58
.4.X.X.X .X.X.X.X
1671105 [020] 00 58 00 58 00 58 00 58 00 58 00 58 00 58 00 00
.X.X.X.X .X.X.X..
1671106 [030] 00 .
1671107 [2008/06/16 08:40:15, 3] smbd/process.c:switch_message(926)
1671108 switch message SMBtrans2 (pid 26808) conn 0x2aaaafd4a50
1671109 [2008/06/16 08:40:15, 3] smbd/sec_ctx.c:set_sec_ctx(241)
1671110 setting sec ctx (99, 99) - sec_ctx_stack_ndx = 0
1671154 size=160
1671155 smb_com=0x32
1671156 smb_rcls=0
1671157 smb_reh=0
1671158 smb_err=0
1671159 smb_flg=128
1671160 smb_flg2=49217
1671161 smb_tid=4
1671162 smb_pid=22232
1671163 smb_uid=0
1671164 smb_mid=46132
1671165 smt_wct=10
1671166 smb_vwv[ 0]= 2 (0x2)
1671167 smb_vwv[ 1]= 100 (0x64)
1671168 smb_vwv[ 2]= 0 (0x0)
1671169 smb_vwv[ 3]= 2 (0x2)
1671170 smb_vwv[ 4]= 56 (0x38)
1671171 smb_vwv[ 5]= 0 (0x0)
1671172 smb_vwv[ 6]= 100 (0x64)
1671173 smb_vwv[ 7]= 60 (0x3C)
1671174 smb_vwv[ 8]= 0 (0x0)
1671175 smb_vwv[ 9]= 0 (0x0)
1671176 smb_bcc=105
1671177 [2008/06/16 08:40:15, 10] lib/util.c:dump_data(2286)
1671178 [000] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
........ ........
1671179 [010] 00 00 00 00 00 00 0B 83 1F AE CF C8 01 80 A7 93
........ ........
1671180 [020] F7 AD CF C8 01 00 0B 83 1F AE CF C8 01 63 00 00
........ .....c..
1671181 [030] 00 00 00 00 00 63 00 00 00 00 00 00 00 01 00 00
.....c.. ........
1671182 [040] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
........ ........
1671183 [050] 00 F3 BD 03 00 00 00 00 00 ED 01 00 00 00 00 00
........ ........
1671184 [060] 00 03 00 00 00 00 00 00 00 ........ .
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send2 success mid: 13493,
pid: 22437,
cmd: 4,
1671192 [2008/06/16 08:40:15, 5] lib/util.c:show_msg(516)
1671193 size=41
1671194 smb_com=0x4
1671195 smb_rcls=0
1671196 smb_reh=0
1671197 smb_err=0
1671198 smb_flg=0
1671199 smb_flg2=49153
1671200 smb_tid=2
1671201 smb_pid=22437
1671202 smb_uid=0
1671203 smb_mid=46388
1671204 smt_wct=3
1671205 smb_vwv[ 0]= 5760 (0x1680)
1671206 smb_vwv[ 1]=65535 (0xFFFF)
1671207 smb_vwv[ 2]=65535 (0xFFFF)
1671208 smb_bcc=0
1671209 [2008/06/16 08:40:15, 3] smbd/process.c:switch_message(926)
1671210 switch message SMBclose (pid 26808) conn 0x2aaaafd1cd0
1671260 [2008/06/16 08:40:15, 2] smbd/close.c:close_normal_file(406)
1671261 nobody closed file
pe/d5XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/f8 (numopen=200)
NT_STATUS_OK
1671262 [2008/06/16 08:40:15, 5] smbd/files.c:file_free(454)
1671263 freed files structure 5760 (748 used)
1671264 [2008/06/16 08:40:15, 5] lib/util.c:show_msg(506)
1671265 [2008/06/16 08:40:15, 5] lib/util.c:show_msg(516)
1671266 size=35
1671267 smb_com=0x4
1671268 smb_rcls=0
1671269 smb_reh=0
1671270 smb_err=0
1671271 smb_flg=128
1671272 smb_flg2=49153
1671273 smb_tid=2
1671274 smb_pid=22437
1671275 smb_uid=0
1671276 smb_mid=46388
1671277 smt_wct=0
1671278 smb_bcc=0
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, c md: 47, error: -11
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: smb_send2 Error -11 sending data on
socket to server
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: SendReceive2 returns -11
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: Send error Write2 = -11
Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: Write2 ret -11, wrote 0
1671287 size=57408
1671288 smb_com=0x2f
1671289 smb_rcls=0
1671290 smb_reh=0
1671291 smb_err=0
1671292 smb_flg=0
1671293 smb_flg2=49153
1671294 smb_tid=4
1671295 smb_pid=22229
1671296 smb_uid=0
1671297 smb_mid=46644
1671298 smt_wct=14
1671299 smb_vwv[ 0]= 255 (0xFF)
1671300 smb_vwv[ 1]= 0 (0x0)
1671301 smb_vwv[ 2]= 5755 (0x167B)
1671302 smb_vwv[ 3]=49152 (0xC000)
1671303 smb_vwv[ 4]= 6 (0x6)
1671304 smb_vwv[ 5]=65535 (0xFFFF)
1671305 smb_vwv[ 6]=65535 (0xFFFF)
1671306 smb_vwv[ 7]= 0 (0x0)
1671307 smb_vwv[ 8]= 0 (0x0)
1671308 smb_vwv[ 9]= 0 (0x0)
1671309 smb_vwv[10]=57344 (0xE000)
1671310 smb_vwv[11]= 64 (0x40)
1671311 smb_vwv[12]= 0 (0x0)
1671312 smb_vwv[13]= 0 (0x0)
1671313 smb_bcc=57345
1671314 [2008/06/16 08:40:15, 10] lib/util.c:dump_data(2286)
1671315 [000] 00 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F
./////// ////////
1671316 [010] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F
//////// ////////
1671317 [020] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F
//////// ////////
1671318 [030] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F
//////// ////////
1671319 [040] 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F 2F //////// //
1671374 [2008/06/16 08:40:15, 3] smbd/reply.c:reply_write_and_X(3154)
1671375 writeX fnum=5755 num=57344 wrote=57344
1671376 [2008/06/16 08:40:15, 5] lib/util.c:show_msg(506)
1671377 [2008/06/16 08:40:15, 5] lib/util.c:show_msg(516)
1671378 size=47
1671379 smb_com=0x2f
1671380 smb_rcls=0
1671381 smb_reh=0
1671382 smb_err=0
1671383 smb_flg=128
1671384 smb_flg2=49153
1671385 smb_tid=4
1671386 smb_pid=22229
1671387 smb_uid=0
1671388 smb_mid=46644
1671389 smt_wct=6
1671390 smb_vwv[ 0]= 255 (0xFF)
1671391 smb_vwv[ 1]= 0 (0x0)
1671392 smb_vwv[ 2]=57344 (0xE000)
1671393 smb_vwv[ 3]= 0 (0x0)
1671394 smb_vwv[ 4]= 0 (0x0)
1671395 smb_vwv[ 5]= 0 (0x0)
1671396 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).
None of these requests are logged on the server
13574 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send2 success mid:
13519, pid: 22229, cmd: 47,
13575 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13495, pid: 22245, cmd: 50,
13576 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13496, pid: 22237, cmd: 50,
13577 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13497, pid: 22243, cmd: 50,
13578 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13498, pid: 22422, cmd: 50,
13579 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13499, pid: 22435, cmd: 50,
13580 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13500, pid: 22234, cmd: 50,
13581 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13501, pid: 22439, cmd: 50,
13582 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13502, pid: 22233, cmd: 50,
13583 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13503, pid: 22441, cmd: 50,
13584 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13504, pid: 22423, cmd: 50,
13585 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13505, pid: 22242, cmd: 50,
13586 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13506, pid: 22244, cmd: 50,
13587 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13507, pid: 22432, cmd: 50,
13588 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13508, pid: 22231, cmd: 50,
13589 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13509, pid: 22430, cmd: 50,
13590 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13510, pid: 22433, cmd: 50,
13591 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13511, pid: 22421, cmd: 50,
13592 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: No task to wake,
unknown frame received! NumMids 19, Mid 13494, Pid: 54614, cmd: 47
13593 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send2 success mid:
13512, pid: 22436, cmd: 47,
13594 Jun 16 08:40:15 LAC0039 kernel: CIFS VFS: send success mid:
13513, pid: 22427, cmd: 50,
More information about the samba-technical
mailing list