samba - Dec 2016 - System freeze if mount cifs share with option "hard", and samba server is not available

I know "hard" means command will hang if network is broken. But it
seems that's not actuate. It's CPU that will hang.


Affected scope:

I tested it against CentOS 5/6/7, it can be reproduced on all the systems. the
debug logs below are captured from CentOS 7 (cifs.ko v2.05)


How to reproduce this problem?


1. mount a cifs share with option "hard"

2. stop samba server

3. access the mount point (e.g. ls /mnt)


Actual result:

case #1: if system has only one CPU (one core):

(1) system will get freeze after about 20 seconds. No command can be run, but I
can ping the system from another machine;

(2) CPU goes to 100% (using VM, I can monitor CPU usage from hypervisor
management console. )

(3) System will not be back even after samba server is started again;


case #2: if system has more than one CPU:

(1) the command will hang, but system is still responsive (can run other
commands)

(2) CPU goes high, but not 100%

(3) the command can exit after samba server is started again

(4) observe the following log in "dmesg":

Dec 25 05:35:56 machine-hostname kernel: BUG: soft lockup - CPU#1 stuck for 22s!
[du:2602]

Dec 25 05:35:56 machine-hostname kernel: [<ffffffff810a6806>]
prepare_to_wait+0x56/0x90
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa04052cb>]
cifs_reconnect_tcon+0xbb/0x2f0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff810a6ae0>] ?
wake_up_atomic_t+0x30/0x30
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa04055ba>]
smb_init+0x2a/0x50 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa040bd8a>]
CIFSSMBUnixQPathInfo+0x7a/0x2e0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa042224b>]
cifs_get_inode_info_unix+0x8b/0x1e0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e8ba0>] ?
complete_walk+0x60/0xe0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811ed823>] ?
path_lookupat+0x83/0x7a0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff8116b8f5>] ?
filemap_fault+0x225/0x430
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa023ed4c>] ?
xfs_iunlock+0x11c/0x130 [xfs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811c1d95>] ?
__kmalloc+0x55/0x230
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa041723e>] ?
build_path_from_dentry+0xae/0x290 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa041723e>] ?
build_path_from_dentry+0xae/0x290 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa04247c0>]
cifs_revalidate_dentry_attr+0xd0/0x1e0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa0424987>]
cifs_getattr+0x57/0x130 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e34c6>]
vfs_getattr+0x46/0x80
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e35f5>]
vfs_fstatat+0x75/0xc0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e3c04>]
SYSC_newfstatat+0x24/0x60
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff816411b3>] ?
trace_do_page_fault+0x43/0x110
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff816408d9>] ?
do_async_page_fault+0x29/0xe0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff8163d438>] ?
async_page_fault+0x28/0x30
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e3e4e>]
SyS_newfstatat+0xe/0x10
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff81645909>]
system_call_fastpath+0x16/0x1b
(5) enable "cifsFYI", observed cifs.ko keeps printing the logs below:

