CIFS VFS: Send error in SessSetup = -126

[Martijn van Brummelen]

Binary package hint: cifs-utils

Im mounting a samba file server with a kerberos ticket, this works fine until a network failure.
I am able to reproduce this error by pulling the network cable while the samba share is mounted, and putting it back in. It seems like it not able to find/renew the ticket. The ticket seems fine since I am able to use the internet which requires kerberos as well.
After the failure syslog get flooded(several logging rules per second) sometimes it eats all my diskspace in /var/log and results in a non use able system.
zcat syslog.2.gz|grep "CIFS VFS: Send error in SessSetup" |wc -l
22449972

If more information is needed let me know.

Technical stuff :
Mount command : mount.cifs //foobar.local/san/$PAM_USER $HOME_mount -o sec=krb5
Ubuntu Lucid LTS 32Bit
Kernel : uname -a
Linux ubuntu-lucid 2.6.32-30-generic #59-Ubuntu SMP Tue Mar 1 21:30:21 UTC 2011 i686 GNU/Linux
Samba-common : 2:3.4.7~dfsg-1ubuntu3.5

Apr 14 12:20:37 ubuntu-lucid kernel: [ 169.308684] e1000e: eth0 NIC Link is Down
Apr 14 12:20:37 ubuntu-lucid NetworkManager: <info> (eth0): carrier now OFF (device state 1)
Apr 14 12:20:54 ubuntu-lucid kernel: [ 186.924066] CIFS VFS: No response for cmd 50 mid 2759
Apr 14 12:20:55 ubuntu-lucid kernel: [ 187.924030] CIFS VFS: No response for cmd 50 mid 2763
Apr 14 12:20:55 ubuntu-lucid kernel: [ 187.925008] CIFS VFS: No response for cmd 50 mid 2760
Apr 14 12:20:55 ubuntu-lucid kernel: [ 187.925516] CIFS VFS: No response for cmd 50 mid 2761
Apr 14 12:20:55 ubuntu-lucid kernel: [ 187.926014] CIFS VFS: No response for cmd 50 mid 2762
Apr 14 12:20:58 ubuntu-lucid kernel: [ 190.564831] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: None
Apr 14 12:20:58 ubuntu-lucid kernel: [ 190.564835] 0000:00:19.0: eth0: 10/100 speed: disabling TSO
Apr 14 12:20:58 ubuntu-lucid NetworkManager: <info> (eth0): carrier now ON (device state 1)
Apr 14 12:21:06 ubuntu-lucid cifs.upcall: key description: cifs.spnego;45939;21920;3f000000;ver=0x2;host=foobar.local;ip4=x.x.x.x;sec=krb5;uid=0x0;user=root;pid=0x887
Apr 14 12:21:06 ubuntu-lucid cifs.upcall: find_krb5_cc: considering /tmp/krb5cc_45939_ui4AgC
Apr 14 12:21:06 ubuntu-lucid cifs.upcall: find_krb5_cc: /tmp/krb5cc_45939_ui4AgC is owned by 45939, not 0
Apr 14 12:21:06 ubuntu-lucid cifs.upcall: handle_krb5_mech: getting service ticket for cifs/foobar.local
Apr 14 12:21:06 ubuntu-lucid cifs.upcall: handle_krb5_mech: failed to obtain service ticket (-1765328189)
Apr 14 12:21:06 ubuntu-lucid cifs.upcall: handle_krb5_mech: getting service ticket for host/foobar.local
Apr 14 12:21:06 ubuntu-lucid cifs.upcall: handle_krb5_mech: failed to obtain service ticket (-1765328189)
Apr 14 12:21:06 ubuntu-lucid kernel: [ 198.955402] CIFS VFS: Send error in SessSetup = -126
Apr 14 12:21:06 ubuntu-lucid kernel: [ 198.956295] CIFS VFS: Unexpected lookup error -126

klist show a valid ticket for foorbar.local

ls -l /tmp/krb
-rw------- 1 l.user somegroup 938 2011-04-14 13:40 krb5cc_45939_iVfJt6

[Martijn van Brummelen (martijn-brumit)]

If I install a maverick 2.6.38 kernel the problem is "solved" system is still use able and no more massive cifs errors, but when I use a 2.6.35 kernel from lucid the problem still exists.

[Martijn van Brummelen (martijn-brumit)]

After some more testing 2.6.38 doesn't fix the problem, it delays the problem. If a short network outage occurs everything goes well, if the network outage takes longer then 5min it still fails with the same cifs 126 error.

[Martijn van Brummelen (martijn-brumit)]

Found a stack trace in /var/log/messages/

