"Dr. Bernd Feige" <bernd.feige@xxxxxxxxxxxxxxxxxxxxx> writes:
> [ 88.029589] fs/cifs/cifsfs.c: Devname: //dc1/Group flags: 0
> [ 88.029600] address conversion returned 1 for xxx
> [ 88.029617] fs/cifs/connect.c: iocharset set to utf8
> [ 88.029626] fs/cifs/connect.c: Username: root
> [ 88.031066] fs/cifs/connect.c: file mode: 0x180 dir mode: 0x1c0
> [ 88.031069] fs/cifs/connect.c: CIFS VFS: in cifs_mount as Xid: 0 with uid: 0
> [ 88.031070] fs/cifs/connect.c: UNC: \\dc1\Group
[...]
we connect to //dc1/Group which resolved to a root DFS server at //dc3/Group
> [ 88.082249] fs/cifs/inode.c: CIFS VFS: in cifs_root_iget as Xid: 11 with uid: 0
> [ 88.082251] fs/cifs/inode.c: Getting info on
> [ 88.082254] fs/cifs/smb2ops.c: found a cached root file handle
> [ 88.082256] fs/cifs/smb2pdu.c: Query Info
> [ 88.083446] fs/cifs/inode.c: looking for uniqueid=281474976823914
> [ 88.083459] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 281474976823914
> [ 88.083461] fs/cifs/inode.c: cifs_revalidate_cache: inode 281474976823914 is new
> [ 88.083464] fs/cifs/inode.c: CIFS VFS: leaving cifs_root_iget (xid = 11) rc = 0
> [ 88.083466] fs/cifs/cifsfs.c: Get root dentry for
> [ 88.083468] fs/cifs/cifsfs.c: dentry root is: 00000000351ca600
> [ 88.092779] fs/cifs/dir.c: CIFS VFS: in cifs_lookup as Xid: 12 with uid: 1000
> [ 88.092783] fs/cifs/dir.c: parent inode = 0x000000000e3e22bf name is: DATA and dentry = 0x00000000a0e964ca
> [ 88.092785] fs/cifs/dir.c: name: \DATA
> [ 88.092786] fs/cifs/dir.c: NULL inode in lookup
> [ 88.092787] fs/cifs/dir.c: Full path: \DATA inode = 0x (null)
> [ 88.092789] fs/cifs/inode.c: Getting info on \DATA
> [ 88.092795] fs/cifs/smb2pdu.c: create/open
> [ 88.093733] Status code returned 0xc0000257 STATUS_PATH_NOT_COVERED
> [ 88.093739] fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000257 to POSIX err -66
once mounted we access DATA
this error DATA (//DC3/Group/DATA) is a dfs link
> [ 88.093742] fs/cifs/inode.c: creating fake fattr for DFS referral
> [ 88.093744] fs/cifs/inode.c: looking for uniqueid=18446612166559357568
> [ 88.093753] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 18446612166559357568
> [ 88.093754] fs/cifs/inode.c: cifs_revalidate_cache: inode 18446612166559357568 is new
> [ 88.093756] fs/cifs/dir.c: CIFS VFS: leaving cifs_lookup (xid = 12) rc = 0
> [ 88.093758] fs/cifs/cifs_dfs_ref.c: in cifs_dfs_d_automount
> [ 88.093759] fs/cifs/cifs_dfs_ref.c: in cifs_dfs_do_automount
> [ 88.093760] fs/cifs/dir.c: name: \DATA
> [ 88.093762] fs/cifs/cifs_dfs_ref.c: CIFS VFS: in cifs_dfs_do_automount as Xid: 13 with uid: 1000
> [ 88.093763] fs/cifs/smb2ops.c: smb2_get_dfs_refer path <\DC3\Group\DATA>
> [ 88.093767] fs/cifs/smb2pdu.c: SMB2 IOCTL
> [ 88.094602] fs/cifs/misc.c: num_referrals: 1 dfs flags: 0x2 ...
> [ 88.094614] fs/cifs/cifs_dfs_ref.c: CIFS VFS: leaving cifs_dfs_do_automount (xid = 13) rc = 0
> [ 88.094615] fs/cifs/cifs_dfs_ref.c: DFS: ref path: \DC3\Group\DATA
> [ 88.094616] fs/cifs/cifs_dfs_ref.c: DFS: node path: \fsgroup4\group\DATA
> [ 88.094617] fs/cifs/cifs_dfs_ref.c: DFS: fl: 2, srv_type: 0
> [ 88.094618] fs/cifs/cifs_dfs_ref.c: DFS: ref_flags: 0, path_consumed: 63
link resolved to //fsgroup4/group/DATA (different server)
> [ 88.094621] address conversion returned 0 for fsgroup4
> [ 88.094622] address conversion returned 0 for fsgroup4
> [ 88.099802] fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: resolved: fsgroup4 to yyy9
> [ 88.099808] fs/cifs/cifsfs.c: Devname: //fsgroup4/group/DATA flags: 67108864
> [ 88.099820] fs/cifs/connect.c: iocharset set to utf8
> [ 88.099827] address conversion returned 1 for yyy9
> [ 88.099828] fs/cifs/connect.c: Username: root
> [ 88.099829] fs/cifs/connect.c: file mode: 0x180 dir mode: 0x1c0
> [ 88.099831] fs/cifs/connect.c: CIFS VFS: in cifs_mount as Xid: 14 with uid: 1000
> [ 88.099831] fs/cifs/connect.c: UNC: \\fsgroup4\group
> [ 88.099836] fs/cifs/connect.c: Socket created
> [ 88.099837] fs/cifs/connect.c: sndbuf 16384 rcvbuf 87380 rcvtimeo
> 0x1b58
we connect to it
> [ 88.100984] fs/cifs/connect.c: CIFS VFS: in cifs_get_smb_ses as Xid: 15 with uid: 1000
> [ 88.100986] fs/cifs/connect.c: Existing smb sess not found
> [ 88.100987] fs/cifs/connect.c: Demultiplex PID: 4543
> [ 88.100990] fs/cifs/smb2pdu.c: Negotiate protocol
> [ 88.101362] fs/cifs/smb2pdu.c: mode 0x1
> [ 88.101363] fs/cifs/smb2pdu.c: negotiated smb3.0 dialect
> [ 88.101378] fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300053 TimeAdjust: 0
> [ 88.101378] fs/cifs/smb2pdu.c: Session Setup
> [ 88.101380] fs/cifs/smb2pdu.c: sess setup type 5
> [ 88.101383] fs/cifs/cifs_spnego.c: key description = ver=0x2;host=fsgroup4;ip4=yyy9;sec=krb5;uid=0x3e8;creduid=0x3e8;user=root;pid=0x1191
> [ 88.108011] SPNEGO reply blob:: dump of 1024 bytes of data at 0x000000002f33df36
> ...
> [ 88.123996] fs/cifs/smb2pdu.c: SMB2/3 session established successfully
we make a new session.
note that this new connection is using smb3.0 and not 3.1.1.
> [ 88.124006] fs/cifs/connect.c: CIFS VFS: leaving cifs_get_smb_ses (xid = 15) rc = 0
> [ 88.124009] fs/cifs/connect.c: CIFS VFS: in cifs_setup_ipc as Xid: 16 with uid: 1000
> [ 88.124010] fs/cifs/smb2pdu.c: TCON
> [ 88.124408] fs/cifs/smb2pdu.c: connection to pipe share
open IPC$ tcon
> [ 88.124410] fs/cifs/smb2pdu.c: validate negotiate
> [ 88.124412] fs/cifs/smb2pdu.c: SMB2 IOCTL
> [ 88.124927] fs/cifs/smb2pdu.c: validate negotiate info successful
send validate nego
> [ 88.124930] fs/cifs/connect.c: CIFS VFS: leaving cifs_setup_ipc (xid = 16) rc = 0
> [ 88.124931] fs/cifs/connect.c: IPC tcon rc = 0 ipc tid = 1
> [ 88.124934] fs/cifs/connect.c: CIFS VFS: in cifs_get_tcon as Xid: 17 with uid: 1000
> [ 88.124935] fs/cifs/smb2pdu.c: TCON
> [ 88.126027] fs/cifs/smb2pdu.c: connection to disk share
> [ 88.126029] fs/cifs/smb2pdu.c: validate negotiate
> [ 88.126040] fs/cifs/smb2pdu.c: SMB2 IOCTL
> [ 88.126594] fs/cifs/smb2pdu.c: validate negotiate info successful
> [ 88.126607] fs/cifs/connect.c: CIFS VFS: leaving cifs_get_tcon (xid = 17) rc = 0
> [ 88.126608] fs/cifs/connect.c: Tcon rc = 0
open DATA tcon
> [ 88.126610] fs/cifs/smb2pdu.c: create/open
> [ 88.127759] Status code returned 0xc0000010 STATUS_INVALID_DEVICE_REQUEST
> [ 88.127778] fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000010 to POSIX err -95
> [ 88.127780] CIFS VFS: error -95 on ioctl to get interface list
This is the code that gets the interface list which the server doesnt
support, can be ignored.
> [ 88.127782] fs/cifs/smb2pdu.c: Query FSInfo level 5
> [ 88.128175] fs/cifs/smb2pdu.c: Query FSInfo level 4
> [ 88.129538] fs/cifs/connect.c: build_unc_path_to_root: full_path=\\fsgroup4\group\DATA
> [ 88.129550] fs/cifs/smb2ops.c: smb2_get_dfs_refer path <\fsgroup4\group>
> [ 88.130012] Status code returned 0xc0000225 STATUS_NOT_FOUND
> [ 88.130015] fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000225 to POSIX err -2
we tried to resolve \fsgroup4\group in case it is a dfs root somewhere
else but it's not, continue rest of mount.
~2 seconds pass here, I'm guessing you waited and ran a command or something.
> [ 90.968502] fs/cifs/inode.c: CIFS VFS: in cifs_revalidate_dentry_attr as Xid: 453 with uid: 1000
> [ 90.968504] fs/cifs/dir.c: name: \DATA
> [ 90.968506] fs/cifs/inode.c: Update attributes: \DATA inode 0x00000000e003cbf1 count 1 dentry: 0x00000000a0e964ca d_time 4294755796 jiffies 4294758671
> [ 90.968507] fs/cifs/inode.c: Getting info on \DATA
> [ 90.968512] fs/cifs/smb2pdu.c: create/open
> [ 90.969081] Status code returned 0xc0000257 STATUS_PATH_NOT_COVERED
> [ 90.969085] fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000257 to POSIX err -66
> [ 90.969098] fs/cifs/inode.c: creating fake fattr for DFS referral
> [ 90.969100] fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate_dentry_attr (xid = 453) rc = -116
we call cifs_revalidate_dentry_attr() on the DATA dentry, again it sees its a
link and adds the DFS/AUTOMOUNT flag to the inode/dentry and returns
-116 aka -ESTALE.
I'm not sure how cifs_revalidate_dentry_attr end up being called but
this is the code path from it:
int cifs_revalidate_dentry_attr(struct dentry *dentry)
{
...
else
rc = cifs_get_inode_info(&inode, full_path, NULL, sb,
xid, NULL);
---> int cifs_get_inode_info_unix(...)
...
/* we already have inode, update it */
/* if uniqueid is different, return error */
if (unlikely(cifs_sb->mnt_cifs_flags & CIFS_MOUNT_SERVER_INUM &&
CIFS_I(*pinode)->uniqueid != fattr.cf_uniqueid)) {
rc = -ESTALE;
goto cgiiu_exit;
}
/* if filetype is different, return error */
if (unlikely(((*pinode)->i_mode & S_IFMT) !=
(fattr.cf_mode & S_IFMT))) {
rc = -ESTALE;
goto cgiiu_exit;
}
cifs_fattr_to_inode(*pinode, &fattr);
}
cgiiu_exit:
return rc;
}
<-- returns to cifs_revalidate_dentry_attr
out:
kfree(full_path);
free_xid(xid);
return rc;
}
Then I guess the task locks up somewhere..
The echo thing is a separate task so it keeps working.
> [ 152.135169] fs/cifs/smb2pdu.c: In echo request
> [ 152.135176] __smb_send_rqst: 478 callbacks suppressed
> [ 152.135187] fs/cifs/transport.c: Sending smb: smb_len=72
> [ 152.135480] cifs_demultiplex_thread: 478 callbacks suppressed
> [ 152.135481] fs/cifs/connect.c: RFC1002 header 0x44
> [ 152.135485] smb2_calc_size: 1338 callbacks suppressed
> [ 152.135485] fs/cifs/smb2misc.c: SMB2 len 68
[...]
So I'm not sure whether the -ESTALE error is supposed to happen. When
using DFS servers you cannot guarantee stable and unique inode numbers
because you are getting unique ids from 2 different servers and they
might overlap.
I think it would help if you provided a similar log of the working
kernel. Maybe redo it for both kernels if you think something might have
changed since your last run.
--
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)
