https://bugzilla.novell.com/show_bug.cgi?id=644880
https://bugzilla.novell.com/show_bug.cgi?id=644880#c7
--- Comment #7 from Joschi Brauchle 2010-10-28 12:41:17 UTC ---
Today I finally experienced the bug again.
Once "rpciod/1" (in this case it was /1, not /0) was running at a constant 20%
CPU, I increased the NFS and RPC debug levels by:
- echo 32767 > /proc/sys/sunrpc/rpc_debug
- echo 32767 > /proc/sys/sunrpc/nfs_debug
I also attached the output of "echo t > /proc/sysrq-trigger" in the second
attachment.
The output is attached on the first file above.
It shows that the process is stuck in some kind of loop:
-------------------------
- The NFS debug log shows:
-------------------------
Oct 28 11:05:59 st-brauchle kernel: [ 2485.031996] --> nfs_put_client({2})
Oct 28 11:05:59 st-brauchle kernel: [ 2485.034878] NFS: 21736
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.034946] NFS: 48904
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.034957] NFS: 33450
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.034962] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.034968] NFS: 21737
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035203] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035231] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035298] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035320] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035342] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035364] --> nfs_put_client({2})
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035747] NFS: 21736
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035875] NFS: 48904
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035887] NFS: 33450
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035889] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.035900] NFS: 21737
nfs_writeback_done (status -10023)
Oct 28 11:05:59 st-brauchle kernel: [ 2485.036140] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.036168] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.036236] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.036257] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.036302] encode_compound: tag=
Oct 28 11:05:59 st-brauchle kernel: [ 2485.036344] --> nfs_put_client({2})
...
-------------------------
The RPC+NFS debug log shows:
-------------------------
Oct 28 11:07:25 st-brauchle kernel: [ 2570.610866] --> nfs_put_client({2})
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611075] RPC:
xs_tcp_data_ready...
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611077] RPC: xs_tcp_data_recv
started
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611079] RPC: reading TCP
record fragment of length 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611080] RPC: reading XID (4
bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611082] RPC: reading reply for
XID 09576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611084] RPC: reading
CALL/REPLY flag (4 bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611085] RPC: read reply XID
09576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611087] RPC: XID 09576cce read
84 bytes
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611089] RPC: xprt =
ffff88007cd0b6f8, tcp_copied = 92, tcp_offset = 92, tcp_reclen = 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611092] RPC: 21736 xid 09576cce
complete (92 bytes received)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611093] RPC: 21736
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611095] RPC: 21736 disabling timer
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611097] RPC: 21736 removed from
queue ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611100] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611101] RPC: xs_tcp_data_recv
done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611107] RPC:
xs_tcp_data_ready...
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611108] RPC: xs_tcp_data_recv
started
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611110] RPC: reading TCP
record fragment of length 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611111] RPC: reading XID (4
bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611113] RPC: reading reply for
XID 0a576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611114] RPC: reading
CALL/REPLY flag (4 bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611116] RPC: read reply XID
0a576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611118] RPC: XID 0a576cce read
84 bytes
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611120] RPC: xprt =
ffff88007cd0b6f8, tcp_copied = 92, tcp_offset = 92, tcp_reclen = 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611122] RPC: 48904 xid 0a576cce
complete (92 bytes received)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611124] RPC: 48904
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611125] RPC: 48904 disabling timer
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611127] RPC: 48904 removed from
queue ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611128] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611130] RPC: xs_tcp_data_recv
done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611139] RPC:
xs_tcp_data_ready...
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611140] RPC: xs_tcp_data_recv
started
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611142] RPC: reading TCP
record fragment of length 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611143] RPC: reading XID (4
bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611145] RPC: reading reply for
XID 0b576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611146] RPC: reading
CALL/REPLY flag (4 bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611148] RPC: read reply XID
0b576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611149] RPC: XID 0b576cce read
84 bytes
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611151] RPC: xprt =
ffff88007cd0b6f8, tcp_copied = 92, tcp_offset = 92, tcp_reclen = 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611153] RPC: 33450 xid 0b576cce
complete (92 bytes received)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611155] RPC: 33450
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611157] RPC: 33450 disabling timer
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611158] RPC: 33450 removed from
queue ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611160] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611161] RPC: xs_tcp_data_recv
done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611178] RPC: 21736 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611180] RPC: 21736 call_status
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611182] RPC: 21736 call_decode
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611184] RPC: 21736 validating
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611186] RPC: 21736 gss_validate
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611187] RPC: krb5_read_token
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611198] RPC:
xs_tcp_data_ready...
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611200] RPC: xs_tcp_data_recv
started
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611201] RPC: reading TCP
record fragment of length 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611202] RPC: reading XID (4
bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611204] RPC: reading reply for
XID 0c576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611206] RPC: reading
CALL/REPLY flag (4 bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611207] RPC: read reply XID
0c576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611209] RPC: XID 0c576cce read
84 bytes
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611211] RPC: xprt =
ffff88007cd0b6f8, tcp_copied = 92, tcp_offset = 92, tcp_reclen = 92
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611213] RPC: 21737 xid 0c576cce
complete (92 bytes received)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611215] RPC: 21737
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611216] RPC: 21737 disabling timer
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611218] RPC: 21737 removed from
queue ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611220] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611221] RPC: xs_tcp_data_recv
done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611227] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611228] RPC: krb5_get_seq_num:
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611230] RPC: gss_k5decrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611232] RPC: 21736 gss_validate:
gss_verify_mic succeeded.
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611234] RPC: 21736 using AUTH_GSS
cred ffff88007e05dee0 to unwrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611236] RPC: 21736 gss_unwrap_resp
returning -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611238] RPC: 21736 call_decode
result -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611239] NFS: 21736
nfs_writeback_done (status -10023)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611241] RPC: 21736 sleep_on(queue
"NFS client" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611243] RPC: 21736 added to queue
ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611277] RPC: freeing buffer of
size 3756 at ffff88005ac01000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611280] RPC: new task
initialized, procpid 5232
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611281] RPC: 21736 release request
ffff88007e02c150
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611283] RPC:
wake_up_next(ffff88007cd0bb20 "xprt_backlog")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611285] RPC: allocated task
ffff88004b367d10
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611287] RPC: 48904 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611289] RPC: 18624 __rpc_execute
flags=0x280
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611291] RPC: 48904 call_status
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611293] RPC: 18624 call_start nfs4
proc RENEW (sync)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611294] RPC: 48904 call_decode
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611296] RPC: 48904 validating
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611299] RPC: 18624 call_reserve
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611301] RPC: 18624 reserved req
ffff88007e02c150 xid 0d576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611302] RPC: 48904 gss_validate
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611303] RPC: krb5_read_token
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611306] RPC: 18624
call_reserveresult (status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611307] RPC: 18624 call_allocate
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611310] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611312] RPC: krb5_get_seq_num:
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611313] RPC: gss_k5decrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611315] RPC: 18624 allocated buffer
of size 3168 at ffff88005a1a1000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611317] RPC: 18624 call_bind (status
0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611319] RPC: 18624 call_connect xprt
ffff88007cd0b6f8 is connected
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611320] RPC: 18624 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611322] RPC: 18624
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611323] RPC: 18624 rpc_xdr_encode
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611325] RPC: 18624 marshaling
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611326] RPC: 18624 gss_marshal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611327] RPC: gss_krb5_seal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611328] RPC: 48904 gss_validate:
gss_verify_mic succeeded.
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611331] RPC: 48904 using AUTH_GSS
cred ffff88007e05dee0 to unwrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611333] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611334] RPC: 48904 gss_unwrap_resp
returning -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611336] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611337] RPC: 48904 call_decode
result -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611340] RPC: 18624 using AUTH_GSS
cred ffff88007e05dee0 to wrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611342] RPC: 18624 gss_wrap_req
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611343] NFS: 48904
nfs_writeback_done (status -10023)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611345] encode_compound: tag=
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611346] RPC: 18624 gss_wrap_req
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611348] RPC: 18624
xprt_transmit(132)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611349] RPC: 48904 sleep_on(queue
"NFS client" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611351] RPC: 48904 added to queue
ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611353] RPC: freeing buffer of
size 3756 at ffff88005e3ed000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611356] RPC:
xs_tcp_send_request(132) = 132
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611357] RPC: 48904 release request
ffff88007e02d110
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611359] RPC: 18624 xmit complete
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611361] RPC: 18624 sleep_on(queue
"xprt_pending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611363] RPC: 18624 added to queue
ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611365] RPC: 18624 setting alarm for
60000 ms
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611366] RPC:
wake_up_next(ffff88007cd0bb20 "xprt_backlog")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611369] RPC:
wake_up_next(ffff88007cd0b970 "xprt_resend")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611370] RPC: 33450 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611371] RPC: 33450 call_status
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611373] RPC: 33450 call_decode
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611374] RPC: 33450 validating
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611376] RPC: 33450 gss_validate
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611377] RPC: krb5_read_token
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611379] RPC:
wake_up_next(ffff88007cd0b898 "xprt_sending")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611381] RPC: 18624 sync task going
to sleep
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611382] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611384] RPC: krb5_get_seq_num:
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611385] RPC: gss_k5decrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611386] RPC: 33450 gss_validate:
gss_verify_mic succeeded.
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611389] RPC: 33450 using AUTH_GSS
cred ffff88007e05dee0 to unwrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611390] RPC: 33450 gss_unwrap_resp
returning -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611392] RPC: 33450 call_decode
result -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611394] NFS: 33450
nfs_writeback_done (status -10023)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611395] RPC: 33450 sleep_on(queue
"NFS client" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611397] RPC: 33450 added to queue
ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611399] RPC: freeing buffer of
size 3756 at ffff880066a4b000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611401] RPC: 33450 release request
ffff88007e02c000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611403] RPC:
wake_up_next(ffff88007cd0bb20 "xprt_backlog")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611405] RPC: 21737 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611407] RPC: 21737 call_status
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611408] RPC: 21737 call_decode
(status 92)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611410] RPC: 21737 validating
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611411] RPC: 21737 gss_validate
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611413] RPC: krb5_read_token
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611417] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611418] RPC: krb5_get_seq_num:
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611420] RPC: gss_k5decrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611421] RPC: 21737 gss_validate:
gss_verify_mic succeeded.
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611423] RPC: 21737 using AUTH_GSS
cred ffff88007e05dee0 to unwrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611425] RPC: 21737 gss_unwrap_resp
returning -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611427] RPC: 21737 call_decode
result -10023
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611428] NFS: 21737
nfs_writeback_done (status -10023)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611430] RPC: 21737 sleep_on(queue
"NFS client" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611432] RPC: 21737 added to queue
ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611434] RPC: freeing buffer of
size 3756 at ffff880047431000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611436] RPC: 21737 release request
ffff88007e02d3b0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611437] RPC:
wake_up_next(ffff88007cd0bb20 "xprt_backlog")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611475] RPC:
xs_tcp_data_ready...
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611477] RPC: xs_tcp_data_recv
started
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611478] RPC: reading TCP
record fragment of length 84
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611480] RPC: reading XID (4
bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611481] RPC: reading reply for
XID 0d576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611483] RPC: reading
CALL/REPLY flag (4 bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611485] RPC: read reply XID
0d576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611487] RPC: XID 0d576cce read
76 bytes
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611489] RPC: xprt =
ffff88007cd0b6f8, tcp_copied = 84, tcp_offset = 84, tcp_reclen = 84
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611491] RPC: 18624 xid 0d576cce
complete (84 bytes received)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611493] RPC: 18624
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611494] RPC: 18624 disabling timer
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611496] RPC: 18624 removed from
queue ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611500] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611502] RPC: 18624 sync task
resuming
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611503] RPC: xs_tcp_data_recv
done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611505] RPC: 18624 call_status
(status 84)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611507] RPC: 18624 call_decode
(status 84)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611509] RPC: 18624 validating
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611511] RPC: 18624 gss_validate
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611512] RPC: krb5_read_token
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611517] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611518] RPC: krb5_get_seq_num:
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611520] RPC: gss_k5decrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611521] RPC: 18624 gss_validate:
gss_verify_mic succeeded.
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611523] RPC: 18624 using AUTH_GSS
cred ffff88007e05dee0 to unwrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611524] RPC: 18624 gss_unwrap_resp
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611526] RPC: 18624 call_decode
result 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611527] RPC: 18624 return 0, status
0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611528] RPC: 18624 release task
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611530] RPC: freeing buffer of
size 3168 at ffff88005a1a1000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611532] RPC: 18624 release request
ffff88007e02c150
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611534] RPC:
wake_up_next(ffff88007cd0bb20 "xprt_backlog")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611536] RPC: 18624 releasing
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611537] RPC:
rpc_release_client(ffff88007e53f720)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611539] RPC: 18624 freeing task
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611545] RPC: new task
initialized, procpid 5232
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611546] RPC: allocated task
ffff88004b367d10
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611548] RPC: 18625 __rpc_execute
flags=0x81
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611550] RPC: 18625 return 0, status
0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611551] RPC: 18625 release task
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611553] RPC: 18625 releasing
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611554] RPC:
rpc_release_client(ffff88007e53fd68)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611560] RPC: 21736
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611562] RPC: 21736 removed from
queue ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611564] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611566] RPC: 48904
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611568] RPC: 48904 removed from
queue ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611569] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611571] RPC: 33450
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611573] RPC: 33450 removed from
queue ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611574] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611576] RPC: 21737
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611577] RPC: 21737 removed from
queue ffff88007cf76868 "NFS client"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611579] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611582] RPC: new task
initialized, procpid 5232
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611583] RPC: allocated task
ffff88004b367650
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611585] RPC: 18626 __rpc_execute
flags=0x280
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611586] RPC: 18626 call_start nfs4
proc RENEW (sync)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611588] RPC: 18626 call_reserve
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611590] RPC: 18626 reserved req
ffff88007e02c150 xid 0e576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611591] RPC: 18626
call_reserveresult (status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611593] RPC: 18626 call_allocate
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611601] RPC: 18626 allocated buffer
of size 3168 at ffff88005a1a1000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611603] RPC: 18626 call_bind (status
0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611604] RPC: 18626 call_connect xprt
ffff88007cd0b6f8 is connected
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611606] RPC: 18626 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611607] RPC: 18626
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611609] RPC: 18626 rpc_xdr_encode
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611611] RPC: 18626 marshaling
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611612] RPC: 18626 gss_marshal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611614] RPC: gss_krb5_seal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611618] RPC: 18625 freeing task
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611621] RPC: 21736 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611623] RPC: 21736 call_start nfs4
proc WRITE (async)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611625] RPC: 21736 call_reserve
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611627] RPC: 21736 reserved req
ffff88007e02d3b0 xid 0f576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611628] RPC: 21736
call_reserveresult (status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611630] RPC: 21736 call_allocate
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611638] RPC: 21736 allocated buffer
of size 3756 at ffff8800479ff000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611640] RPC: 21736 call_bind (status
0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611641] RPC: 21736 call_connect xprt
ffff88007cd0b6f8 is connected
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611643] RPC: 21736 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611644] RPC: 21736
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611645] RPC: 21736 failed to lock
transport ffff88007cd0b6f8
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611647] RPC: 21736 sleep_on(queue
"xprt_sending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611649] RPC: 21736 added to queue
ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611651] RPC: 48904 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611652] RPC: 48904 call_start nfs4
proc WRITE (async)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611653] RPC: 48904 call_reserve
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611655] RPC: 48904 reserved req
ffff88007e02c000 xid 10576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611657] RPC: 48904
call_reserveresult (status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611658] RPC: 48904 call_allocate
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611666] RPC: 48904 allocated buffer
of size 3756 at ffff880047575000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611668] RPC: 48904 call_bind (status
0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611669] RPC: 48904 call_connect xprt
ffff88007cd0b6f8 is connected
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611671] RPC: 48904 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611672] RPC: 48904
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611674] RPC: 48904 failed to lock
transport ffff88007cd0b6f8
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611676] RPC: 48904 sleep_on(queue
"xprt_sending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611678] RPC: 48904 added to queue
ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611680] RPC: 33450 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611682] RPC: 33450 call_start nfs4
proc WRITE (async)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611683] RPC: 33450 call_reserve
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611685] RPC: 33450 reserved req
ffff88007e02d110 xid 11576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611687] RPC: 33450
call_reserveresult (status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611688] RPC: 33450 call_allocate
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611696] RPC: 33450 allocated buffer
of size 3756 at ffff88005e3a0000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611698] RPC: 33450 call_bind (status
0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611700] RPC: 33450 call_connect xprt
ffff88007cd0b6f8 is connected
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611701] RPC: 33450 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611703] RPC: 33450
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611704] RPC: 33450 failed to lock
transport ffff88007cd0b6f8
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611706] RPC: 33450 sleep_on(queue
"xprt_sending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611707] RPC: 33450 added to queue
ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611709] RPC: 21737 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611711] RPC: 21737 call_start nfs4
proc WRITE (async)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611712] RPC: 21737 call_reserve
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611714] RPC: 21737 reserved req
ffff88007e02c7e0 xid 12576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611715] RPC: 21737
call_reserveresult (status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611717] RPC: 21737 call_allocate
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611725] RPC: 21737 allocated buffer
of size 3756 at ffff880047745000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611726] RPC: 21737 call_bind (status
0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611728] RPC: 21737 call_connect xprt
ffff88007cd0b6f8 is connected
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611730] RPC: 21737 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611731] RPC: 21737
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611733] RPC: 21737 failed to lock
transport ffff88007cd0b6f8
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611735] RPC: 21737 sleep_on(queue
"xprt_sending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611737] RPC: 21737 added to queue
ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611741] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611744] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611746] RPC: 18626 using AUTH_GSS
cred ffff88007e05dee0 to wrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611748] RPC: 18626 gss_wrap_req
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611749] encode_compound: tag=
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611750] RPC: 18626 gss_wrap_req
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611752] RPC: 18626
xprt_transmit(132)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611759] RPC:
xs_tcp_send_request(132) = 132
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611761] RPC: 18626 xmit complete
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611763] RPC: 18626 sleep_on(queue
"xprt_pending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611765] RPC: 18626 added to queue
ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611766] RPC: 18626 setting alarm for
60000 ms
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611768] RPC:
wake_up_next(ffff88007cd0b970 "xprt_resend")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611769] RPC:
wake_up_next(ffff88007cd0b898 "xprt_sending")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611771] RPC: 21736
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611772] RPC: 21736 removed from
queue ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611775] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611776] RPC: 18626 sync task going
to sleep
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611779] RPC: 21736 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611781] RPC: 21736 call_status
(status -11)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611782] RPC: 21736 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611784] RPC: 21736
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611786] RPC: 21736 rpc_xdr_encode
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611787] RPC: 21736 marshaling
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611789] RPC: 21736 gss_marshal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611790] RPC: gss_krb5_seal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611795] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611798] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611800] RPC: 21736 using AUTH_GSS
cred ffff88007e05dee0 to wrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611801] RPC: 21736 gss_wrap_req
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611803] encode_compound: tag=
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611804] RPC: 21736 gss_wrap_req
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611806] RPC: 21736
xprt_transmit(32964)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611844] RPC:
xs_tcp_send_request(32964) = 32964
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611845] RPC: 21736 xmit complete
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611847] RPC: 21736 sleep_on(queue
"xprt_pending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611849] RPC: 21736 added to queue
ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611851] RPC: 21736 setting alarm for
60000 ms
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611853] RPC:
wake_up_next(ffff88007cd0b970 "xprt_resend")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611854] RPC:
wake_up_next(ffff88007cd0b898 "xprt_sending")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611856] RPC: 48904
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611858] RPC: 48904 removed from
queue ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611860] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611861] RPC: 48904 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611863] RPC: 48904 call_status
(status -11)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611865] RPC: 48904 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611866] RPC: 48904
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611868] RPC: 48904 rpc_xdr_encode
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611870] RPC: 48904 marshaling
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611871] RPC: 48904 gss_marshal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611872] RPC: gss_krb5_seal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611878] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611880] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611880] RPC:
xs_tcp_data_ready...
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611882] RPC: xs_tcp_data_recv
started
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611883] RPC: reading TCP
record fragment of length 84
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611885] RPC: reading XID (4
bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611886] RPC: reading reply for
XID 0e576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611888] RPC: reading
CALL/REPLY flag (4 bytes)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611889] RPC: read reply XID
0e576cce
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611891] RPC: XID 0e576cce read
76 bytes
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611894] RPC: 48904 using AUTH_GSS
cred ffff88007e05dee0 to wrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611896] RPC: xprt =
ffff88007cd0b6f8, tcp_copied = 84, tcp_offset = 84, tcp_reclen = 84
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611898] RPC: 18626 xid 0e576cce
complete (84 bytes received)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611900] RPC: 18626
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611901] RPC: 18626 disabling timer
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611903] RPC: 18626 removed from
queue ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611906] RPC: 48904 gss_wrap_req
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611906] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611908] encode_compound: tag=
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611909] RPC: xs_tcp_data_recv
done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611911] RPC: 48904 gss_wrap_req
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611913] RPC: 48904
xprt_transmit(764)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611922] RPC:
xs_tcp_send_request(764) = 764
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611923] RPC: 48904 xmit complete
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611925] RPC: 48904 sleep_on(queue
"xprt_pending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611927] RPC: 48904 added to queue
ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611928] RPC: 48904 setting alarm for
60000 ms
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611930] RPC:
wake_up_next(ffff88007cd0b970 "xprt_resend")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611931] RPC:
wake_up_next(ffff88007cd0b898 "xprt_sending")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611933] RPC: 33450
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611935] RPC: 33450 removed from
queue ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611936] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611938] RPC: 33450 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611939] RPC: 33450 call_status
(status -11)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611941] RPC: 33450 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611942] RPC: 33450
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611944] RPC: 33450 rpc_xdr_encode
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611945] RPC: 33450 marshaling
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611947] RPC: 33450 gss_marshal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611948] RPC: gss_krb5_seal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611953] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611955] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611957] RPC: 33450 using AUTH_GSS
cred ffff88007e05dee0 to wrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611959] RPC: 33450 gss_wrap_req
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611960] encode_compound: tag=
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611962] RPC: 33450 gss_wrap_req
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611963] RPC: 33450
xprt_transmit(708)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611971] RPC:
xs_tcp_send_request(708) = 708
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611972] RPC: 33450 xmit complete
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611974] RPC: 33450 sleep_on(queue
"xprt_pending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611976] RPC: 33450 added to queue
ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611978] RPC: 33450 setting alarm for
60000 ms
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611980] RPC:
wake_up_next(ffff88007cd0b970 "xprt_resend")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611981] RPC:
wake_up_next(ffff88007cd0b898 "xprt_sending")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611983] RPC: 21737
__rpc_wake_up_task (now 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611985] RPC: 21737 removed from
queue ffff88007cd0b898 "xprt_sending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611987] RPC:
__rpc_wake_up_task done
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611988] RPC: 21737 __rpc_execute
flags=0x1
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611990] RPC: 21737 call_status
(status -11)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611992] RPC: 21737 call_transmit
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611993] RPC: 21737
xprt_prepare_transmit
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611995] RPC: 21737 rpc_xdr_encode
(status 0)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611996] RPC: 21737 marshaling
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611998] RPC: 21737 gss_marshal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.611999] RPC: gss_krb5_seal
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612004] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612006] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612008] RPC: 21737 using AUTH_GSS
cred ffff88007e05dee0 to wrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612010] RPC: 21737 gss_wrap_req
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612011] encode_compound: tag=
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612013] RPC: 21737 gss_wrap_req
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612014] RPC: 21737
xprt_transmit(12484)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612032] RPC:
xs_tcp_send_request(12484) = 12484
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612034] RPC: 21737 xmit complete
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612036] RPC: 21737 sleep_on(queue
"xprt_pending" time 4295534948)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612038] RPC: 21737 added to queue
ffff88007cd0ba48 "xprt_pending"
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612039] RPC: 21737 setting alarm for
60000 ms
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612041] RPC:
wake_up_next(ffff88007cd0b970 "xprt_resend")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612043] RPC:
wake_up_next(ffff88007cd0b898 "xprt_sending")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612046] RPC: 18626 sync task
resuming
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612048] RPC: 18626 call_status
(status 84)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612049] RPC: 18626 call_decode
(status 84)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612051] RPC: 18626 validating
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612053] RPC: 18626 gss_validate
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612054] RPC: krb5_read_token
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612059] RPC: krb5_encrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612060] RPC: krb5_get_seq_num:
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612062] RPC: gss_k5decrypt
returns 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612063] RPC: 18626 gss_validate:
gss_verify_mic succeeded.
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612065] RPC: 18626 using AUTH_GSS
cred ffff88007e05dee0 to unwrap rpc data
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612067] RPC: 18626 gss_unwrap_resp
returning 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612068] RPC: 18626 call_decode
result 0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612070] RPC: 18626 return 0, status
0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612071] RPC: 18626 release task
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612073] RPC: freeing buffer of
size 3168 at ffff88005a1a1000
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612075] RPC: 18626 release request
ffff88007e02c150
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612076] RPC:
wake_up_next(ffff88007cd0bb20 "xprt_backlog")
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612078] RPC: 18626 releasing
RPCSEC_GSS cred ffff88007e05dee0
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612079] RPC:
rpc_release_client(ffff88007e53f720)
Oct 28 11:07:25 st-brauchle kernel: [ 2570.612080] RPC: 18626 freeing task
-------------------------
Maybe some RPC/NFS expert can figure out what's going wrong?
--
Configure bugmail: https://bugzilla.novell.com/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are on the CC list for the bug.