May 12 04:46:22 ubuntu kernel: [43380.856587] Pid: 19245, comm: chmod Tainted: P (2.6.32-31-generic #61-Ubuntu) HP Compaq 8000 Elite SFF PC
May 12 04:46:22 ubuntu kernel: [43380.856591] EIP: 0060:[<c02f4a2a>] EFLAGS: 00210246 CPU: 3
May 12 04:46:22 ubuntu kernel: [43380.856594] EIP is at wait_for_key_construction+0x2a/0x70
May 12 04:46:22 ubuntu kernel: [43380.856596] EAX: 00000000 EBX: 00000000 ECX: c02f4a70 EDX: 00000000
May 12 04:46:22 ubuntu kernel: [43380.856599] ESI: 00000002 EDI: f28b4300 EBP: f0e3bb18 ESP: f0e3bb0c
May 12 04:46:22 ubuntu kernel: [43380.856601] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
May 12 04:46:22 ubuntu kernel: [43380.856607] f8b168c0 00000000 f13d9e00 f0e3bb40 c02f53ba 00000000 00000000 00000000
May 12 04:46:22 ubuntu kernel: [43380.856614] <0> 00000000 f8b0900c f2905480 f2905480 f13d9e00 f0e3bb6c f8b023fc f29054cf
May 12 04:46:22 ubuntu kernel: [43380.856621] <0> f8b09002 00004b2d f6bf2320 f6bf2320 f28b43a2 f28b4300 00000800 00004058
May 12 04:46:22 ubuntu kernel: [43380.856633] [<c02f53ba>] ? request_key+0x5a/0x90
May 12 04:46:22 ubuntu kernel: [43380.856642] [<f8b023fc>] ? cifs_get_spnego_key+0x17c/0x1d0 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856649] [<f8b00e1d>] ? CIFS_SessSetup+0x66d/0xc10 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856654] [<c012a768>] ? default_spin_lock_flags+0x8/0x10
May 12 04:46:22 ubuntu kernel: [43380.856659] [<c03b3bee>] ? extract_buf+0x7e/0xe0
May 12 04:46:22 ubuntu kernel: [43380.856665] [<f8ae8a79>] ? cifs_setup_session+0x69/0x1a0 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856670] [<c058f74f>] ? _spin_lock_irqsave+0x2f/0x50
May 12 04:46:22 ubuntu kernel: [43380.856676] [<f8adf5eb>] ? cifs_reconnect_tcon+0x1ab/0x280 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856682] [<f8adf6e4>] ? smb_init+0x24/0x80 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856688] [<f8ae3375>] ? CIFSSMBUnixQPathInfo+0x55/0x250 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856696] [<f8af4a5e>] ? cifs_get_inode_info_unix+0x5e/0x100 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856703] [<f8aed8c5>] ? build_path_from_dentry+0xa5/0x1e0 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856710] [<f8aed99c>] ? build_path_from_dentry+0x17c/0x1e0 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856714] [<c058f84d>] ? _spin_lock+0xd/0x10
May 12 04:46:22 ubuntu kernel: [43380.856721] [<f8af4cf4>] ? cifs_revalidate+0x1f4/0x3e0 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856725] [<c021c811>] ? dput+0x91/0x130
May 12 04:46:22 ubuntu kernel: [43380.856728] [<c0130925>] ? kmap_atomic_prot+0xd5/0xf0
May 12 04:46:22 ubuntu kernel: [43380.856735] [<f8aedf1f>] ? cifs_d_revalidate+0x1f/0xe0 [cifs]
May 12 04:46:22 ubuntu kernel: [43380.856739] [<c02142d1>] ? do_lookup+0x41/0xc0
May 12 04:46:22 ubuntu kernel: [43380.856743] [<c021268f>] ? generic_permission+0x1f/0xa0
May 12 04:46:22 ubuntu kernel: [43380.856747] [<c021476d>] ? __link_path_walk+0x15d/0xca0
May 12 04:46:22 ubuntu kernel: [43380.856750] [<c01307b0>] ? kunmap_atomic+0x60/0x70
May 12 04:46:22 ubuntu kernel: [43380.856753] [<c02154c4>] ? path_walk+0x54/0xc0
May 12 04:46:22 ubuntu kernel: [4338...

[Martijn van Brummelen (martijn-brumit)]

On a other computer slightly different maybe cause of the slightly older kernel? :
May 12 04:57:04 ict143 kernel: [162817.458671] Pid: 331, comm: cp Tainted: P (2.6.32-30-generic #59-Ubuntu) HP Compaq dc7800p Small Form Factor
May 12 04:57:04 ict143 kernel: [162817.458674] EIP: 0060:[<c02f474a>] EFLAGS: 00210246 CPU: 0
May 12 04:57:04 ict143 kernel: [162817.458677] EIP is at wait_for_key_construction+0x2a/0x70
May 12 04:57:04 ict143 kernel: [162817.458679] EAX: 00000000 EBX: 00000000 ECX: c02f4790 EDX: 00000000
May 12 04:57:04 ict143 kernel: [162817.458682] ESI: 00000002 EDI: f15e2700 EBP: c89cdb18 ESP: c89cdb0c
May 12 04:57:04 ict143 kernel: [162817.458684] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
May 12 04:57:04 ict143 kernel: [162817.458690] f8d7a8a0 00000000 f2128e00 c89cdb40 c02f50da 00000000 00000000 00000000
May 12 04:57:04 ict143 kernel: [162817.458697] <0> 00000000 f8d6cfec ef963cc0 ef963cc0 f2128e00 c89cdb6c f8d663dc ef963d0f
May 12 04:57:04 ict143 kernel: [162817.458704] <0> f8d6cfe2 0000014b f6815780 f6815780 f15e27a2 f15e2700 00000800 00004058
May 12 04:57:04 ict143 kernel: [162817.458715] [<c02f50da>] ? request_key+0x5a/0x90
May 12 04:57:04 ict143 kernel: [162817.458725] [<f8d663dc>] ? cifs_get_spnego_key+0x17c/0x1d0 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458733] [<f8d64dfd>] ? CIFS_SessSetup+0x66d/0xc10 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458738] [<c03b38fe>] ? extract_buf+0x7e/0xe0
May 12 04:57:04 ict143 kernel: [162817.458745] [<f8d4ca69>] ? cifs_setup_session+0x69/0x1a0 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458751] [<f8d435eb>] ? cifs_reconnect_tcon+0x1ab/0x280 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458757] [<f8d436e4>] ? smb_init+0x24/0x80 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458764] [<f8d47375>] ? CIFSSMBUnixQPathInfo+0x55/0x250 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458771] [<f8d58a3e>] ? cifs_get_inode_info_unix+0x5e/0x100 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458776] [<c013087c>] ? kmap_atomic_prot+0x4c/0xf0
May 12 04:57:04 ict143 kernel: [162817.458783] [<f8d518b5>] ? build_path_from_dentry+0xa5/0x1e0 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458790] [<f8d5198c>] ? build_path_from_dentry+0x17c/0x1e0 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458795] [<c01d0c37>] ? get_page_from_freelist+0x147/0x360
May 12 04:57:04 ict143 kernel: [162817.458800] [<c058f4ed>] ? _spin_lock+0xd/0x10
May 12 04:57:04 ict143 kernel: [162817.458807] [<f8d58cd4>] ? cifs_revalidate+0x1f4/0x3e0 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458811] [<c0203a4a>] ? __mem_cgroup_commit_charge+0x4a/0xc0
May 12 04:57:04 ict143 kernel: [162817.458818] [<f8d51f0f>] ? cifs_d_revalidate+0x1f/0xe0 [cifs]
May 12 04:57:04 ict143 kernel: [162817.458822] [<c02141e1>] ? do_lookup+0x41/0xc0
May 12 04:57:04 ict143 kernel: [162817.458826] [<c021259f>] ? generic_permission+0x1f/0xa0
May 12 04:57:04 ict143 kernel: [162817.458830] [<c021467d>] ? __link_path_walk+0x15d/0xca0
May 12 04:57:04 ict143 kernel: [162817.458834] [<c01e82a8>] ? handle_mm_fault+0x338/0x390
May 12 04:57:04 ict143 kernel: [162817.458837] [<c02153d4>] ? path_walk+0x54/0xc0
May 12 04:57:04 ict143 ker...