[ 3058.820504] fs/cifs/file.c: 7: iov_base=ffff8800129e6000 iov_len=4096
[ 3058.820506] fs/cifs/file.c: 8: iov_base=ffff88003d4e3000 iov_len=4096
[ 3058.820508] fs/cifs/file.c: 9: iov_base=ffff8800109cb000 iov_len=4096
[ 3058.820510] fs/cifs/file.c: 10: iov_base=ffff88003b56b000 iov_len=4096
[ 3058.820512] fs/cifs/file.c: 11: iov_base=ffff880013bd6000 iov_len=4096
[ 3058.820515] fs/cifs/cifssmb.c: total_read=49216 buflen=49216 remaining=49152
[ 3058.820529] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61459 state=4
result=0 bytes=49152
[ 3058.820531] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.820546] fs/cifs/cifssmb.c: cifs_async_readv: offset=116178944 bytes=16384
[ 3058.820547] fs/cifs/transport.c: For smb_command 46
[ 3058.820548] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.820961] fs/cifs/connect.c: RFC1002 header 0x403c
[ 3058.820963] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61460 offset=116178944
bytes=16384
[ 3058.820964] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.820965] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.820966] fs/cifs/file.c: 0: iov_base=ffff880013bd6000 iov_len=4096
[ 3058.820968] fs/cifs/file.c: 1: iov_base=ffff88003b56b000 iov_len=4096
[ 3058.820970] fs/cifs/file.c: 2: iov_base=ffff8800109cb000 iov_len=4096
[ 3058.820972] fs/cifs/file.c: 3: iov_base=ffff88003d4e3000 iov_len=4096
[ 3058.820975] fs/cifs/cifssmb.c: total_read=16448 buflen=16448 remaining=16384
[ 3058.820976] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61460 state=4
result=0 bytes=16384
[ 3058.820978] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.821600] fs/cifs/cifssmb.c: cifs_async_readv: offset=116195328 bytes=49152
[ 3058.821602] fs/cifs/transport.c: For smb_command 46
[ 3058.821603] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.821982] fs/cifs/connect.c: RFC1002 header 0xc03c
[ 3058.821985] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61461 offset=116195328
bytes=49152
[ 3058.821986] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.821987] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.821988] fs/cifs/file.c: 0: iov_base=ffff880036797000 iov_len=4096
[ 3058.821990] fs/cifs/file.c: 1: iov_base=ffff8800367cc000 iov_len=4096
[ 3058.821992] fs/cifs/file.c: 2: iov_base=ffff88003d069000 iov_len=4096
[ 3058.821993] fs/cifs/file.c: 3: iov_base=ffff8800156b8000 iov_len=4096
[ 3058.821995] fs/cifs/file.c: 4: iov_base=ffff88003d07b000 iov_len=4096
[ 3058.821997] fs/cifs/file.c: 5: iov_base=ffff880014f7b000 iov_len=4096
[ 3058.821999] fs/cifs/file.c: 6: iov_base=ffff88003b44d000 iov_len=4096
[ 3058.822001] fs/cifs/file.c: 7: iov_base=ffff880013aba000 iov_len=4096
[ 3058.822015] fs/cifs/file.c: 8: iov_base=ffff880013abb000 iov_len=4096
[ 3058.822016] fs/cifs/file.c: 9: iov_base=ffff880036856000 iov_len=4096
[ 3058.822018] fs/cifs/file.c: 10: iov_base=ffff880036857000 iov_len=4096
[ 3058.822020] fs/cifs/file.c: 11: iov_base=ffff880010a8e000 iov_len=4096
[ 3058.822023] fs/cifs/cifssmb.c: total_read=49216 buflen=49216 remaining=49152
[ 3058.822024] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61461 state=4
result=0 bytes=49152
[ 3058.822026] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.822040] fs/cifs/cifssmb.c: cifs_async_readv: offset=116244480 bytes=16384
[ 3058.822041] fs/cifs/transport.c: For smb_command 46
[ 3058.822042] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.822418] fs/cifs/connect.c: RFC1002 header 0x403c
[ 3058.822420] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61462 offset=116244480
bytes=16384
[ 3058.822422] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.822423] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.822424] fs/cifs/file.c: 0: iov_base=ffff880010a8e000 iov_len=4096
[ 3058.822426] fs/cifs/file.c: 1: iov_base=ffff880036857000 iov_len=4096
[ 3058.822428] fs/cifs/file.c: 2: iov_base=ffff880036856000 iov_len=4096
[ 3058.822430] fs/cifs/file.c: 3: iov_base=ffff880013abb000 iov_len=4096
[ 3058.822434] fs/cifs/cifssmb.c: total_read=16448 buflen=16448 remaining=16384
[ 3058.822435] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61462 state=4
result=0 bytes=16384
[ 3058.822437] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.822967] fs/cifs/cifssmb.c: cifs_async_readv: offset=116260864 bytes=49152
[ 3058.822969] fs/cifs/transport.c: For smb_command 46
[ 3058.822970] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.833419] fs/cifs/connect.c: RFC1002 header 0xc03c
[ 3058.833423] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61463 offset=116260864
bytes=49152
[ 3058.833425] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.833438] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.833440] fs/cifs/file.c: 0: iov_base=ffff8800206d5000 iov_len=4096
[ 3058.833441] fs/cifs/file.c: 1: iov_base=ffff88003d1d6000 iov_len=4096
[ 3058.833444] fs/cifs/file.c: 2: iov_base=ffff8800367cd000 iov_len=4096
[ 3058.833445] fs/cifs/file.c: 3: iov_base=ffff88003acd2000 iov_len=4096
[ 3058.833447] fs/cifs/file.c: 4: iov_base=ffff88003acd3000 iov_len=4096
[ 3058.833449] fs/cifs/file.c: 5: iov_base=ffff88003d128000 iov_len=4096



Thanks

Mike

Sorry, please ignore this email. I just realized I post to wrong mail list.





发件人: samba <samba-bounces at lists.samba.org> 代表 Wang, Zhiye via samba
<samba at lists.samba.org>
发送时间: 2016年12月25日 19:37
收件人: samba at lists.samba.org
主题: [Samba] System freeze if mount cifs share with option "hard", and
samba server is not available
    
I know "hard" means command will hang if network is broken. But it
seems that's not actuate. It's CPU that will hang.


Affected scope:

