* re: backing up to a Drobo CIFS VFS: Error -11 sending data on socket to server, Bufferbloat?
[not found] <B0AAEC04-DBAE-49AB-A549-B772D5F1B7F6@fordham.edu>
@ 2017-05-11 20:42 ` Robert Kudyba
[not found] ` <D5627D5A-065B-4C28-B152-7B0A587A0CBF-tzaSEmCkE7qVc3sceRu5cw@public.gmane.org>
0 siblings, 1 reply; 5+ messages in thread
From: Robert Kudyba @ 2017-05-11 20:42 UTC (permalink / raw)
To: linux-cifs-u79uwXL29TY76Z2rM5mHXA
>> Could you provide a network trace of the isssue happening? You can add a
>> new bug report on bugzilla.samba.org in the cifsVFS/kernel fs section
>> and attach the trace there.
> I submitted a bug. Seems to happen every night. Cron starts at 11:30 PM. Error happens around 1:25 AM. Here are some logs in context as well as a tcpdump—drobo-ds is the NAS backup device. I created a large (3GB) tcpdump during the backup but it’s way too big to upload. Could this be bufferbloat?
>
> May 11 01:22:23 ourserver kernel: CIFS VFS: Server droboh has not responded in 120 seconds. Reconnecting...
> May 11 01:23:40 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
> May 11 01:23:40 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
> May 11 01:24:24 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
> May 11 01:24:24 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
> May 11 01:25:00 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
> May 11 01:25:00 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
> May 11 01:25:16 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
> May 11 01:25:16 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
> May 11 01:25:49 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
> May 11 01:25:49 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
>
> reading from file capture_eth1.pcap, link-type EN10MB (Ethernet)
> 01:29:10.445882 IP ourserver.uuidgen > fileserver.nfs: Flags [P.], seq 2359428476:2359428700, ack 4223248510, win 1444, options [nop,nop,TS val 1979978735 ecr 775533219], length 224: NFS request xid 2016398399 220 getattr fh 0,2/53
> 01:29:10.446331 IP fileserver.nfs > ourserver.uuidgen: Flags [P.], seq 1:173, ack 224, win 5204, options [nop,nop,TS val 775535659 ecr 1979978735], length 172: NFS reply xid 2016398399 reply ok 168 getattr NON 4 ids 0/1730480217 sz 1861894709
> 01:29:10.446378 IP ourserver.uuidgen > fileserver.nfs: Flags [.], ack 173, win 1444, options [nop,nop,TS val 1979978736 ecr 775535659], length 0
> 01:29:10.446466 IP ourserver.uuidgen > fileserver.nfs: Flags [P.], seq 224:568, ack 173, win 1444, options [nop,nop,TS val 1979978736 ecr 775535659], length 344: NFS request xid 2033175615 340 getattr fh 0,2/53
> 01:29:10.447034 IP fileserver.nfs > ourserver.uuidgen: Flags [P.], seq 173:537, ack 568, win 5204, options [nop,nop,TS val 775535660 ecr 1979978736], length 364: NFS reply xid 2033175615 reply ok 360 getattr NON 6 ids 0/1730480217 sz 1861894709
> 01:29:10.447346 IP ourserver.uuidgen > fileserver.nfs: Flags [P.], seq 568:836, ack 537, win 1444, options [nop,nop,TS val 1979978737 ecr 775535660], length 268: NFS request xid 2049952831 264 getattr fh 0,2/53
> 01:29:10.465786 IP fileserver.nfs > ourserver.uuidgen: Flags [P.], seq 537:805, ack 836, win 5204, options [nop,nop,TS val 775535679 ecr 1979978737], length 268: NFS reply xid 2049952831 reply ok 264 getattr NON 4 ids 0/1730480217 sz 1861894709
> 01:29:13.964676 IP drobo-ds > ourserver.42582: Flags [.], ack 3571070888, win 26508, options [nop,nop,TS val 616097295 ecr 1073740628], length 0
> 01:29:13.964780 IP drobo-ds > ourserver.42582: Flags [.], ack 2897, win 26508, options [nop,nop,TS val 616097295 ecr 1073740628], length 0
> 01:29:13.965029 IP drobo-ds > ourserver.42582: Flags [.], ack 5793, win 26508, options [nop,nop,TS val 616097295 ecr 1073740628], length 0
> 01:29:13.965155 IP drobo-ds > ourserver.42582: Flags [.], ack 8689, win 26508, options [nop,nop,TS val 616097295 ecr 1073740629], length 0
> 01:29:13.965176 IP ourserver.42582 > drobo-ds: Flags [.], seq 101361:115841, ack 0, win 321, options [nop,nop,TS val 1073740637 ecr 616097295], length 14480 SMB-over-TCP packet:(raw data or continuation?)
>
> 01:29:13.965397 IP drobo-ds > ourserver.42582: Flags [.], ack 11585, win 26421, options [nop,nop,TS val 616097295 ecr 1073740630], length 0
> 01:29:13.965418 IP ourserver.42582 > drobo-ds: Flags [.], seq 115841:118737, ack 0, win 321, options [nop,nop,TS val 1073740638 ecr 616097295], length 2896 SMB-over-TCP packet:(raw data or continuation?)
>
> 01:29:13.966364 IP drobo-ds > ourserver.42582: Flags [P.], seq 0:51, ack 18825, win 25986, options [nop,nop,TS val 616097295 ecr 1073740630], length 51 SMB PACKET: SMBwriteX (REPLY)
>
> 01:29:13.966386 IP drobo-ds > ourserver.42582: Flags [.], ack 21721, win 26508, options [nop,nop,TS val 616097295 ecr 1073740630], length 0
> 01:29:13.966416 IP ourserver.42582 > drobo-ds: Flags [.], seq 118737:125977, ack 51, win 321, options [nop,nop,TS val 1073740639 ecr 616097295], length 7240 SMB-over-TCP packet:(raw data or continuation?)
>
> 01:29:13.966658 IP drobo-ds > ourserver.42582: Flags [.], ack 24617, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
> 01:29:13.966783 IP drobo-ds > ourserver.42582: Flags [.], ack 27513, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
> 01:29:13.967054 IP drobo-ds > ourserver.42582: Flags [.], ack 30409, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
> 01:29:13.967072 IP ourserver.42582 > drobo-ds: Flags [P.], seq 125977:137561, ack 51, win 321, options [nop,nop,TS val 1073740639 ecr 616097295], length 11584 SMB-over-TCP packet:(raw data or continuation?)
>
> 01:29:13.967408 IP drobo-ds > ourserver.42582: Flags [.], ack 33305, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
> 01:29:13.968436 IP drobo-ds > ourserver.42582: Flags [.], ack 44889, win 26508, options [nop,nop,TS val 616097296 ecr 1073740632], length 0
> 01:29:13.968460 IP ourserver.42582 > drobo-ds: Flags [.], seq 140457:152041, ack 51, win 321, options [nop,nop,TS val 1073740641 ecr 616097296], length 11584 SMB-over-TCP packet:(raw data or continuation?)
>
> 01:29:13.968515 IP drobo-ds > ourserver.42582: Flags [.], ack 47785, win 26508, options [nop,nop,TS val 616097296 ecr 1073740634], length 0
> 01:29:13.968782 IP drobo-ds > ourserver.42582: Flags [.], ack 50681, win 26508, options [nop,nop,TS val 616097296 ecr 1073740634], length 0
> 01:29:13.969224 IP drobo-ds > ourserver.42582: Flags [.], ack 53577, win 26508, options [nop,nop,TS val 616097296 ecr 1073740634], length 0
> 01:29:13.969242 IP ourserver.42582 > drobo-ds: Flags [.], seq 152041:160729, ack 51, win 321, options [nop,nop,TS val 1073740642 ecr 616097296], length 8688 SMB-over-TCP packet:(raw data or continuation?)
>
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: backing up to a Drobo CIFS VFS: Error -11 sending data on socket to server, Bufferbloat?
[not found] ` <D5627D5A-065B-4C28-B152-7B0A587A0CBF-tzaSEmCkE7qVc3sceRu5cw@public.gmane.org>
@ 2017-05-11 22:56 ` Richard Sharpe
[not found] ` <CAFHi+KS6HtBGvqTJxNgMYvBaYnibryf==5x8FTJfGtjMJOSkBA@mail.gmail.com>
0 siblings, 1 reply; 5+ messages in thread
From: Richard Sharpe @ 2017-05-11 22:56 UTC (permalink / raw)
To: Robert Kudyba; +Cc: linux-cifs
On Thu, May 11, 2017 at 1:42 PM, Robert Kudyba <rkudyba-tzaSEmCkE7qVc3sceRu5cw@public.gmane.org> wrote:
>>> Could you provide a network trace of the isssue happening? You can add a
>>> new bug report on bugzilla.samba.org in the cifsVFS/kernel fs section
>>> and attach the trace there.
>
>> I submitted a bug. Seems to happen every night. Cron starts at 11:30 PM. Error happens around 1:25 AM. Here are some logs in context as well as a tcpdump—drobo-ds is the NAS backup device. I created a large (3GB) tcpdump during the backup but it’s way too big to upload. Could this be bufferbloat?
This suggests that the Drobo is simply going off into the weeds
somewhere. Do you have enough storage on it. They will insert write
delays when storage is low, but I didn't think they would insert 120
seconds.
Also, if you run the capture through tshark you can get a text listing
of the requests that might allow you to find the location where the
Drobo stops responding and then you can extract the 100-1000 packets
around that point.
tshark -r whatever-your-capture-is.pcap.
>> May 11 01:22:23 ourserver kernel: CIFS VFS: Server droboh has not responded in 120 seconds. Reconnecting...
>> May 11 01:23:40 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
>> May 11 01:23:40 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
>> May 11 01:24:24 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
>> May 11 01:24:24 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
>> May 11 01:25:00 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
>> May 11 01:25:00 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
>> May 11 01:25:16 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
>> May 11 01:25:16 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
>> May 11 01:25:49 ourserver kernel: CIFS VFS: sends on sock ffff9f2881408c80 stuck for 15 seconds
>> May 11 01:25:49 ourserver kernel: CIFS VFS: Error -11 sending data on socket to server
>>
>> reading from file capture_eth1.pcap, link-type EN10MB (Ethernet)
>> 01:29:10.445882 IP ourserver.uuidgen > fileserver.nfs: Flags [P.], seq 2359428476:2359428700, ack 4223248510, win 1444, options [nop,nop,TS val 1979978735 ecr 775533219], length 224: NFS request xid 2016398399 220 getattr fh 0,2/53
>> 01:29:10.446331 IP fileserver.nfs > ourserver.uuidgen: Flags [P.], seq 1:173, ack 224, win 5204, options [nop,nop,TS val 775535659 ecr 1979978735], length 172: NFS reply xid 2016398399 reply ok 168 getattr NON 4 ids 0/1730480217 sz 1861894709
>> 01:29:10.446378 IP ourserver.uuidgen > fileserver.nfs: Flags [.], ack 173, win 1444, options [nop,nop,TS val 1979978736 ecr 775535659], length 0
>> 01:29:10.446466 IP ourserver.uuidgen > fileserver.nfs: Flags [P.], seq 224:568, ack 173, win 1444, options [nop,nop,TS val 1979978736 ecr 775535659], length 344: NFS request xid 2033175615 340 getattr fh 0,2/53
>> 01:29:10.447034 IP fileserver.nfs > ourserver.uuidgen: Flags [P.], seq 173:537, ack 568, win 5204, options [nop,nop,TS val 775535660 ecr 1979978736], length 364: NFS reply xid 2033175615 reply ok 360 getattr NON 6 ids 0/1730480217 sz 1861894709
>> 01:29:10.447346 IP ourserver.uuidgen > fileserver.nfs: Flags [P.], seq 568:836, ack 537, win 1444, options [nop,nop,TS val 1979978737 ecr 775535660], length 268: NFS request xid 2049952831 264 getattr fh 0,2/53
>> 01:29:10.465786 IP fileserver.nfs > ourserver.uuidgen: Flags [P.], seq 537:805, ack 836, win 5204, options [nop,nop,TS val 775535679 ecr 1979978737], length 268: NFS reply xid 2049952831 reply ok 264 getattr NON 4 ids 0/1730480217 sz 1861894709
>> 01:29:13.964676 IP drobo-ds > ourserver.42582: Flags [.], ack 3571070888, win 26508, options [nop,nop,TS val 616097295 ecr 1073740628], length 0
>> 01:29:13.964780 IP drobo-ds > ourserver.42582: Flags [.], ack 2897, win 26508, options [nop,nop,TS val 616097295 ecr 1073740628], length 0
>> 01:29:13.965029 IP drobo-ds > ourserver.42582: Flags [.], ack 5793, win 26508, options [nop,nop,TS val 616097295 ecr 1073740628], length 0
>> 01:29:13.965155 IP drobo-ds > ourserver.42582: Flags [.], ack 8689, win 26508, options [nop,nop,TS val 616097295 ecr 1073740629], length 0
>> 01:29:13.965176 IP ourserver.42582 > drobo-ds: Flags [.], seq 101361:115841, ack 0, win 321, options [nop,nop,TS val 1073740637 ecr 616097295], length 14480 SMB-over-TCP packet:(raw data or continuation?)
>>
>> 01:29:13.965397 IP drobo-ds > ourserver.42582: Flags [.], ack 11585, win 26421, options [nop,nop,TS val 616097295 ecr 1073740630], length 0
>> 01:29:13.965418 IP ourserver.42582 > drobo-ds: Flags [.], seq 115841:118737, ack 0, win 321, options [nop,nop,TS val 1073740638 ecr 616097295], length 2896 SMB-over-TCP packet:(raw data or continuation?)
>>
>> 01:29:13.966364 IP drobo-ds > ourserver.42582: Flags [P.], seq 0:51, ack 18825, win 25986, options [nop,nop,TS val 616097295 ecr 1073740630], length 51 SMB PACKET: SMBwriteX (REPLY)
>>
>> 01:29:13.966386 IP drobo-ds > ourserver.42582: Flags [.], ack 21721, win 26508, options [nop,nop,TS val 616097295 ecr 1073740630], length 0
>> 01:29:13.966416 IP ourserver.42582 > drobo-ds: Flags [.], seq 118737:125977, ack 51, win 321, options [nop,nop,TS val 1073740639 ecr 616097295], length 7240 SMB-over-TCP packet:(raw data or continuation?)
>>
>> 01:29:13.966658 IP drobo-ds > ourserver.42582: Flags [.], ack 24617, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
>> 01:29:13.966783 IP drobo-ds > ourserver.42582: Flags [.], ack 27513, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
>> 01:29:13.967054 IP drobo-ds > ourserver.42582: Flags [.], ack 30409, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
>> 01:29:13.967072 IP ourserver.42582 > drobo-ds: Flags [P.], seq 125977:137561, ack 51, win 321, options [nop,nop,TS val 1073740639 ecr 616097295], length 11584 SMB-over-TCP packet:(raw data or continuation?)
>>
>> 01:29:13.967408 IP drobo-ds > ourserver.42582: Flags [.], ack 33305, win 26508, options [nop,nop,TS val 616097295 ecr 1073740631], length 0
>> 01:29:13.968436 IP drobo-ds > ourserver.42582: Flags [.], ack 44889, win 26508, options [nop,nop,TS val 616097296 ecr 1073740632], length 0
>> 01:29:13.968460 IP ourserver.42582 > drobo-ds: Flags [.], seq 140457:152041, ack 51, win 321, options [nop,nop,TS val 1073740641 ecr 616097296], length 11584 SMB-over-TCP packet:(raw data or continuation?)
>>
>> 01:29:13.968515 IP drobo-ds > ourserver.42582: Flags [.], ack 47785, win 26508, options [nop,nop,TS val 616097296 ecr 1073740634], length 0
>> 01:29:13.968782 IP drobo-ds > ourserver.42582: Flags [.], ack 50681, win 26508, options [nop,nop,TS val 616097296 ecr 1073740634], length 0
>> 01:29:13.969224 IP drobo-ds > ourserver.42582: Flags [.], ack 53577, win 26508, options [nop,nop,TS val 616097296 ecr 1073740634], length 0
>> 01:29:13.969242 IP ourserver.42582 > drobo-ds: Flags [.], seq 152041:160729, ack 51, win 321, options [nop,nop,TS val 1073740642 ecr 616097296], length 8688 SMB-over-TCP packet:(raw data or continuation?)
>>
>>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-cifs" in
> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
Regards,
Richard Sharpe
(何以解憂？唯有杜康。--曹操)
^ permalink raw reply [flat|nested] 5+ messages in thread
* Fwd: backing up to a Drobo CIFS VFS: Error -11 sending data on socket to server, Bufferbloat?
[not found] ` <CAFHi+KRjK-pLxr+gNkE0jpsM1YfgE4s2Lw8Q4XTSTP-V0_Ds8A-JsoAwUIsXosN+BqQ9rBEUg@public.gmane.org>
@ 2017-05-12 2:37 ` Robert Kudyba
[not found] ` <CAFHi+KQhXFrOVDb51fZCs1e5ik3RY+v91H5Sz1Z3YkgUpMPURw-JsoAwUIsXosN+BqQ9rBEUg@public.gmane.org>
0 siblings, 1 reply; 5+ messages in thread
From: Robert Kudyba @ 2017-05-12 2:37 UTC (permalink / raw)
To: linux-cifs
Does this help? Here's the last few lines. Seems to be increasing in time?
424 0.101504413 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=817
Ack=1072969 Win=26508 Len=0 TSval=623636942 TSecr=2708013080
427 0.101741409 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=817
Ack=1075865 Win=26508 Len=0 TSval=623636942 TSecr=2708013081
432 0.102065108 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=817
Ack=1080209 Win=26334 Len=0 TSval=623636942 TSecr=2708013081
433 0.102072906 ourserver → drobo TCP 13098 [TCP segment of a reassembled PDU]
438 0.102829996 drobo → ourserver SMB 117 Write AndX Response, 65536 bytes
439 0.103240767 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1090345 Win=26508 Len=0 TSval=623636943 TSecr=2708013082
440 0.103251494 ourserver → drobo TCP 10202 [TCP segment of a reassembled PDU]
441 0.103259721 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1093241 Win=26508 Len=0 TSval=623636943 TSecr=2708013082
442 0.103475120 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1096137 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
443 0.103794874 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1099033 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
444 0.104305892 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1101929 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
445 0.104312236 ourserver → drobo TCP 11650 [TCP segment of a reassembled PDU]
446 0.104320705 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1104825 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
447 0.104568606 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1107721 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
448 0.104935339 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1110617 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
449 0.104945095 ourserver → drobo TCP 8754 [TCP segment of a reassembled PDU]
450 0.104953663 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1113513 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
451 0.105193542 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1116409 Win=26508 Len=0 TSval=623636943 TSecr=2708013083
452 0.105666892 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1119305 Win=26508 Len=0 TSval=623636943 TSecr=2708013084
453 0.105922535 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1122201 Win=26508 Len=0 TSval=623636943 TSecr=2708013084
454 0.105935375 ourserver → drobo TCP 11650 [TCP segment of a reassembled PDU]
455 0.105944869 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1125097 Win=26508 Len=0 TSval=623636943 TSecr=2708013085
456 0.106190594 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1127993 Win=26508 Len=0 TSval=623636943 TSecr=2708013085
458 0.106504814 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1130889 Win=26508 Len=0 TSval=623636943 TSecr=2708013085
459 0.106510176 ourserver → drobo TCP 7306 [TCP segment of a reassembled PDU]
460 0.106763808 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1133785 Win=26508 Len=0 TSval=623636943 TSecr=2708013085
461 0.107075671 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1136681 Win=26508 Len=0 TSval=623636943 TSecr=2708013086
462 0.107081982 ourserver → drobo TCP 7306 [TCP segment of a reassembled PDU]
463 0.107332634 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1139577 Win=26508 Len=0 TSval=623636943 TSecr=2708013086
464 0.107668225 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1142473 Win=26508 Len=0 TSval=623636943 TSecr=2708013086
465 0.107676435 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=868
Ack=1145369 Win=26421 Len=0 TSval=623636943 TSecr=2708013086
466 0.108678068 drobo → ourserver SMB 117 Write AndX Response, 65536 bytes
467 0.108694727 ourserver → drobo TCP 13098 [TCP segment of a reassembled PDU]
468 0.108703948 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1155505 Win=25812 Len=0 TSval=623636943 TSecr=2708013087
469 0.108951009 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1158401 Win=26508 Len=0 TSval=623636943 TSecr=2708013088
470 0.108961831 ourserver → drobo TCP 8754 [TCP segment of a reassembled PDU]
471 0.109218407 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1161297 Win=26508 Len=0 TSval=623636943 TSecr=2708013088
472 0.109231036 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1164193 Win=26508 Len=0 TSval=623636943 TSecr=2708013088
473 0.109662758 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1167089 Win=26508 Len=0 TSval=623636943 TSecr=2708013088
474 0.109918958 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1169985 Win=26508 Len=0 TSval=623636943 TSecr=2708013088
475 0.109932278 ourserver → drobo TCP 11650 [TCP segment of a reassembled PDU]
476 0.110190734 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1172881 Win=26508 Len=0 TSval=623636943 TSecr=2708013089
477 0.110200652 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1175777 Win=26508 Len=0 TSval=623636943 TSecr=2708013089
478 0.110661525 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1178673 Win=26508 Len=0 TSval=623636943 TSecr=2708013089
479 0.110670551 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1181569 Win=26508 Len=0 TSval=623636943 TSecr=2708013090
480 0.111313324 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1184465 Win=26508 Len=0 TSval=623636943 TSecr=2708013090
481 0.111325306 ourserver → drobo TCP 13098 [TCP segment of a reassembled PDU]
482 0.111336728 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1187361 Win=26508 Len=0 TSval=623636943 TSecr=2708013090
483 0.111579771 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1190257 Win=26508 Len=0 TSval=623636943 TSecr=2708013090
484 0.111918239 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1193153 Win=26508 Len=0 TSval=623636943 TSecr=2708013091
485 0.111924773 ourserver → drobo TCP 10202 [TCP segment of a reassembled PDU]
486 0.112172538 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1196049 Win=26508 Len=0 TSval=623636943 TSecr=2708013091
487 0.112178669 ourserver → drobo TCP 1514 [TCP segment of a reassembled PDU]
488 0.112186029 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1198945 Win=26508 Len=0 TSval=623636943 TSecr=2708013091
489 0.112430393 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1201841 Win=26508 Len=0 TSval=623636943 TSecr=2708013092
490 0.112934871 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1204737 Win=26508 Len=0 TSval=623636943 TSecr=2708013092
491 0.112946063 ourserver → drobo TCP 10202 [TCP segment of a reassembled PDU]
492 0.113132494 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1207633 Win=26508 Len=0 TSval=623636944 TSecr=2708013092
493 0.113256633 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=919
Ack=1211977 Win=26334 Len=0 TSval=623636944 TSecr=2708013092
494 0.114291076 drobo → ourserver SMB 117 Write AndX Response, 65536 bytes
495 0.114305898 ourserver → drobo TCP 13098 [TCP segment of a reassembled PDU]
496 0.114548027 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=970
Ack=1222113 Win=26508 Len=0 TSval=623636944 TSecr=2708013093
497 0.114554350 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=970
Ack=1225009 Win=26508 Len=0 TSval=623636944 TSecr=2708013093
498 0.114559411 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=970
Ack=1227905 Win=26508 Len=0 TSval=623636944 TSecr=2708013094
499 0.115071785 drobo → ourserver TCP 66 445 → 58706 [ACK] Seq=970
Ack=1230801 Win=26508 Len=0 TSval=623636944 TSecr=2708013094
500 0.115078479 ourserver → drobo TCP 13098 [TCP segment of a reassembled PDU]
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Fwd: backing up to a Drobo CIFS VFS: Error -11 sending data on socket to server, Bufferbloat?
[not found] ` <CAFHi+KQhXFrOVDb51fZCs1e5ik3RY+v91H5Sz1Z3YkgUpMPURw-JsoAwUIsXosN+BqQ9rBEUg@public.gmane.org>
@ 2017-05-12 11:49 ` Aurélien Aptel
[not found] ` <mpsinl6cn2g.fsf-zpEvHKhluMwYitT5tn2FcQ@public.gmane.org>
0 siblings, 1 reply; 5+ messages in thread
From: Aurélien Aptel @ 2017-05-12 11:49 UTC (permalink / raw)
To: Robert Kudyba, linux-cifs
Hi Robert,
The capture you posted unfortunately does not contain anything of worth
looking at I think. Only 2 SMB packets.
% tshark -r capture.pcap -Y 'smb||smb2'
1130 15.032933 150.108.64.56 → 150.108.68.23 SMB 144 Trans2 Request, QUERY_PATH_INFO, Query File All Info, Path:
1131 15.034786 150.108.68.23 → 150.108.64.56 SMB 204 Trans2 Response, QUERY_PATH_INFO
Given your kernel log message I would expect seeing the reconnecting happen.
I would wrap your backup script like so to get the right capture:
capfile="$(date -Ihours)"
tcpdump -w "$capfile" port 445 &
cappid=$!
sleep 2
.....<your script>....
sleep 2
kill -6 $cappid
--
Aurélien Aptel / SUSE Labs Samba Team
GPG: 1839 CB5F 9F5B FB9B AA97 8C99 03C8 A49B 521B D5D3
SUSE Linux GmbH, Maxfeldstraße 5, 90409 Nürnberg, Germany
GF: Felix Imendörffer, Jane Smithard, Graham Norton, HRB 21284 (AG Nürnberg)
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Fwd: backing up to a Drobo CIFS VFS: Error -11 sending data on socket to server, Bufferbloat?
[not found] ` <mpsinl6cn2g.fsf-zpEvHKhluMwYitT5tn2FcQ@public.gmane.org>
@ 2017-05-12 13:45 ` Robert Kudyba
0 siblings, 0 replies; 5+ messages in thread
From: Robert Kudyba @ 2017-05-12 13:45 UTC (permalink / raw)
To: Aurélien Aptel; +Cc: linux-cifs
> Given your kernel log message I would expect seeing the reconnecting happen.
I scheduled a tshark -c over night and was able to get it to run
within minutes of the reconnect attempts.It seems pretty consistent,
about 2 hours after the start of the cron the Error -11's start to
happen. Last night it also happened about 30 minutes into the job:
May 11 23:47:51 localworkstation kernel: CIFS VFS: Server drobo-rh has
not responded in 120 seconds. Reconnecting...
May 11 23:49:59 localworkstation kernel: CIFS VFS: Server drobo-rh has
not responded in 120 seconds. Reconnecting...
May 11 23:52:57 localworkstation kernel: CIFS VFS: Server drobo-rh has
not responded in 120 seconds. Reconnecting...
May 12 01:19:44 localworkstation cupsd: REQUEST localhost - - "POST /
HTTP/1.1" 200 181 Renew-Subscription successful-ok
May 12 01:21:20 localworkstation kernel: CIFS VFS: sends on sock
ffff9f2817bede00 stuck for 15 seconds
May 12 01:21:20 localworkstation kernel: CIFS VFS: Error -11 sending
data on socket to server
Here's the tshark -r tshark.pcap -Y 'smb||smb2' results from 2 files:
593 0.273687063 drobo → localserver SMB 117 [TCP ACKed unseen
segment] Write AndX Response, 65536 bytes
666 0.282264835 drobo → localserver SMB 117 Write AndX Response, 65536 bytes
8 0.136979937 drobo → localserver SMB 117 [TCP ACKed unseen
segment] [TCP Previous segment not captured] Write AndX Response,
65536 bytes
36 0.142752037 drobo → localserver SMB 117 Write AndX Response, 65536 bytes
63 0.149017707 drobo → localserver SMB 117 Write AndX Response, 65536 bytes
> I would wrap your backup script like so to get the right capture:
>
> capfile="$(date -Ihours)"
> tcpdump -w "$capfile" port 445 &
> cappid=$!
> sleep 2
> .....<your script>....
> sleep 2
> kill -6 $cappid
OK just did that and started running the backup manually so far I've
seen variations/multiples of these (cut for easier reading):
38735 18.521926 localserver → drobo SMB 10202 Write AndX Request,
FID: 0x1fca, 65536 bytes at offset 87949312[TCP segment of a
reassembled PDU]
38760 18.527189 localserver → drobo SMB 7306 Write AndX Request, FID:
0x1fca, 65536 bytes at offset 88014848[TCP segment of a reassembled
PDU]
38771 18.529817 drobo → localserver SMB 117 Write AndX Response, FID:
0x1fca, 65536 bytes
44079 19.615349 drobo → localserver SMB 117 [TCP ACKed unseen
segment] Write AndX Response, 65536 bytes
44102 19.626642 drobo → localserver SMB 117 [TCP ACKed unseen
segment] Write AndX Response, 65536 bytes
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2017-05-12 13:45 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <B0AAEC04-DBAE-49AB-A549-B772D5F1B7F6@fordham.edu>
2017-05-11 20:42 ` backing up to a Drobo CIFS VFS: Error -11 sending data on socket to server, Bufferbloat? Robert Kudyba
[not found] ` <D5627D5A-065B-4C28-B152-7B0A587A0CBF-tzaSEmCkE7qVc3sceRu5cw@public.gmane.org>
2017-05-11 22:56 ` Richard Sharpe
[not found] ` <CAFHi+KS6HtBGvqTJxNgMYvBaYnibryf==5x8FTJfGtjMJOSkBA@mail.gmail.com>
[not found] ` <CAFHi+KRGNSvfgj7o+tK0RZZa9Nf2NQANUiygsUR5aokJH5NP7w@mail.gmail.com>
[not found] ` <CAFHi+KSB348xPhYSf=x7FW9kmgU5iN-mDGvs2Fhyv=UYCMQckw@mail.gmail.com>
[not found] ` <CAFHi+KRjK-pLxr+gNkE0jpsM1YfgE4s2Lw8Q4XTSTP-V0_Ds8A@mail.gmail.com>
[not found] ` <CAFHi+KRjK-pLxr+gNkE0jpsM1YfgE4s2Lw8Q4XTSTP-V0_Ds8A-JsoAwUIsXosN+BqQ9rBEUg@public.gmane.org>
2017-05-12 2:37 ` Fwd: " Robert Kudyba
[not found] ` <CAFHi+KQhXFrOVDb51fZCs1e5ik3RY+v91H5Sz1Z3YkgUpMPURw-JsoAwUIsXosN+BqQ9rBEUg@public.gmane.org>
2017-05-12 11:49 ` Aurélien Aptel
[not found] ` <mpsinl6cn2g.fsf-zpEvHKhluMwYitT5tn2FcQ@public.gmane.org>
2017-05-12 13:45 ` Robert Kudyba
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.