[Martijn van Brummelen (martijn-brumit)]

More logging
May 20 15:52:41 kernel: [27120.280287] [<f874e0ef>] cifs_file_aio_write+0x2f/0x60 [cifs]
May 20 15:52:41 kernel: [27120.280294] [<c02136d4>] do_sync_write+0xc4/0x100
May 20 15:52:41 kernel: [27120.280299] [<c01706d0>] ? autoremove_wake_function+0x0/0x50
May 20 15:52:41 kernel: [27120.280307] [<c0300dc4>] ? security_file_permission+0x14/0x20
May 20 15:52:41 kernel: [27120.280311] [<c0213874>] ? rw_verify_area+0x64/0xe0
May 20 15:52:41 kernel: [27120.280318] [<c0213992>] vfs_write+0xa2/0x1a0
May 20 15:52:41 kernel: [27120.280321] [<c0213610>] ? do_sync_write+0x0/0x100
May 20 15:52:41 kernel: [27120.280329] [<c05b7cf0>] ? do_page_fault+0x160/0x3a0
May 20 15:52:41 kernel: [27120.280333] [<c02142b2>] sys_write+0x42/0x70
May 20 15:52:41 kernel: [27120.280340] [<c01096c3>] sysenter_do_call+0x12/0x28
May 20 15:52:41 kernel: < Send error in SessSetup = -126