I tested it against CentOS 5/6/7, it can be reproduced on all the systems. the
debug logs below are captured from CentOS 7 (cifs.ko v2.05)


How to reproduce this problem?


1. mount a cifs share with option "hard"

2. stop samba server

3. access the mount point (e.g. ls /mnt)


Actual result:

case #1: if system has only one CPU (one core):

(1) system will get freeze after about 20 seconds. No command can be run, but I
can ping the system from another machine;

(2) CPU goes to 100% (using VM, I can monitor CPU usage from hypervisor
management console. )

(3) System will not be back even after samba server is started again;


case #2: if system has more than one CPU:

(1) the command will hang, but system is still responsive (can run other
commands)

(2) CPU goes high, but not 100%

(3) the command can exit after samba server is started again

(4) observe the following log in "dmesg":

Dec 25 05:35:56 machine-hostname kernel: BUG: soft lockup - CPU#1 stuck for 22s!
[du:2602]

Dec 25 05:35:56 machine-hostname kernel: [<ffffffff810a6806>]
prepare_to_wait+0x56/0x90
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa04052cb>]
cifs_reconnect_tcon+0xbb/0x2f0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff810a6ae0>] ?
wake_up_atomic_t+0x30/0x30
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa04055ba>]
smb_init+0x2a/0x50 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa040bd8a>]
CIFSSMBUnixQPathInfo+0x7a/0x2e0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa042224b>]
cifs_get_inode_info_unix+0x8b/0x1e0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e8ba0>] ?
complete_walk+0x60/0xe0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811ed823>] ?
path_lookupat+0x83/0x7a0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff8116b8f5>] ?
filemap_fault+0x225/0x430
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa023ed4c>] ?
xfs_iunlock+0x11c/0x130 [xfs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811c1d95>] ?
__kmalloc+0x55/0x230
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa041723e>] ?
build_path_from_dentry+0xae/0x290 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa041723e>] ?
build_path_from_dentry+0xae/0x290 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa04247c0>]
cifs_revalidate_dentry_attr+0xd0/0x1e0 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffffa0424987>]
cifs_getattr+0x57/0x130 [cifs]
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e34c6>]
vfs_getattr+0x46/0x80
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e35f5>]
vfs_fstatat+0x75/0xc0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e3c04>]
SYSC_newfstatat+0x24/0x60
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff816411b3>] ?
trace_do_page_fault+0x43/0x110
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff816408d9>] ?
do_async_page_fault+0x29/0xe0
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff8163d438>] ?
async_page_fault+0x28/0x30
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff811e3e4e>]
SyS_newfstatat+0xe/0x10
Dec 25 05:35:56 machine-hostname kernel: [<ffffffff81645909>]
system_call_fastpath+0x16/0x1b
(5) enable "cifsFYI", observed cifs.ko keeps printing the logs below:

