* [LTP] NFS tests failure: RPC: Couldn't create auth handle (flavor 390004)
@ 2021-03-01 15:51 Petr Vorel
2021-03-02 11:35 ` Alexey Kodanev
0 siblings, 1 reply; 3+ messages in thread
From: Petr Vorel @ 2021-03-01 15:51 UTC (permalink / raw)
To: ltp
Hi Alexey,
I'm looking to some NFS failures on recent openSUSE kernel 5.11.
"RPC: Couldn't create auth handle (flavor 390004)" error has something to
do with krb5i, but module rpcsec_gss_krb5 is loaded.
Any idea what could cause "nfs41_sequence_process: Error 0 free the slot"
and "NFS reply lookup: -2"?
Kind regards,
Petr
[35133.723728] nfsd_inet6addr_event: removed fd00:0001:0001:0001:0000:0000:0000:0002
[35133.723783] nfsd_inet6addr_event: removed fe80:0000:0000:0000:04c0:ffff:fecb:0122
[35133.741177] nfsd_inetaddr_event: removed 10.0.0.2
[35133.745023] IPv6: ADDRCONF(NETDEV_CHANGE): ltp_ns_veth2: link becomes ready
[35134.023324] NFS: parsing nfs mount option 'source'
[35134.023329] NFS: parsing nfs mount option 'proto'
[35134.023330] NFS: parsing nfs mount option 'vers'
[35134.023332] NFS: parsing nfs mount option 'addr'
[35134.023334] NFS: parsing nfs mount option 'clientaddr'
[35134.023336] NFS: MNTPATH: '/tmp/LTP_nfs01.Npv7p6ePHT/4.1/tcp'
[35134.023338] --> nfs4_try_get_tree()
[35134.023346] NFS: get client cookie (0x000000003f4944e9/0x00000000c67386ff)
[35134.023380] RPC: Couldn't create auth handle (flavor 390004)
[35134.023392] nfs_create_rpc_client: cannot create RPC client. Error = -22
[35134.023826] nfs_callback_create_svc: service created
[35134.023827] NFS: create per-net callback data; net=f0000358
[35134.023919] nfs_callback_up: service started
[35134.023920] NFS: nfs4_discover_server_trunking: testing '10.0.0.2'
[35134.023967] nfsd4_exchange_id rqstp=00000000b0a905ff exid=00000000c41af45a clname.len=22 clname.data=000000004be94038 ip_addr=10.0.0.1 flags 101, spa_how 0
[35134.023981] nfsd4_exchange_id seqid 0 flags 20001
[35134.024131] nfsd4_exchange_id rqstp=00000000b0a905ff exid=00000000c41af45a clname.len=22 clname.data=000000004be94038 ip_addr=10.0.0.1 flags 101, spa_how 0
[35134.024150] nfsd4_exchange_id seqid 0 flags 20001
[35134.024271] --> nfs4_proc_create_session clp=000000003f4944e9 session=000000008231b4d6
[35134.024277] nfs4_init_channel_attrs: Fore Channel : max_rqst_sz=1049620 max_resp_sz=1049480 max_ops=8 max_reqs=64
[35134.024281] nfs4_init_channel_attrs: Back Channel : max_rqst_sz=4096 max_resp_sz=4096 max_resp_sz_cached=0 max_ops=2 max_reqs=16
[35134.024334] check_slot_seqid enter. seqid 1 slot_seqid 0
[35134.024337] NFSD: move_to_confirm nfs4_client 0000000005ccbb59
[35134.024462] --> nfs4_setup_session_slot_tables
[35134.024464] --> nfs4_realloc_slot_table: max_reqs=30, tbl->max_slots 0
[35134.024469] nfs4_realloc_slot_table: tbl=0000000054cdc1a8 slots=00000000b96721b4 max_slots=30
[35134.024471] <-- nfs4_realloc_slot_table: return 0
[35134.024473] --> nfs4_realloc_slot_table: max_reqs=16, tbl->max_slots 0
[35134.024476] nfs4_realloc_slot_table: tbl=00000000a895ddf2 slots=0000000031ce2890 max_slots=16
[35134.024478] <-- nfs4_realloc_slot_table: return 0
[35134.024479] slot table setup returned 0
[35134.024480] nfs4_proc_create_session client>seqid 2 sessionid 1614612109:2516949716:5:0
[35134.024482] <-- nfs4_proc_create_session
[35134.024483] nfs4_schedule_state_renewal: requeueing work. Lease period = 5
[35134.024489] --> nfs41_proc_reclaim_complete
[35134.024491] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.024492] NFS: nfs4_discover_server_trunking: status = 0
[35134.024493] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.024497] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=1 slotid=0 max_slotid=0 cache_this=0
[35134.024510] --> _nfs41_proc_secinfo_no_name
[35134.024512] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.024535] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.024539] nfsd4_sequence: slotid 0
[35134.024540] check_slot_seqid enter. seqid 1 slot_seqid 0
[35134.024544] alloc_cld_upcall: allocated xid 5
[35134.046004] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.046096] --> nfs4_reclaim_complete_done
[35134.046104] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.046109] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.046112] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.046115] nfs41_sequence_process: Error 0 free the slot
[35134.046117] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.046120] <-- nfs4_reclaim_complete_done
[35134.046127] <-- nfs41_proc_reclaim_complete status=0
[35134.046130] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=16
[35134.046133] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.046136] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.046138] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.046141] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.046148] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.046151] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.046153] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.046153] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.046162] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=2 slotid=0 max_slotid=0 cache_this=0
[35134.046247] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.046251] nfsd4_sequence: slotid 0
[35134.046253] check_slot_seqid enter. seqid 2 slot_seqid 1
[35134.046258] nfsd: fh_compose(exp fe:01/2 /, ino=2)
[35134.046264] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.046373] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.046378] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.046380] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.046382] nfs41_sequence_process: Error 0 free the slot
[35134.046384] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.046389] <-- _nfs41_proc_secinfo_no_name status=0
[35134.058969] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.058975] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.058981] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.058989] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=3 slotid=0 max_slotid=0 cache_this=0
[35134.059137] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.059142] nfsd4_sequence: slotid 0
[35134.059144] check_slot_seqid enter. seqid 3 slot_seqid 2
[35134.059149] nfsd: fh_compose(exp fe:01/2 /, ino=2)
[35134.059155] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.059162] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.059254] decode_attr_type: type=040000
[35134.059258] decode_attr_change: change attribute=6934706255420194816
[35134.059260] decode_attr_size: file size=4096
[35134.059262] decode_attr_fsid: fsid=(0x0/0x0)
[35134.059265] decode_attr_fileid: fileid=2
[35134.059267] decode_attr_fs_locations: fs_locations done, error = 0
[35134.059269] decode_attr_mode: file mode=0755
[35134.059271] decode_attr_nlink: nlink=23
[35134.059273] decode_attr_owner: uid=0
[35134.059275] decode_attr_group: gid=0
[35134.059276] decode_attr_rdev: rdev=(0x0:0x0)
[35134.059278] decode_attr_space_used: space used=4096
[35134.059279] decode_attr_time_access: atime=1614577167
[35134.059281] decode_attr_time_metadata: ctime=1606120833
[35134.059284] decode_attr_time_modify: mtime=1606120833
[35134.059285] decode_attr_mounted_on_fileid: fileid=1
[35134.059287] decode_getfattr_attrs: xdr returned 0
[35134.059289] decode_getfattr_generic: xdr returned 0
[35134.059293] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.059296] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.059299] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.059300] nfs41_sequence_process: Error 0 free the slot
[35134.059303] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.059311] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.059314] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.059317] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.059322] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=4 slotid=0 max_slotid=0 cache_this=0
[35134.059439] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.059444] nfsd4_sequence: slotid 0
[35134.059445] check_slot_seqid enter. seqid 4 slot_seqid 3
[35134.059450] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.059455] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.059459] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.059620] decode_attr_supported: bitmask=fdffbfff:40f9be3e:00000803
[35134.059643] decode_attr_fh_expire_type: expire type=0x0
[35134.059645] decode_attr_link_support: link support=true
[35134.059646] decode_attr_symlink_support: symlink support=true
[35134.059648] decode_attr_aclsupport: ACLs supported=3
[35134.059649] decode_attr_exclcreat_supported: bitmask=00001010:00000032:00000000
[35134.059651] decode_server_caps: xdr returned 0!
[35134.059654] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.059657] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.059659] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.059660] nfs41_sequence_process: Error 0 free the slot
[35134.059662] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.059668] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.059671] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.059672] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.059677] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=5 slotid=0 max_slotid=0 cache_this=0
[35134.059800] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.059804] nfsd4_sequence: slotid 0
[35134.059806] check_slot_seqid enter. seqid 5 slot_seqid 4
[35134.059810] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.059816] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.059820] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.059932] decode_attr_lease_time: lease time=90
[35134.059936] decode_attr_maxfilesize: maxfilesize=17592186040320
[35134.059938] decode_attr_maxread: maxread=1048576
[35134.059939] decode_attr_maxwrite: maxwrite=1048576
[35134.059941] decode_attr_time_delta: time_delta=0 4000000
[35134.059942] decode_attr_pnfstype: bitmap is 40000000
[35134.059944] decode_attr_layout_blksize: bitmap is 2
[35134.059945] decode_attr_clone_blksize: bitmap is 0
[35134.059946] decode_attr_xattrsupport: XATTR support=false
[35134.059947] decode_fsinfo: xdr returned 0!
[35134.059950] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.059952] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.059954] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.059955] nfs41_sequence_process: Error 0 free the slot
[35134.059957] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.059964] Server FSID: 0:0
[35134.059967] Pseudo-fs root FH@0000000032a8b38c is 8 bytes, crc: 0x62d40c52:
[35134.059970] 01000100 00000000
[35134.059973] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.059975] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.059977] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.059981] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=6 slotid=0 max_slotid=0 cache_this=0
[35134.060025] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.060028] nfsd4_sequence: slotid 0
[35134.060029] check_slot_seqid enter. seqid 6 slot_seqid 5
[35134.060032] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060036] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060039] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.060146] decode_attr_supported: bitmask=fdffbfff:40f9be3e:00000803
[35134.060151] decode_attr_fh_expire_type: expire type=0x0
[35134.060152] decode_attr_link_support: link support=true
[35134.060154] decode_attr_symlink_support: symlink support=true
[35134.060155] decode_attr_aclsupport: ACLs supported=3
[35134.060156] decode_attr_exclcreat_supported: bitmask=00001010:00000032:00000000
[35134.060158] decode_server_caps: xdr returned 0!
[35134.060161] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.060163] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.060165] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.060167] nfs41_sequence_process: Error 0 free the slot
[35134.060168] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.060175] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.060177] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.060179] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.060183] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=7 slotid=0 max_slotid=0 cache_this=0
[35134.060267] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.060272] nfsd4_sequence: slotid 0
[35134.060274] check_slot_seqid enter. seqid 7 slot_seqid 6
[35134.060278] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060284] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060288] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.060449] decode_attr_lease_time: lease time=90
[35134.060468] decode_attr_maxfilesize: maxfilesize=17592186040320
[35134.060470] decode_attr_maxread: maxread=1048576
[35134.060471] decode_attr_maxwrite: maxwrite=1048576
[35134.060472] decode_attr_time_delta: time_delta=0 4000000
[35134.060474] decode_attr_pnfstype: bitmap is 40000000
[35134.060476] decode_attr_layout_blksize: bitmap is 2
[35134.060477] decode_attr_clone_blksize: bitmap is 0
[35134.060478] decode_attr_xattrsupport: XATTR support=false
[35134.060479] decode_fsinfo: xdr returned 0!
[35134.060481] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.060483] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.060485] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.060487] nfs41_sequence_process: Error 0 free the slot
[35134.060488] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.060494] set_pnfs_layoutdriver: Using NFSv4 I/O
[35134.060497] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.060499] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.060501] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.060505] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=8 slotid=0 max_slotid=0 cache_this=0
[35134.060604] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.060608] nfsd4_sequence: slotid 0
[35134.060609] check_slot_seqid enter. seqid 8 slot_seqid 7
[35134.060613] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060617] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060621] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.060727] decode_attr_maxlink: maxlink=255
[35134.060730] decode_attr_maxname: maxname=255
[35134.060731] decode_pathconf: xdr returned 0!
[35134.060734] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.060736] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.060739] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.060740] nfs41_sequence_process: Error 0 free the slot
[35134.060741] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.060752] NFS: parsing nfs mount option 'source'
[35134.060755] NFS: MNTPATH: '/'
[35134.060851] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.060855] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.060858] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.060864] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=9 slotid=0 max_slotid=0 cache_this=0
[35134.060914] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.060918] nfsd4_sequence: slotid 0
[35134.060919] check_slot_seqid enter. seqid 9 slot_seqid 8
[35134.060922] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060927] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.060929] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.060980] decode_attr_supported: bitmask=fdffbfff:40f9be3e:00000803
[35134.060985] decode_attr_fh_expire_type: expire type=0x0
[35134.060986] decode_attr_link_support: link support=true
[35134.060989] decode_attr_symlink_support: symlink support=true
[35134.060990] decode_attr_aclsupport: ACLs supported=3
[35134.060992] decode_attr_exclcreat_supported: bitmask=00001010:00000032:00000000
[35134.060995] decode_server_caps: xdr returned 0!
[35134.060998] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.061001] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.061003] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.061005] nfs41_sequence_process: Error 0 free the slot
[35134.061007] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.061015] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.061017] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.061020] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.061027] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=10 slotid=0 max_slotid=0 cache_this=0
[35134.061116] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.061122] nfsd4_sequence: slotid 0
[35134.061124] check_slot_seqid enter. seqid 10 slot_seqid 9
[35134.061128] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.061134] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.061140] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.061220] decode_attr_type: type=040000
[35134.061223] decode_attr_change: change attribute=6934706255420194816
[35134.061225] decode_attr_size: file size=4096
[35134.061227] decode_attr_fsid: fsid=(0x0/0x0)
[35134.061229] decode_attr_fileid: fileid=2
[35134.061231] decode_attr_fs_locations: fs_locations done, error = 0
[35134.061233] decode_attr_mode: file mode=0755
[35134.061235] decode_attr_nlink: nlink=23
[35134.061237] decode_attr_owner: uid=0
[35134.061239] decode_attr_group: gid=0
[35134.061241] decode_attr_rdev: rdev=(0x0:0x0)
[35134.061243] decode_attr_space_used: space used=4096
[35134.061245] decode_attr_time_access: atime=1614577167
[35134.061247] decode_attr_time_metadata: ctime=1606120833
[35134.061249] decode_attr_time_modify: mtime=1606120833
[35134.061250] decode_attr_mounted_on_fileid: fileid=1
[35134.061252] decode_getfattr_attrs: xdr returned 0
[35134.061254] decode_getfattr_generic: xdr returned 0
[35134.061256] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.061259] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.061261] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.061264] nfs41_sequence_process: Error 0 free the slot
[35134.061266] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.061275] NFS: nfs_fhget(0:82/2 fh_crc=0x62d40c52 ct=1)
[35134.061294] NFS: permission(0:82/2), mask=0x81, res=-10
[35134.061300] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.061303] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.061305] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.061310] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=11 slotid=0 max_slotid=0 cache_this=0
[35134.061396] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.061402] nfsd4_sequence: slotid 0
[35134.061404] check_slot_seqid enter. seqid 11 slot_seqid 10
[35134.061408] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.061414] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.061418] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.061421] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.061503] decode_attr_type: type=00
[35134.061505] decode_attr_change: change attribute=6934706255420194816
[35134.061507] decode_attr_size: file size=4096
[35134.061508] decode_attr_fsid: fsid=(0x0/0x0)
[35134.061510] decode_attr_fileid: fileid=0
[35134.061512] decode_attr_fs_locations: fs_locations done, error = 0
[35134.061514] decode_attr_mode: file mode=00
[35134.061515] decode_attr_nlink: nlink=1
[35134.061517] decode_attr_rdev: rdev=(0x0:0x0)
[35134.061519] decode_attr_space_used: space used=0
[35134.061521] decode_attr_time_access: atime=0
[35134.061523] decode_attr_time_metadata: ctime=1606120833
[35134.061525] decode_attr_time_modify: mtime=1606120833
[35134.061526] decode_attr_mounted_on_fileid: fileid=0
[35134.061527] decode_getfattr_attrs: xdr returned 0
[35134.061529] decode_getfattr_generic: xdr returned 0
[35134.061532] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.061535] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.061537] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.061538] nfs41_sequence_process: Error 0 free the slot
[35134.061540] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.061546] NFS: nfs_update_inode(0:82/2 fh_crc=0x62d40c52 ct=2 info=0x26040)
[35134.061553] NFS: permission(0:82/2), mask=0x1, res=0
[35134.061559] NFS: lookup(/tmp)
[35134.061562] NFS call lookup /tmp
[35134.061564] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
[35134.061567] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
[35134.061569] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[35134.061575] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=12 slotid=0 max_slotid=0 cache_this=0
[35134.061642] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.061646] nfsd4_sequence: slotid 0
[35134.061648] check_slot_seqid enter. seqid 12 slot_seqid 11
[35134.061651] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.061655] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
[35134.061658] nfsd: nfsd_lookup(fh 8: 00010001 00000000 00000000 00000000 00000000 00000000, tmp)
[35134.061663] --> nfsd4_store_cache_entry slot 000000008e086c0f
[35134.061691] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
[35134.061694] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[35134.061695] nfs4_free_slot: slotid 1 highest_used_slotid 0
[35134.061696] nfs41_sequence_process: Error 0 free the slot
[35134.061698] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[35134.061701] NFS reply lookup: -2
[35134.061704] NFS: dentry_delete(/tmp, 80c)
[35134.061730] NFS4: Couldn't follow remote path
[35134.061731] <-- nfs4_try_get_tree() = -2 [error]
[35134.061745] NFS: clear cookie (0x0000000002f41426/0x0000000000000000)
[35134.061948] NFS: releasing superblock cookie (0x00000000faf52af4/0x0000000000000000)
[35134.101941] --> nfs4_proc_destroy_session
[35134.102103] nfsd4_destroy_session: 1614612109:2516949716:5:0
[35134.102111] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
[35134.102427] <-- nfs4_proc_destroy_session
[35134.102432] nfs4_destroy_session Destroy backchannel for xprt 00000000733269a8
[35134.102604] alloc_cld_upcall: allocated xid 6
[35134.125122] NFS: destroy per-net callback data; net=f0000358
[35134.125256] nfs_callback_down: service destroyed
[35134.125267] NFS: releasing client cookie (0x000000003f4944e9/0x00000000c67386ff)
^ permalink raw reply [flat|nested] 3+ messages in thread
* [LTP] NFS tests failure: RPC: Couldn't create auth handle (flavor 390004)
2021-03-01 15:51 [LTP] NFS tests failure: RPC: Couldn't create auth handle (flavor 390004) Petr Vorel
@ 2021-03-02 11:35 ` Alexey Kodanev
2021-03-04 17:02 ` Petr Vorel
0 siblings, 1 reply; 3+ messages in thread
From: Alexey Kodanev @ 2021-03-02 11:35 UTC (permalink / raw)
To: ltp
On 01.03.2021 18:51, Petr Vorel wrote:
> Hi Alexey,
>
> I'm looking to some NFS failures on recent openSUSE kernel 5.11.
>
> "RPC: Couldn't create auth handle (flavor 390004)" error has something to
> do with krb5i, but module rpcsec_gss_krb5 is loaded.
>
Hi Petr,
Do other security flavours work well, or without them using "none" opt?
Also 'sys' is not default in your setup? If it doesn't work just for
krb5 it might be some misconfiguration with kerberos setup there...
> Any idea what could cause "nfs41_sequence_process: Error 0 free the slot"
> and "NFS reply lookup: -2"?
>
> Kind regards,
> Petr
>
> [35133.723728] nfsd_inet6addr_event: removed fd00:0001:0001:0001:0000:0000:0000:0002
> [35133.723783] nfsd_inet6addr_event: removed fe80:0000:0000:0000:04c0:ffff:fecb:0122
> [35133.741177] nfsd_inetaddr_event: removed 10.0.0.2
> [35133.745023] IPv6: ADDRCONF(NETDEV_CHANGE): ltp_ns_veth2: link becomes ready
> [35134.023324] NFS: parsing nfs mount option 'source'
> [35134.023329] NFS: parsing nfs mount option 'proto'
> [35134.023330] NFS: parsing nfs mount option 'vers'
> [35134.023332] NFS: parsing nfs mount option 'addr'
> [35134.023334] NFS: parsing nfs mount option 'clientaddr'
> [35134.023336] NFS: MNTPATH: '/tmp/LTP_nfs01.Npv7p6ePHT/4.1/tcp'
> [35134.023338] --> nfs4_try_get_tree()
> [35134.023346] NFS: get client cookie (0x000000003f4944e9/0x00000000c67386ff)
> [35134.023380] RPC: Couldn't create auth handle (flavor 390004)
> [35134.023392] nfs_create_rpc_client: cannot create RPC client. Error = -22
> [35134.023826] nfs_callback_create_svc: service created
> [35134.023827] NFS: create per-net callback data; net=f0000358
> [35134.023919] nfs_callback_up: service started
> [35134.023920] NFS: nfs4_discover_server_trunking: testing '10.0.0.2'
> [35134.023967] nfsd4_exchange_id rqstp=00000000b0a905ff exid=00000000c41af45a clname.len=22 clname.data=000000004be94038 ip_addr=10.0.0.1 flags 101, spa_how 0
> [35134.023981] nfsd4_exchange_id seqid 0 flags 20001
> [35134.024131] nfsd4_exchange_id rqstp=00000000b0a905ff exid=00000000c41af45a clname.len=22 clname.data=000000004be94038 ip_addr=10.0.0.1 flags 101, spa_how 0
> [35134.024150] nfsd4_exchange_id seqid 0 flags 20001
> [35134.024271] --> nfs4_proc_create_session clp=000000003f4944e9 session=000000008231b4d6
> [35134.024277] nfs4_init_channel_attrs: Fore Channel : max_rqst_sz=1049620 max_resp_sz=1049480 max_ops=8 max_reqs=64
> [35134.024281] nfs4_init_channel_attrs: Back Channel : max_rqst_sz=4096 max_resp_sz=4096 max_resp_sz_cached=0 max_ops=2 max_reqs=16
> [35134.024334] check_slot_seqid enter. seqid 1 slot_seqid 0
> [35134.024337] NFSD: move_to_confirm nfs4_client 0000000005ccbb59
> [35134.024462] --> nfs4_setup_session_slot_tables
> [35134.024464] --> nfs4_realloc_slot_table: max_reqs=30, tbl->max_slots 0
> [35134.024469] nfs4_realloc_slot_table: tbl=0000000054cdc1a8 slots=00000000b96721b4 max_slots=30
> [35134.024471] <-- nfs4_realloc_slot_table: return 0
> [35134.024473] --> nfs4_realloc_slot_table: max_reqs=16, tbl->max_slots 0
> [35134.024476] nfs4_realloc_slot_table: tbl=00000000a895ddf2 slots=0000000031ce2890 max_slots=16
> [35134.024478] <-- nfs4_realloc_slot_table: return 0
> [35134.024479] slot table setup returned 0
> [35134.024480] nfs4_proc_create_session client>seqid 2 sessionid 1614612109:2516949716:5:0
> [35134.024482] <-- nfs4_proc_create_session
> [35134.024483] nfs4_schedule_state_renewal: requeueing work. Lease period = 5
> [35134.024489] --> nfs41_proc_reclaim_complete
> [35134.024491] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.024492] NFS: nfs4_discover_server_trunking: status = 0
> [35134.024493] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.024497] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=1 slotid=0 max_slotid=0 cache_this=0
> [35134.024510] --> _nfs41_proc_secinfo_no_name
> [35134.024512] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.024535] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.024539] nfsd4_sequence: slotid 0
> [35134.024540] check_slot_seqid enter. seqid 1 slot_seqid 0
> [35134.024544] alloc_cld_upcall: allocated xid 5
> [35134.046004] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.046096] --> nfs4_reclaim_complete_done
> [35134.046104] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.046109] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.046112] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.046115] nfs41_sequence_process: Error 0 free the slot
> [35134.046117] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.046120] <-- nfs4_reclaim_complete_done
> [35134.046127] <-- nfs41_proc_reclaim_complete status=0
> [35134.046130] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=16
> [35134.046133] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.046136] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.046138] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.046141] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.046148] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.046151] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.046153] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.046153] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.046162] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=2 slotid=0 max_slotid=0 cache_this=0
> [35134.046247] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.046251] nfsd4_sequence: slotid 0
> [35134.046253] check_slot_seqid enter. seqid 2 slot_seqid 1
> [35134.046258] nfsd: fh_compose(exp fe:01/2 /, ino=2)
> [35134.046264] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.046373] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.046378] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.046380] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.046382] nfs41_sequence_process: Error 0 free the slot
> [35134.046384] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.046389] <-- _nfs41_proc_secinfo_no_name status=0
> [35134.058969] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.058975] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.058981] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.058989] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=3 slotid=0 max_slotid=0 cache_this=0
> [35134.059137] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.059142] nfsd4_sequence: slotid 0
> [35134.059144] check_slot_seqid enter. seqid 3 slot_seqid 2
> [35134.059149] nfsd: fh_compose(exp fe:01/2 /, ino=2)
> [35134.059155] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.059162] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.059254] decode_attr_type: type=040000
> [35134.059258] decode_attr_change: change attribute=6934706255420194816
> [35134.059260] decode_attr_size: file size=4096
> [35134.059262] decode_attr_fsid: fsid=(0x0/0x0)
> [35134.059265] decode_attr_fileid: fileid=2
> [35134.059267] decode_attr_fs_locations: fs_locations done, error = 0
> [35134.059269] decode_attr_mode: file mode=0755
> [35134.059271] decode_attr_nlink: nlink=23
> [35134.059273] decode_attr_owner: uid=0
> [35134.059275] decode_attr_group: gid=0
> [35134.059276] decode_attr_rdev: rdev=(0x0:0x0)
> [35134.059278] decode_attr_space_used: space used=4096
> [35134.059279] decode_attr_time_access: atime=1614577167
> [35134.059281] decode_attr_time_metadata: ctime=1606120833
> [35134.059284] decode_attr_time_modify: mtime=1606120833
> [35134.059285] decode_attr_mounted_on_fileid: fileid=1
> [35134.059287] decode_getfattr_attrs: xdr returned 0
> [35134.059289] decode_getfattr_generic: xdr returned 0
> [35134.059293] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.059296] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.059299] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.059300] nfs41_sequence_process: Error 0 free the slot
> [35134.059303] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.059311] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.059314] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.059317] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.059322] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=4 slotid=0 max_slotid=0 cache_this=0
> [35134.059439] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.059444] nfsd4_sequence: slotid 0
> [35134.059445] check_slot_seqid enter. seqid 4 slot_seqid 3
> [35134.059450] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.059455] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.059459] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.059620] decode_attr_supported: bitmask=fdffbfff:40f9be3e:00000803
> [35134.059643] decode_attr_fh_expire_type: expire type=0x0
> [35134.059645] decode_attr_link_support: link support=true
> [35134.059646] decode_attr_symlink_support: symlink support=true
> [35134.059648] decode_attr_aclsupport: ACLs supported=3
> [35134.059649] decode_attr_exclcreat_supported: bitmask=00001010:00000032:00000000
> [35134.059651] decode_server_caps: xdr returned 0!
> [35134.059654] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.059657] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.059659] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.059660] nfs41_sequence_process: Error 0 free the slot
> [35134.059662] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.059668] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.059671] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.059672] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.059677] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=5 slotid=0 max_slotid=0 cache_this=0
> [35134.059800] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.059804] nfsd4_sequence: slotid 0
> [35134.059806] check_slot_seqid enter. seqid 5 slot_seqid 4
> [35134.059810] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.059816] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.059820] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.059932] decode_attr_lease_time: lease time=90
> [35134.059936] decode_attr_maxfilesize: maxfilesize=17592186040320
> [35134.059938] decode_attr_maxread: maxread=1048576
> [35134.059939] decode_attr_maxwrite: maxwrite=1048576
> [35134.059941] decode_attr_time_delta: time_delta=0 4000000
> [35134.059942] decode_attr_pnfstype: bitmap is 40000000
> [35134.059944] decode_attr_layout_blksize: bitmap is 2
> [35134.059945] decode_attr_clone_blksize: bitmap is 0
> [35134.059946] decode_attr_xattrsupport: XATTR support=false
> [35134.059947] decode_fsinfo: xdr returned 0!
> [35134.059950] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.059952] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.059954] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.059955] nfs41_sequence_process: Error 0 free the slot
> [35134.059957] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.059964] Server FSID: 0:0
> [35134.059967] Pseudo-fs root FH at 0000000032a8b38c is 8 bytes, crc: 0x62d40c52:
> [35134.059970] 01000100 00000000
> [35134.059973] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.059975] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.059977] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.059981] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=6 slotid=0 max_slotid=0 cache_this=0
> [35134.060025] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.060028] nfsd4_sequence: slotid 0
> [35134.060029] check_slot_seqid enter. seqid 6 slot_seqid 5
> [35134.060032] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060036] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060039] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.060146] decode_attr_supported: bitmask=fdffbfff:40f9be3e:00000803
> [35134.060151] decode_attr_fh_expire_type: expire type=0x0
> [35134.060152] decode_attr_link_support: link support=true
> [35134.060154] decode_attr_symlink_support: symlink support=true
> [35134.060155] decode_attr_aclsupport: ACLs supported=3
> [35134.060156] decode_attr_exclcreat_supported: bitmask=00001010:00000032:00000000
> [35134.060158] decode_server_caps: xdr returned 0!
> [35134.060161] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.060163] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.060165] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.060167] nfs41_sequence_process: Error 0 free the slot
> [35134.060168] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.060175] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.060177] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.060179] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.060183] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=7 slotid=0 max_slotid=0 cache_this=0
> [35134.060267] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.060272] nfsd4_sequence: slotid 0
> [35134.060274] check_slot_seqid enter. seqid 7 slot_seqid 6
> [35134.060278] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060284] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060288] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.060449] decode_attr_lease_time: lease time=90
> [35134.060468] decode_attr_maxfilesize: maxfilesize=17592186040320
> [35134.060470] decode_attr_maxread: maxread=1048576
> [35134.060471] decode_attr_maxwrite: maxwrite=1048576
> [35134.060472] decode_attr_time_delta: time_delta=0 4000000
> [35134.060474] decode_attr_pnfstype: bitmap is 40000000
> [35134.060476] decode_attr_layout_blksize: bitmap is 2
> [35134.060477] decode_attr_clone_blksize: bitmap is 0
> [35134.060478] decode_attr_xattrsupport: XATTR support=false
> [35134.060479] decode_fsinfo: xdr returned 0!
> [35134.060481] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.060483] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.060485] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.060487] nfs41_sequence_process: Error 0 free the slot
> [35134.060488] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.060494] set_pnfs_layoutdriver: Using NFSv4 I/O
> [35134.060497] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.060499] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.060501] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.060505] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=8 slotid=0 max_slotid=0 cache_this=0
> [35134.060604] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.060608] nfsd4_sequence: slotid 0
> [35134.060609] check_slot_seqid enter. seqid 8 slot_seqid 7
> [35134.060613] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060617] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060621] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.060727] decode_attr_maxlink: maxlink=255
> [35134.060730] decode_attr_maxname: maxname=255
> [35134.060731] decode_pathconf: xdr returned 0!
> [35134.060734] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.060736] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.060739] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.060740] nfs41_sequence_process: Error 0 free the slot
> [35134.060741] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.060752] NFS: parsing nfs mount option 'source'
> [35134.060755] NFS: MNTPATH: '/'
> [35134.060851] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.060855] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.060858] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.060864] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=9 slotid=0 max_slotid=0 cache_this=0
> [35134.060914] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.060918] nfsd4_sequence: slotid 0
> [35134.060919] check_slot_seqid enter. seqid 9 slot_seqid 8
> [35134.060922] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060927] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.060929] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.060980] decode_attr_supported: bitmask=fdffbfff:40f9be3e:00000803
> [35134.060985] decode_attr_fh_expire_type: expire type=0x0
> [35134.060986] decode_attr_link_support: link support=true
> [35134.060989] decode_attr_symlink_support: symlink support=true
> [35134.060990] decode_attr_aclsupport: ACLs supported=3
> [35134.060992] decode_attr_exclcreat_supported: bitmask=00001010:00000032:00000000
> [35134.060995] decode_server_caps: xdr returned 0!
> [35134.060998] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.061001] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.061003] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.061005] nfs41_sequence_process: Error 0 free the slot
> [35134.061007] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.061015] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.061017] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.061020] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.061027] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=10 slotid=0 max_slotid=0 cache_this=0
> [35134.061116] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.061122] nfsd4_sequence: slotid 0
> [35134.061124] check_slot_seqid enter. seqid 10 slot_seqid 9
> [35134.061128] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.061134] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.061140] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.061220] decode_attr_type: type=040000
> [35134.061223] decode_attr_change: change attribute=6934706255420194816
> [35134.061225] decode_attr_size: file size=4096
> [35134.061227] decode_attr_fsid: fsid=(0x0/0x0)
> [35134.061229] decode_attr_fileid: fileid=2
> [35134.061231] decode_attr_fs_locations: fs_locations done, error = 0
> [35134.061233] decode_attr_mode: file mode=0755
> [35134.061235] decode_attr_nlink: nlink=23
> [35134.061237] decode_attr_owner: uid=0
> [35134.061239] decode_attr_group: gid=0
> [35134.061241] decode_attr_rdev: rdev=(0x0:0x0)
> [35134.061243] decode_attr_space_used: space used=4096
> [35134.061245] decode_attr_time_access: atime=1614577167
> [35134.061247] decode_attr_time_metadata: ctime=1606120833
> [35134.061249] decode_attr_time_modify: mtime=1606120833
> [35134.061250] decode_attr_mounted_on_fileid: fileid=1
> [35134.061252] decode_getfattr_attrs: xdr returned 0
> [35134.061254] decode_getfattr_generic: xdr returned 0
> [35134.061256] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.061259] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.061261] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.061264] nfs41_sequence_process: Error 0 free the slot
> [35134.061266] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.061275] NFS: nfs_fhget(0:82/2 fh_crc=0x62d40c52 ct=1)
> [35134.061294] NFS: permission(0:82/2), mask=0x81, res=-10
> [35134.061300] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.061303] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.061305] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.061310] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=11 slotid=0 max_slotid=0 cache_this=0
> [35134.061396] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.061402] nfsd4_sequence: slotid 0
> [35134.061404] check_slot_seqid enter. seqid 11 slot_seqid 10
> [35134.061408] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.061414] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.061418] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.061421] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.061503] decode_attr_type: type=00
> [35134.061505] decode_attr_change: change attribute=6934706255420194816
> [35134.061507] decode_attr_size: file size=4096
> [35134.061508] decode_attr_fsid: fsid=(0x0/0x0)
> [35134.061510] decode_attr_fileid: fileid=0
> [35134.061512] decode_attr_fs_locations: fs_locations done, error = 0
> [35134.061514] decode_attr_mode: file mode=00
> [35134.061515] decode_attr_nlink: nlink=1
> [35134.061517] decode_attr_rdev: rdev=(0x0:0x0)
> [35134.061519] decode_attr_space_used: space used=0
> [35134.061521] decode_attr_time_access: atime=0
> [35134.061523] decode_attr_time_metadata: ctime=1606120833
> [35134.061525] decode_attr_time_modify: mtime=1606120833
> [35134.061526] decode_attr_mounted_on_fileid: fileid=0
> [35134.061527] decode_getfattr_attrs: xdr returned 0
> [35134.061529] decode_getfattr_generic: xdr returned 0
> [35134.061532] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.061535] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.061537] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.061538] nfs41_sequence_process: Error 0 free the slot
> [35134.061540] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.061546] NFS: nfs_update_inode(0:82/2 fh_crc=0x62d40c52 ct=2 info=0x26040)
> [35134.061553] NFS: permission(0:82/2), mask=0x1, res=0
> [35134.061559] NFS: lookup(/tmp)
> [35134.061562] NFS call lookup /tmp
> [35134.061564] --> nfs41_call_sync_prepare data->seq_server 00000000faf52af4
> [35134.061567] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
> [35134.061569] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
> [35134.061575] encode_sequence: sessionid=1614612109:2516949716:5:0 seqid=12 slotid=0 max_slotid=0 cache_this=0
> [35134.061642] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.061646] nfsd4_sequence: slotid 0
> [35134.061648] check_slot_seqid enter. seqid 12 slot_seqid 11
> [35134.061651] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.061655] nfsd: fh_verify(8: 00010001 00000000 00000000 00000000 00000000 00000000)
> [35134.061658] nfsd: nfsd_lookup(fh 8: 00010001 00000000 00000000 00000000 00000000 00000000, tmp)
> [35134.061663] --> nfsd4_store_cache_entry slot 000000008e086c0f
> [35134.061691] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
> [35134.061694] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
> [35134.061695] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [35134.061696] nfs41_sequence_process: Error 0 free the slot
> [35134.061698] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [35134.061701] NFS reply lookup: -2
> [35134.061704] NFS: dentry_delete(/tmp, 80c)
> [35134.061730] NFS4: Couldn't follow remote path
> [35134.061731] <-- nfs4_try_get_tree() = -2 [error]
> [35134.061745] NFS: clear cookie (0x0000000002f41426/0x0000000000000000)
> [35134.061948] NFS: releasing superblock cookie (0x00000000faf52af4/0x0000000000000000)
> [35134.101941] --> nfs4_proc_destroy_session
> [35134.102103] nfsd4_destroy_session: 1614612109:2516949716:5:0
> [35134.102111] __find_in_sessionid_hashtbl: 1614612109:2516949716:5:0
> [35134.102427] <-- nfs4_proc_destroy_session
> [35134.102432] nfs4_destroy_session Destroy backchannel for xprt 00000000733269a8
> [35134.102604] alloc_cld_upcall: allocated xid 6
> [35134.125122] NFS: destroy per-net callback data; net=f0000358
> [35134.125256] nfs_callback_down: service destroyed
> [35134.125267] NFS: releasing client cookie (0x000000003f4944e9/0x00000000c67386ff)
>
^ permalink raw reply [flat|nested] 3+ messages in thread
* [LTP] NFS tests failure: RPC: Couldn't create auth handle (flavor 390004)
2021-03-02 11:35 ` Alexey Kodanev
@ 2021-03-04 17:02 ` Petr Vorel
0 siblings, 0 replies; 3+ messages in thread
From: Petr Vorel @ 2021-03-04 17:02 UTC (permalink / raw)
To: ltp
> > I'm looking to some NFS failures on recent openSUSE kernel 5.11.
> > "RPC: Couldn't create auth handle (flavor 390004)" error has something to
> > do with krb5i, but module rpcsec_gss_krb5 is loaded.
Hi Alexey,
> Hi Petr,
> Do other security flavours work well, or without them using "none" opt?
> Also 'sys' is not default in your setup? If it doesn't work just for
> krb5 it might be some misconfiguration with kerberos setup there...
thanks for a tip. No, define sec=... in /etc/nfsmount.conf does not help.
* Adding sec=sys into /etc/nfsmount.conf leads to (or keeping the default):
nfs01 1 TINFO: Mounting NFS: mount -t nfs -o proto=tcp,vers=4.1 10.0.0.2:/tmp/LTP_nfs01.nM6Epvvg20/4.1/tcp /tmp/LTP_nfs01.nM6Epvvg20/4.1/0
mount.nfs: mounting 10.0.0.2:/tmp/LTP_nfs01.nM6Epvvg20/4.1/tcp failed, reason given by server: No such file or directory
nfs01 1 TBROK: mount command failed
* sec=none
nfs01 1 TINFO: setup NFSv4.1, socket type tcp
nfs01 1 TINFO: Mounting NFS: mount -t nfs -o proto=tcp,vers=4.1 10.0.0.2:/tmp/LTP_nfs01.pCXxr8Cr0I/4.1/tcp /tmp/LTP_nfs01.pCXxr8Cr0I/4.1/0
mount.nfs: Operation not permitted
* sec=krb5 or sec=krb5i or sec=krb5p
nfs01 1 TINFO: setup NFSv4.1, socket type tcp
nfs01 1 TINFO: Mounting NFS: mount -t nfs -o proto=tcp,vers=4.1 10.0.0.2:/tmp/LTP_nfs01.9oZybEIlye/4.1/tcp /tmp/LTP_nfs01.9oZybEIlye/4.1/0
mount.nfs: an incorrect mount option was specified
I have to dig more into the docs.
BTW what services are required to be running for NFS tests?
I have running: proc-fs-nfsd.mount, var-lib-nfs-rpc_pipefs.mount, nfs-idmapd.service, nfs-mountd.service, nfs-server.service, nfsdcld.servicenfs-client.target.
Kind regards,
Petr
> > Any idea what could cause "nfs41_sequence_process: Error 0 free the slot"
> > and "NFS reply lookup: -2"?
> > Kind regards,
> > Petr
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2021-03-04 17:02 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2021-03-01 15:51 [LTP] NFS tests failure: RPC: Couldn't create auth handle (flavor 390004) Petr Vorel
2021-03-02 11:35 ` Alexey Kodanev
2021-03-04 17:02 ` Petr Vorel
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.