[Martijn van Brummelen (martijn-brumit)]

May 20 15:50:40 kernel: Send error in SessSetup = -126 Send error in SessSetup = -126
May 20 15:50:41 kernel: <3 Send error in SessSetup = -126
May 20 15:50:41 kernel: < Send error in SessSetup = -126
May 20 15:50:41 kernel: <3 Send error in SessSetup = -126
May 20 15:50:41 kernel: < Send error in SessSetup = -126
May 20 15:50:41 kernel: <3 Send error in SessSetup = -126
May 20 15:50:41 kernel: Send error in SessSetup = -126
May 20 15:50:41 kernel: S VFS: Send e-126
May 20 15:50:41 kernel: 7000.rror in S>[27000.5763IFSSenr iSet1267000.25 er Sep =<3>.25 CI: Sror in270655S Vnd in tup6
May 20 15:50:41 kernel: <00.257r in SessSetup = -126
May 20 15:50:41 kernel: <-126
May 20 15:50:41 kernel: < -126
May 20 15:50:41 kernel: <sSetup = ssSetup = -126
May 20 15:50:41 kernel: <3ssSetup = -126
May 20 15:50:41 kernel: <3ssSetup = -126
May 20 15:50:41 kernel: <3 Send error in SessSetup = -126
May 20 15:50:41 kernel: <3317126] CIFS VFS: Send error in SessSetup = -126

[Massimo Forti (slackwarelife)]

Hi, the "CIFS VFS: No response for cmd 50" problem appears because you shutting down the network service before the Samba unmount the shares. In many other case this happens when you stop the OS and it not unmount correctly the shares.

For "Send error in SessSetup = -126", probably we need to reed this: http://samba.2283325.n4.nabble.com/CIFS-mount-and-smbclient-with-krb5-not-work-with-dfs-namespace-td2521803.html

Now I try and then we will continue to post about your bug. Many Thanks.

[Martijn van Brummelen (martijn-brumit)]

Hi,

I am mounting the home directory of a user with mount.cifs if a packets gets lost while logged in the cifs error appears and the machine gets unuseable.
If I mount the home directory with libpam-mount everything goes fine.
If you need more informatie please let me know.

[Massimo Forti (slackwarelife)]

Hi, try to mount with this command: "mount.cifs //foobar.local/san/$PAM_USER $HOME_mount -verobse -o sec=krb5" for debug the mount works command. Many thanks.

[Martijn van Brummelen (martijn-brumit)]

Allright will try it on thuesday and paste the verbose information.

[Martijn van Brummelen (martijn-brumit)]

mount.cifs kernel mount option unc=//foobar.local\san,user=root,ver=1,sec=krb5,prefixpath=$username,ip=$ip-adres

Not much other verbose information while mounting.

syslog says :

Jul 19 08:26:56 ubuntu cifs.upcall: key description: cifs.spnego;0;513;3f000000;ver=0x2;host=foobar.local;ip4=$ip;sec=krb5;uid=0xb373;user=$username;pid=0x1239
Jul 19 08:26:56 ubuntu cifs.upcall: find_krb5_cc: considering /tmp/krb5cc_pam_0SFxOq
Jul 19 08:26:56 ubuntu cifs.upcall: find_krb5_cc: /tmp/krb5cc_pam_0SFxOq is owned by 0, not 45939
Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: getting service ticket for cifs/foorbar.local
Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: failed to obtain service ticket (-1765328189)
Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: getting service ticket for host/foobar.local
Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: failed to obtain service ticket (-1765328189)
Jul 19 08:26:56 ubuntu kernel: [ 1003.356085] CIFS VFS: Send error in SessSetup = -126
Jul 19 08:26:56 ubuntu kernel: [ 1003.356093] CIFS VFS: cifs_mount failed w/return code = -126

Machine is fully updates Lucid 10.4-3

[Massimo Forti (slackwarelife)]

Hi, thanks for your debug reporting. The information I need are these:

Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: getting service ticket for cifs/foorbar.local
Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: failed to obtain service ticket (-1765328189)
Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: getting service ticket for host/foobar.local
Jul 19 08:26:56 ubuntu cifs.upcall: handle_krb5_mech: failed to obtain service ticket (-1765328189)