[ 3058.820504] fs/cifs/file.c: 7: iov_base=ffff8800129e6000 iov_len=4096
[ 3058.820506] fs/cifs/file.c: 8: iov_base=ffff88003d4e3000 iov_len=4096
[ 3058.820508] fs/cifs/file.c: 9: iov_base=ffff8800109cb000 iov_len=4096
[ 3058.820510] fs/cifs/file.c: 10: iov_base=ffff88003b56b000 iov_len=4096
[ 3058.820512] fs/cifs/file.c: 11: iov_base=ffff880013bd6000 iov_len=4096
[ 3058.820515] fs/cifs/cifssmb.c: total_read=49216 buflen=49216 remaining=49152
[ 3058.820529] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61459 state=4
result=0 bytes=49152
[ 3058.820531] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.820546] fs/cifs/cifssmb.c: cifs_async_readv: offset=116178944 bytes=16384
[ 3058.820547] fs/cifs/transport.c: For smb_command 46
[ 3058.820548] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.820961] fs/cifs/connect.c: RFC1002 header 0x403c
[ 3058.820963] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61460 offset=116178944
bytes=16384
[ 3058.820964] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.820965] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.820966] fs/cifs/file.c: 0: iov_base=ffff880013bd6000 iov_len=4096
[ 3058.820968] fs/cifs/file.c: 1: iov_base=ffff88003b56b000 iov_len=4096
[ 3058.820970] fs/cifs/file.c: 2: iov_base=ffff8800109cb000 iov_len=4096
[ 3058.820972] fs/cifs/file.c: 3: iov_base=ffff88003d4e3000 iov_len=4096
[ 3058.820975] fs/cifs/cifssmb.c: total_read=16448 buflen=16448 remaining=16384
[ 3058.820976] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61460 state=4
result=0 bytes=16384
[ 3058.820978] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.821600] fs/cifs/cifssmb.c: cifs_async_readv: offset=116195328 bytes=49152
[ 3058.821602] fs/cifs/transport.c: For smb_command 46
[ 3058.821603] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.821982] fs/cifs/connect.c: RFC1002 header 0xc03c
[ 3058.821985] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61461 offset=116195328
bytes=49152
[ 3058.821986] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.821987] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.821988] fs/cifs/file.c: 0: iov_base=ffff880036797000 iov_len=4096
[ 3058.821990] fs/cifs/file.c: 1: iov_base=ffff8800367cc000 iov_len=4096
[ 3058.821992] fs/cifs/file.c: 2: iov_base=ffff88003d069000 iov_len=4096
[ 3058.821993] fs/cifs/file.c: 3: iov_base=ffff8800156b8000 iov_len=4096
[ 3058.821995] fs/cifs/file.c: 4: iov_base=ffff88003d07b000 iov_len=4096
[ 3058.821997] fs/cifs/file.c: 5: iov_base=ffff880014f7b000 iov_len=4096
[ 3058.821999] fs/cifs/file.c: 6: iov_base=ffff88003b44d000 iov_len=4096
[ 3058.822001] fs/cifs/file.c: 7: iov_base=ffff880013aba000 iov_len=4096
[ 3058.822015] fs/cifs/file.c: 8: iov_base=ffff880013abb000 iov_len=4096
[ 3058.822016] fs/cifs/file.c: 9: iov_base=ffff880036856000 iov_len=4096
[ 3058.822018] fs/cifs/file.c: 10: iov_base=ffff880036857000 iov_len=4096
[ 3058.822020] fs/cifs/file.c: 11: iov_base=ffff880010a8e000 iov_len=4096
[ 3058.822023] fs/cifs/cifssmb.c: total_read=49216 buflen=49216 remaining=49152
[ 3058.822024] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61461 state=4
result=0 bytes=49152
[ 3058.822026] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.822040] fs/cifs/cifssmb.c: cifs_async_readv: offset=116244480 bytes=16384
[ 3058.822041] fs/cifs/transport.c: For smb_command 46
[ 3058.822042] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.822418] fs/cifs/connect.c: RFC1002 header 0x403c
[ 3058.822420] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61462 offset=116244480
bytes=16384
[ 3058.822422] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.822423] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.822424] fs/cifs/file.c: 0: iov_base=ffff880010a8e000 iov_len=4096
[ 3058.822426] fs/cifs/file.c: 1: iov_base=ffff880036857000 iov_len=4096
[ 3058.822428] fs/cifs/file.c: 2: iov_base=ffff880036856000 iov_len=4096
[ 3058.822430] fs/cifs/file.c: 3: iov_base=ffff880013abb000 iov_len=4096
[ 3058.822434] fs/cifs/cifssmb.c: total_read=16448 buflen=16448 remaining=16384
[ 3058.822435] fs/cifs/cifssmb.c: cifs_readv_callback: mid=61462 state=4
result=0 bytes=16384
[ 3058.822437] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[ 3058.822967] fs/cifs/cifssmb.c: cifs_async_readv: offset=116260864 bytes=49152
[ 3058.822969] fs/cifs/transport.c: For smb_command 46
[ 3058.822970] fs/cifs/transport.c: Sending smb: smb_len=59
[ 3058.833419] fs/cifs/connect.c: RFC1002 header 0xc03c
[ 3058.833423] fs/cifs/cifssmb.c: cifs_readv_receive: mid=61463 offset=116260864
bytes=49152
[ 3058.833425] fs/cifs/cifssmb.c: cifs_readv_receive: total_read=63
data_offset=64
[ 3058.833438] fs/cifs/cifssmb.c: 0: iov_base=ffff880036267d40 iov_len=64
[ 3058.833440] fs/cifs/file.c: 0: iov_base=ffff8800206d5000 iov_len=4096
[ 3058.833441] fs/cifs/file.c: 1: iov_base=ffff88003d1d6000 iov_len=4096
[ 3058.833444] fs/cifs/file.c: 2: iov_base=ffff8800367cd000 iov_len=4096
[ 3058.833445] fs/cifs/file.c: 3: iov_base=ffff88003acd2000 iov_len=4096
[ 3058.833447] fs/cifs/file.c: 4: iov_base=ffff88003acd3000 iov_len=4096
[ 3058.833449] fs/cifs/file.c: 5: iov_base=ffff88003d128000 iov_len=4096



Thanks

Mike




-- 
To unsubscribe from this list go to the following URL and read the
instructions:  https://lists.samba.org/mailman/options/samba


samba list: member options login page
lists.samba.org
Unsubscribe: By clicking on the Unsubscribe button, a confirmation message will
be emailed to you. This message will have a link that you should click on to ...