The sane thing was discussed in Red Hat Bug with a solution. To not copy all the Red Hat bug, i post to you the interesting link:

https://bugzilla.redhat.com/show_bug.cgi?id=574750

Let me know your opinion about the discussion done in above link. Thanks.

[Mike Warnecke (q-mike-d)]

This is still a problem in 2019? I've attached my Ubuntu 18.04.2 desktop to an Active Directory using:

https://help.ubuntu.com/lts/serverguide/sssd-ad.html.en

Everything appears to work perfectly until some sort of failure - I can reproduce it under high load, or just waiting..., I'll try pulling the network cable next. After than, any access to the mount, causes a hang for that process.

dmesg offers:
[91051.156847] CIFS VFS: Send error in SessSetup = -126
[91051.156860] CIFS VFS: Send error in SessSetup = -126
[91229.140916] INFO: task kworker/3:1:11816 blocked for more than 120 seconds.
[91229.140922] Not tainted 4.18.0-18-generic #19~18.04.1-Ubuntu
[91229.140924] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91229.140927] kworker/3:1 D 0 11816 2 0x80000000
[91229.140961] Workqueue: cifsiod smb2_reconnect_server [cifs]
[91229.140963] Call Trace:
[91229.140969] __schedule+0x2b7/0x880
[91229.140972] schedule+0x2c/0x80
[91229.140974] schedule_preempt_disabled+0xe/0x10
[91229.140976] __mutex_lock.isra.4+0x18c/0x4d0
[91229.140980] __mutex_lock_slowpath+0x13/0x20
[91229.140981] ? __mutex_lock_slowpath+0x13/0x20
[91229.140983] mutex_lock+0x2f/0x40
[91229.141003] smb2_reconnect+0xed/0x4b0 [cifs]
[91229.141006] ? __switch_to_asm+0x34/0x70
[91229.141008] ? __switch_to_asm+0x40/0x70
[91229.141010] ? __switch_to_asm+0x34/0x70
[91229.141012] ? __switch_to_asm+0x40/0x70
[91229.141015] ? __switch_to_asm+0x34/0x70
[91229.141017] ? __switch_to_asm+0x40/0x70
[91229.141019] ? __switch_to_asm+0x34/0x70
[91229.141036] smb2_reconnect_server+0x190/0x2d0 [cifs]
[91229.141041] process_one_work+0x1fd/0x3f0
[91229.141044] worker_thread+0x34/0x410
[91229.141047] kthread+0x121/0x140
[91229.141050] ? process_one_work+0x3f0/0x3f0
[91229.141053] ? kthread_create_worker_on_cpu+0x70/0x70
[91229.141055] ret_from_fork+0x35/0x40
[91229.141058] INFO: task bash:11900 blocked for more than 120 seconds.
[91229.141061] Not tainted 4.18.0-18-generic #19~18.04.1-Ubuntu
[91229.141062] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91229.141064] bash D 0 11900 2685 0x80000000
[91229.141066] Call Trace:
[91229.141069] __schedule+0x2b7/0x880
[91229.141071] schedule+0x2c/0x80
[91229.141073] schedule_preempt_disabled+0xe/0x10
[91229.141074] __mutex_lock.isra.4+0x18c/0x4d0
[91229.141092] ? cifs_small_buf_release+0x1a/0x70 [cifs]
[91229.141109] ? SMB2_auth_kerberos+0x92/0x190 [cifs]
[91229.141112] __mutex_lock_slowpath+0x13/0x20
[91229.141114] ? __mutex_lock_slowpath+0x13/0x20
[91229.141115] mutex_lock+0x2f/0x40
[91229.141130] cifs_mark_open_files_invalid+0x5b/0xa0 [cifs]
[91229.141146] smb2_reconnect+0x135/0x4b0 [cifs]
[91229.141163] smb2_plain_req_init+0x34/0x270 [cifs]
[91229.141180] SMB2_open+0xe9/0xc90 [cifs]
[91229.141185] ? get_page_from_freelist+0xcd0/0x1430
[91229.141187] ? get_page_from_freelist+0x1420/0x1430
[91229.141205] open_shroot+0x16c/0x210 [cifs]
[91229.141221] ? open_shroot+0x16c/0x210 [cifs]
[91229.141239] smb2_open_op_close+0x26f/0x2e0 [cifs]
[91229.141242] ? alloc_pages_current+0x6a/0xe0
[91229.141259] smb2_query_path_info+0x74/...