00010000:00010000:0.0F:1776194619.545385:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:3.0F:1776194620.568220:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00080000:1.0F:1776194621.208125:0:145598:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:1.0:1776194621.208139:0:145598:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:1.0:1776194621.208142:0:145598:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:1.0:1776194621.208144:0:145598:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:0.0:1776194621.208652:0:2226:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000da751bd1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091192448:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:0.0:1776194621.208748:0:2226:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0] 00000100:00100000:0.0:1776194621.208755:0:2226:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000181443ac pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:9c577acc-8068-4558-bc36-a4a67c56c094:2226:1862468091192512:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:0.0:1776194621.216838:0:2226:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000da751bd1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091192448:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:1.0:1776194621.217690:0:2226:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000181443ac pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:9c577acc-8068-4558-bc36-a4a67c56c094:2226:1862468091192512:192.168.204.122@tcp:400:kworker/u8:3.0 00010000:00010000:0.0:1776194621.597232:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0F:1776194622.616750:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194623.641622:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:0.0:1776194624.664617:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194625.687715:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00080000:1.0:1776194626.328607:0:145598:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:1.0:1776194626.328616:0:145598:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:1.0:1776194626.328619:0:145598:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:1.0:1776194626.328621:0:145598:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:1.0:1776194626.328665:0:2227:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000010b6c589 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:9c577acc-8068-4558-bc36-a4a67c56c094:2227:1862468091192640:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:1.0:1776194626.328788:0:2227:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [0->1] 00000100:00100000:1.0:1776194626.328795:0:2227:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000181443ac pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2227:1862468091192576:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:0.0:1776194626.338015:0:2227:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000181443ac pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2227:1862468091192576:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:0.0:1776194626.338051:0:2227:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000010b6c589 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:9c577acc-8068-4558-bc36-a4a67c56c094:2227:1862468091192640:192.168.204.122@tcp:400:kworker/u8:3.0 00010000:00010000:0.0:1776194626.712044:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194627.735675:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:0.0:1776194628.761735:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194629.783663:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194630.808725:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00080000:0.0:1776194631.448324:0:169720:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194631.448336:0:169720:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:0.0:1776194631.448339:0:169720:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194631.448342:0:169720:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:0.0:1776194631.448382:0:2226:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000073b92078 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091192704:192.168.204.122@tcp:400:kworker/u8:0.0 00000100:00100000:0.0:1776194631.448553:0:2226:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0] 00000100:00100000:0.0:1776194631.448560:0:2226:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000ca723aec pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:9c577acc-8068-4558-bc36-a4a67c56c094:2226:1862468091192768:192.168.204.122@tcp:400:kworker/u8:0.0 00000100:00100000:0.0:1776194631.453490:0:2226:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000073b92078 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091192704:192.168.204.122@tcp:400:kworker/u8:0.0 00000100:00100000:1.0:1776194631.460915:0:2226:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000ca723aec pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:9c577acc-8068-4558-bc36-a4a67c56c094:2226:1862468091192768:192.168.204.122@tcp:400:kworker/u8:0.0 00010000:00010000:1.0:1776194631.832874:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:3.0:1776194632.863459:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000400:00000080:0.0:1776194632.955653:0:184731:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648 00000001:02000400:0.0:1776194632.955661:0:184731:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: == sanity test 823: Setting create_count > OST_MAX_PRECREATE is lowered to maximum ========================================================== 15:23:50 (1776194630) 00010000:00010000:1.0:1776194633.880696:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:3.0:1776194634.903731:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194635.928593:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00080000:2.0:1776194636.568023:0:180600:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:2.0:1776194636.568032:0:180600:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:2.0:1776194636.568034:0:180600:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:2.0:1776194636.568036:0:180600:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:2.0:1776194636.568065:0:2229:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000ab5a4fd1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_01:9c577acc-8068-4558-bc36-a4a67c56c094:2229:1862468091192896:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:2.0:1776194636.568185:0:2229:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [0->1] 00000100:00100000:2.0:1776194636.568192:0:2229:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_01:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2229:1862468091192832:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:2.0:1776194636.573328:0:2229:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000ab5a4fd1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_01:9c577acc-8068-4558-bc36-a4a67c56c094:2229:1862468091192896:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:2.0:1776194636.573376:0:2229:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_01:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2229:1862468091192832:192.168.204.122@tcp:400:kworker/u8:2.0 00010000:00010000:3.0:1776194636.953814:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194637.975753:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:0.0:1776194638.999662:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000400:00000080:1.0:1776194639.807895:0:184924:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648 00000001:02000400:1.0:1776194639.807905:0:184924:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: setting create_count to 100200: 00010000:00010000:1.0:1776194640.024972:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194641.047743:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000400:00000080:3.0:1776194641.404335:0:185060:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648 00000001:02000400:3.0:1776194641.404340:0:185060:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: -result- count: 9984 with max: 20000, expecting: 9984 00000100:00080000:3.0:1776194641.692294:0:180600:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:3.0:1776194641.692301:0:180600:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:3.0:1776194641.692304:0:180600:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:3.0:1776194641.692306:0:180600:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:3.0:1776194641.692341:0:2229:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000010b816c1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_01:9c577acc-8068-4558-bc36-a4a67c56c094:2229:1862468091193024:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:2.0:1776194641.692549:0:2228:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000096bf9c94 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2228:1862468091192960:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:2.0:1776194641.717465:0:2228:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000096bf9c94 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2228:1862468091192960:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:2.0:1776194641.723119:0:2229:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000010b816c1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_01_01:9c577acc-8068-4558-bc36-a4a67c56c094:2229:1862468091193024:192.168.204.122@tcp:400:kworker/u8:2.0 00010000:00010000:0.0:1776194642.073752:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1776194643.098068:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194644.120696:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194645.145326:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194646.170157:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00080000:0.0:1776194646.811775:0:145598:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194646.811784:0:145598:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:0.0:1776194646.811786:0:145598:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194646.811789:0:145598:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:0.0:1776194646.811816:0:2227:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000078d15144 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:9c577acc-8068-4558-bc36-a4a67c56c094:2227:1862468091193152:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:0.0:1776194646.811911:0:2227:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [0->1] 00000100:00100000:0.0:1776194646.811917:0:2227:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000073b92078 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2227:1862468091193088:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:0.0:1776194646.828488:0:2227:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000078d15144 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:9c577acc-8068-4558-bc36-a4a67c56c094:2227:1862468091193152:192.168.204.122@tcp:400:kworker/u8:3.0 00000100:00100000:0.0:1776194646.831491:0:2227:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000073b92078 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2227:1862468091193088:192.168.204.122@tcp:400:kworker/u8:3.0 00010000:00010000:2.0:1776194647.194733:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194648.216842:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194649.245158:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194650.277750:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194651.293039:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000400:00000080:1.0:1776194651.727031:0:185642:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648 00000001:02000400:1.0:1776194651.727038:0:185642:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: == sanity test 831: throttling unlink/setattr queuing on OSP ========================================================== 15:24:09 (1776194649) 00000100:00080000:0.0:1776194651.928746:0:180600:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194651.928752:0:180600:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:0.0:1776194651.928754:0:180600:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194651.928756:0:180600:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:0.0:1776194651.928781:0:2227:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000078d15144 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:9c577acc-8068-4558-bc36-a4a67c56c094:2227:1862468091193280:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:1.0:1776194651.928823:0:2226:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000073b92078 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091193216:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:0.0:1776194651.948291:0:2227:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000078d15144 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:9c577acc-8068-4558-bc36-a4a67c56c094:2227:1862468091193280:192.168.204.122@tcp:400:kworker/u8:2.0 00000100:00100000:1.0:1776194651.959490:0:2226:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000073b92078 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091193216:192.168.204.122@tcp:400:kworker/u8:2.0 00010000:00010000:2.0:1776194652.312577:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000080:00200000:3.0:1776194652.800070:0:185666:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:3.0:1776194652.800214:0:185666:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: lookup flags 0 00010000:00010000:3.0:1776194652.800239:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.800258:0:185666:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00010000:3.0:1776194652.800272:0:185666:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:3.0:1776194652.800276:0:185666:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475bc4 00000080:00010000:3.0:1776194652.800285:0:185666:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475bc4 from it 00000000d4454968 00010000:00010000:3.0:1776194652.800288:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.800297:0:185666:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00200000:3.0:1776194652.800431:0:185666:0:(file.c:5661:ll_inode_permission()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), inode mode 41ff mask 1 00000080:00200000:3.0:1776194652.801048:0:185666:0:(namei.c:1111:ll_lookup_nd()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), flags=13 00000080:00200000:3.0:1776194652.801056:0:185666:0:(namei.c:833:ll_lookup_it()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), intent=getattr 00000002:00010000:3.0:1776194652.801077:0:185666:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: d831.sanity,[0x0:0x0:0x0]) in obj [0x200000007:0x1:0x0], intent: getattr flags 0 00010000:00010000:3.0:1776194652.801253:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.801264:0:185666:0:(ldlm_request.c:1026:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000 ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.801275:0:185666:0:(ldlm_request.c:1114:ldlm_cli_enqueue()) ### sending request ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000100:00100000:3.0:1776194652.801407:0:185666:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000004e111f15 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193344:192.168.204.122@tcp:101:lfs.0 00000100:00100000:3.0:1776194652.801918:0:185666:0:(client.c:2500:ptlrpc_set_wait()) set 00000000a39f97ce going to sleep for 41 seconds 00000100:00100000:3.0:1776194652.816135:0:185666:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000004e111f15 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193344:192.168.204.122@tcp:101:lfs.0 00010000:00010000:3.0:1776194652.816171:0:185666:0:(ldlm_request.c:641:ldlm_cli_enqueue_fini()) ### client-side enqueue END (ABORTED) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816192:0:185666:0:(ldlm_request.c:562:failed_lock_cleanup()) ### setting FL_LOCAL_ONLY | LDLM_FL_FAILED | LDLM_FL_ATOMIC_CB | LDLM_FL_CBPENDING ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816200:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816207:0:185666:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 3/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816250:0:185666:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816258:0:185666:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000439f63a0 already unused, calling callback (00000000b6f2abc1) 00010000:00010000:3.0:1776194652.816263:0:185666:0:(ldlm_request.c:1546:ldlm_cli_convert()) ### client lock convert START ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816271:0:185666:0:(ldlm_request.c:1556:ldlm_cli_convert()) ### client lock convert END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816280:0:185666:0:(ldlm_request.c:1232:ldlm_cli_cancel_local()) ### client-side cancel ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 5/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x20e400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816288:0:185666:0:(ldlm_request.c:1248:ldlm_cli_cancel_local()) not sending request (at caller's instruction) 00010000:00010000:3.0:1776194652.816295:0:185666:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 3/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.816302:0:185666:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000439f63a0/0xf969c8b2a0475bf5 lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000002:00100000:3.0:1776194652.816337:0:185666:0:(mdc_locks.c:743:mdc_finish_enqueue()) @@@ op=8 disposition=7, status=0 req@000000004e111f15 x1862468091193344/t0(0) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 584/640 e 0 to 0 dl 1776194694 ref 1 fl Complete:RQU/0/0 rc 301/301 job:'lfs.0' 00010000:00010000:3.0:1776194652.816387:0:185666:0:(ldlm_lock.c:1511:ldlm_lock_match_with_skip()) ### not matched ns 00000000ceb24551 type 13 mode 30 res 8589934599/1 (0 0) 00000080:00200000:2.0:1776194652.816713:0:185666:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:2.0:1776194652.816734:0:185666:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: lookup flags 0 00010000:00010000:2.0:1776194652.816743:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.816756:0:185666:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00010000:2.0:1776194652.816767:0:185666:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:2.0:1776194652.816771:0:185666:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475bc4 00000080:00010000:2.0:1776194652.816778:0:185666:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475bc4 from it 000000003675a750 00010000:00010000:2.0:1776194652.816781:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.816800:0:185666:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00200000:2.0:1776194652.816826:0:185666:0:(file.c:5661:ll_inode_permission()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), inode mode 41ff mask 1 00000080:00200000:2.0:1776194652.816849:0:185666:0:(namei.c:1111:ll_lookup_nd()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), flags=16392 00000080:00200000:2.0:1776194652.816855:0:185666:0:(namei.c:833:ll_lookup_it()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), intent=getattr 00000002:00010000:2.0:1776194652.816869:0:185666:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: d831.sanity,[0x0:0x0:0x0]) in obj [0x200000007:0x1:0x0], intent: getattr flags 0 00010000:00010000:2.0:1776194652.816928:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.816936:0:185666:0:(ldlm_request.c:1026:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000 ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.816947:0:185666:0:(ldlm_request.c:1114:ldlm_cli_enqueue()) ### sending request ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000100:00100000:2.0:1776194652.816991:0:185666:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193408:192.168.204.122@tcp:101:lfs.0 00000100:00100000:2.0:1776194652.817095:0:185666:0:(client.c:2500:ptlrpc_set_wait()) set 00000000fc402b96 going to sleep for 41 seconds 00000100:00100000:2.0:1776194652.821302:0:185666:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193408:192.168.204.122@tcp:101:lfs.0 00010000:00010000:2.0:1776194652.821341:0:185666:0:(ldlm_request.c:641:ldlm_cli_enqueue_fini()) ### client-side enqueue END (ABORTED) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821364:0:185666:0:(ldlm_request.c:562:failed_lock_cleanup()) ### setting FL_LOCAL_ONLY | LDLM_FL_FAILED | LDLM_FL_ATOMIC_CB | LDLM_FL_CBPENDING ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821373:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821380:0:185666:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 3/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821389:0:185666:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821396:0:185666:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000f6780553 already unused, calling callback (00000000b6f2abc1) 00010000:00010000:2.0:1776194652.821401:0:185666:0:(ldlm_request.c:1546:ldlm_cli_convert()) ### client lock convert START ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821409:0:185666:0:(ldlm_request.c:1556:ldlm_cli_convert()) ### client lock convert END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821418:0:185666:0:(ldlm_request.c:1232:ldlm_cli_cancel_local()) ### client-side cancel ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 5/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x20e400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821470:0:185666:0:(ldlm_request.c:1248:ldlm_cli_cancel_local()) not sending request (at caller's instruction) 00010000:00010000:2.0:1776194652.821478:0:185666:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 3/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821485:0:185666:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000f6780553/0xf969c8b2a0475bfc lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x2 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000002:00100000:2.0:1776194652.821551:0:185666:0:(mdc_locks.c:743:mdc_finish_enqueue()) @@@ op=8 disposition=7, status=0 req@0000000091544660 x1862468091193408/t0(0) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 584/640 e 0 to 0 dl 1776194694 ref 1 fl Complete:RQU/0/0 rc 301/301 job:'lfs.0' 00010000:00010000:2.0:1776194652.821595:0:185666:0:(ldlm_lock.c:1511:ldlm_lock_match_with_skip()) ### not matched ns 00000000ceb24551 type 13 mode 30 res 8589934599/1 (0 0) 00000080:00200000:2.0:1776194652.821897:0:185666:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:2.0:1776194652.821914:0:185666:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: getattr flags 0 00010000:00010000:2.0:1776194652.821922:0:185666:0:(ldlm_lock.c:1511:ldlm_lock_match_with_skip()) ### not matched ns 00000000ceb24551 type 13 mode 30 res 8589934599/1 (0 0) 00010000:00010000:2.0:1776194652.821981:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.821990:0:185666:0:(ldlm_request.c:1026:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000 ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.822001:0:185666:0:(ldlm_request.c:1114:ldlm_cli_enqueue()) ### sending request ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000100:00100000:2.0:1776194652.822031:0:185666:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193472:192.168.204.122@tcp:101:lfs.0 00000100:00100000:2.0:1776194652.824354:0:185666:0:(client.c:2500:ptlrpc_set_wait()) set 00000000fc402b96 going to sleep for 41 seconds 00000100:00100000:2.0:1776194652.829230:0:185666:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193472:192.168.204.122@tcp:101:lfs.0 00010000:00010000:2.0:1776194652.829270:0:185666:0:(ldlm_request.c:714:ldlm_cli_enqueue_fini()) ### server returned different mode PR ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829311:0:185666:0:(ldlm_request.c:742:ldlm_cli_enqueue_fini()) ### client-side enqueue, new policy data ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 4/1,0 mode: --/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829327:0:185666:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 4/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829342:0:185666:0:(ldlm_request.c:796:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 4/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829357:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 5/2,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829366:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 5/2,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829373:0:185666:0:(ldlm_lock.c:909:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 4/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000002:00100000:2.0:1776194652.829385:0:185666:0:(mdc_locks.c:743:mdc_finish_enqueue()) @@@ op=8 disposition=b, status=0 req@0000000091544660 x1862468091193472/t0(0) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 576/688 e 0 to 0 dl 1776194694 ref 1 fl Complete:RQU/0/0 rc 0/0 job:'lfs.0' 00000002:00010000:2.0:1776194652.829401:0:185666:0:(mdc_locks.c:1179:mdc_finish_intent_lock()) ### matching against this ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829418:0:185666:0:(ldlm_lock.c:1511:ldlm_lock_match_with_skip()) ### not matched ns 00000000ceb24551 type 13 mode 4 res 8589934599/1 (0 0) 00000080:00200000:2.0:1776194652.829485:0:185666:0:(llite_lib.c:2760:ll_update_inode()) inode=[0x200000007:0x1:0x0], updating i_size 25088 00000080:00010000:2.0:1776194652.829538:0:185666:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475c03 00000080:00010000:2.0:1776194652.829546:0:185666:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:2.0:1776194652.829549:0:185666:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475c03 from it 0000000050da104b 00010000:00010000:2.0:1776194652.829557:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.829565:0:185666:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000080:00200000:2.0:1776194652.833755:0:185666:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:2.0:1776194652.833791:0:185666:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: getattr flags 0 00010000:00010000:2.0:1776194652.833824:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 4 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.833843:0:185666:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000080:00010000:2.0:1776194652.833858:0:185666:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:2.0:1776194652.833862:0:185666:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475c03 00000080:00010000:2.0:1776194652.833871:0:185666:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475c03 from it 0000000050da104b 00010000:00010000:2.0:1776194652.833875:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.833883:0:185666:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000080:00200000:2.0:1776194652.834077:0:185666:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:2.0:1776194652.834085:0:185666:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: lookup flags 0 00010000:00010000:2.0:1776194652.834091:0:185666:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 4 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.834099:0:185666:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00010000:2.0:1776194652.834119:0:185666:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:2.0:1776194652.834122:0:185666:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475bc4 00000080:00010000:2.0:1776194652.834125:0:185666:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475bc4 from it 00000000a1eaf5e0 00010000:00010000:2.0:1776194652.834127:0:185666:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.834134:0:185666:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00200000:2.0:1776194652.834141:0:185666:0:(file.c:5661:ll_inode_permission()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), inode mode 41ff mask 44 00000080:00200000:2.0:1776194652.834151:0:185666:0:(file.c:837:ll_file_open()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), flags 300000 00000080:00200000:2.0:1776194652.834173:0:185666:0:(dir.c:1423:ll_dir_ioctl()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), cmd=0xc03066f0 00000080:00200000:2.0:1776194652.834187:0:185666:0:(dir.c:475:ll_dir_setdirstripe()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f) name d831.sanity stripe_offset 0, stripe_count: 0 00010000:00010000:2.0:1776194652.834217:0:185666:0:(ldlm_request.c:1232:ldlm_cli_cancel_local()) ### client-side cancel ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 4 type: IBT gid 0 flags: 0x8400000000 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.834237:0:185666:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 4 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.834297:0:185666:0:(ldlm_request.c:1279:__ldlm_pack_lock()) ### packing ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 1/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x4809400000020 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.834305:0:185666:0:(ldlm_request.c:1325:ldlm_cancel_pack()) 1 locks packed 00010000:00010000:2.0:1776194652.834308:0:185666:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 0000000010976a78/0xf969c8b2a0475c03 lrc: 0/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x4809400000020 nid: local remote: 0xe96d6de1471f031e expref: -99 pid: 185666 timeout: 0 lvb_type: 0 00000020:00100000:2.0:1776194652.834329:0:185666:0:(genops.c:2339:obd_get_mod_rpc_slot()) lustre-MDT0000-mdc-ffff92e388860000: modify RPC slot 1 is allocated opc 36, max 7 00000100:00100000:2.0:1776194652.834343:0:185666:0:(client.c:742:ptlrpc_reassign_next_xid()) @@@ reassign xid req@0000000091544660 x1862468091193600/t0(0) o36->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 560/448 e 0 to 0 dl 0 ref 1 fl New:QU/0/ffffffff rc 0/-1 job:'' 00000100:00100000:2.0:1776194652.834380:0:185666:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193600:192.168.204.122@tcp:36:lfs.0 00000100:00100000:2.0:1776194652.834544:0:185666:0:(client.c:2500:ptlrpc_set_wait()) set 00000000fc402b96 going to sleep for 41 seconds 00000100:00100000:2.0:1776194652.844553:0:185666:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000091544660 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185666:1862468091193600:192.168.204.122@tcp:36:lfs.0 00000080:00200000:2.0:1776194652.844622:0:185666:0:(llite_lib.c:2838:ll_read_inode2()) VFS Op:inode=[0x200002b11:0xec2:0x0](00000000221b4fb6) 00000080:00200000:2.0:1776194652.844629:0:185666:0:(llite_lib.c:2760:ll_update_inode()) inode=[0x200002b11:0xec2:0x0], updating i_size 512 00000080:00200000:2.0:1776194652.844678:0:185666:0:(file.c:410:ll_file_release()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f) 00000080:00200000:3.0:1776194652.875610:0:185667:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:3.0:1776194652.875649:0:185667:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: lookup flags 0 00010000:00010000:3.0:1776194652.875673:0:185667:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.875704:0:185667:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00010000:3.0:1776194652.875718:0:185667:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:3.0:1776194652.875722:0:185667:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475bc4 00000080:00010000:3.0:1776194652.875731:0:185667:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475bc4 from it 00000000f7733aa5 00010000:00010000:3.0:1776194652.875734:0:185667:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.875743:0:185667:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00200000:3.0:1776194652.875762:0:185667:0:(file.c:5661:ll_inode_permission()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), inode mode 41ff mask 1 00000080:00200000:3.0:1776194652.875780:0:185667:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:3.0:1776194652.875783:0:185667:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: lookup flags 0 00010000:00010000:3.0:1776194652.875788:0:185667:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.875794:0:185667:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00010000:3.0:1776194652.875801:0:185667:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:3.0:1776194652.875803:0:185667:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475bc4 00000080:00010000:3.0:1776194652.875806:0:185667:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475bc4 from it 0000000033d63896 00010000:00010000:3.0:1776194652.875808:0:185667:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:3.0:1776194652.879289:0:185667:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00200000:3.0:1776194652.879352:0:185667:0:(file.c:5661:ll_inode_permission()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), inode mode 41ff mask 3 00000080:00200000:3.0:1776194652.879365:0:185667:0:(namei.c:1183:ll_atomic_open()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), file 000000003ead87b3, open_flags a141, mode 81b6 opened 0 00000080:00200000:1.0:1776194652.880732:0:185667:0:(namei.c:833:ll_lookup_it()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), intent=open|creat 00000002:00010000:1.0:1776194652.880784:0:185667:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: d831.sanity,[0x200002b11:0xec3:0x0]) in obj [0x200000007:0x1:0x0], intent: open|creat flags 0120502 00010000:00010000:1.0:1776194652.880893:0:185667:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CW) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 3/0,1 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:1.0:1776194652.880907:0:185667:0:(ldlm_request.c:1026:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000 ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 3/0,1 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00000020:00100000:1.0:1776194652.880922:0:185667:0:(genops.c:2339:obd_get_mod_rpc_slot()) lustre-MDT0000-mdc-ffff92e388860000: modify RPC slot 1 is allocated opc 101, max 7 00000100:00100000:1.0:1776194652.880938:0:185667:0:(client.c:742:ptlrpc_reassign_next_xid()) @@@ reassign xid req@000000008e5abb2f x1862468091193728/t0(0) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/66264 e 0 to 0 dl 0 ref 1 fl New:PQU/0/ffffffff rc 0/-1 job:'' 00010000:00010000:1.0:1776194652.880949:0:185667:0:(ldlm_request.c:1114:ldlm_cli_enqueue()) ### sending request ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 3/0,1 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00000100:00100000:1.0:1776194652.880981:0:185667:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000008e5abb2f pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091193728:192.168.204.122@tcp:101:lfs.0 00000100:00100000:1.0:1776194652.881908:0:185667:0:(client.c:2500:ptlrpc_set_wait()) set 00000000b09f699f going to sleep for 41 seconds 00000100:00100000:0.0:1776194652.895613:0:185667:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000008e5abb2f pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091193728:192.168.204.122@tcp:101:lfs.0 00010000:00010000:0.0:1776194652.895662:0:185667:0:(ldlm_request.c:641:ldlm_cli_enqueue_fini()) ### client-side enqueue END (ABORTED) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 4/0,1 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895880:0:185667:0:(ldlm_request.c:562:failed_lock_cleanup()) ### setting FL_LOCAL_ONLY | LDLM_FL_FAILED | LDLM_FL_ATOMIC_CB | LDLM_FL_CBPENDING ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 4/0,1 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895888:0:185667:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CW) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 4/0,1 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895895:0:185667:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 3/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895905:0:185667:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 4/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895911:0:185667:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000066a0174 already unused, calling callback (00000000b6f2abc1) 00010000:00010000:0.0:1776194652.895916:0:185667:0:(ldlm_request.c:1546:ldlm_cli_convert()) ### client lock convert START ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 4/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895926:0:185667:0:(ldlm_request.c:1556:ldlm_cli_convert()) ### client lock convert END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 4/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895934:0:185667:0:(ldlm_request.c:1232:ldlm_cli_cancel_local()) ### client-side cancel ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 5/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x20e400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895943:0:185667:0:(ldlm_request.c:1248:ldlm_cli_cancel_local()) not sending request (at caller's instruction) 00010000:00010000:0.0:1776194652.895951:0:185667:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 3/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.895957:0:185667:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000066a0174/0xf969c8b2a0475c0a lrc: 0/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00000002:00100000:0.0:1776194652.895992:0:185667:0:(mdc_locks.c:743:mdc_finish_enqueue()) @@@ op=3 disposition=b, status=-21 req@000000008e5abb2f x1862468091193728/t0(0) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/600 e 0 to 0 dl 1776194694 ref 1 fl Complete:RQU/0/0 rc 301/301 job:'lfs.0' 00000080:00200000:0.0:1776194652.896297:0:185667:0:(file.c:5227:ll_inode_revalidate()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f),name=/ 00000002:00010000:0.0:1776194652.896325:0:185667:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: ,[0x200000007:0x1:0x0]) in obj [0x200000007:0x1:0x0], intent: lookup flags 0 00010000:00010000:0.0:1776194652.896347:0:185667:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.896360:0:185667:0:(ldlm_lock.c:1494:ldlm_lock_match_with_skip()) ### matched (0 0) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00010000:0.0:1776194652.896371:0:185667:0:(dcache.c:293:ll_lookup_finish_locks()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) 00000080:00010000:0.0:1776194652.896375:0:185667:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200000007:0x1:0x0](000000002e96928f) for lock 0xf969c8b2a0475bc4 00000080:00010000:0.0:1776194652.896381:0:185667:0:(dcache.c:193:ll_intent_drop_lock()) releasing lock with cookie 0xf969c8b2a0475bc4 from it 00000000f7733aa5 00010000:00010000:0.0:1776194652.896383:0:185667:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.896390:0:185667:0:(ldlm_lock.c:902:ldlm_lock_decref_internal()) ### add lock into lru list ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000a13612f3/0xf969c8b2a0475bc4 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x11/0x0 rrc: 2 type: IBT gid 0 flags: 0x0 nid: local remote: 0xe96d6de1471f0276 expref: -99 pid: 182541 timeout: 0 lvb_type: 0 00000080:00200000:0.0:1776194652.896406:0:185667:0:(file.c:5661:ll_inode_permission()) VFS Op:inode=[0x200000007:0x1:0x0](000000002e96928f), inode mode 41ff mask 1 00000080:00200000:0.0:1776194652.896423:0:185667:0:(namei.c:1183:ll_atomic_open()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), file 0000000028c4b997, open_flags 1a100, mode 0 opened 0 00000080:00200000:0.0:1776194652.896430:0:185667:0:(namei.c:833:ll_lookup_it()) VFS Op:name=d831.sanity, dir=[0x200000007:0x1:0x0](000000002e96928f), intent=open 00000002:00010000:0.0:1776194652.896442:0:185667:0:(mdc_locks.c:1328:mdc_intent_lock()) (name: d831.sanity,[0x0:0x0:0x0]) in obj [0x200000007:0x1:0x0], intent: open flags 0320401 00010000:00010000:0.0:1776194652.896564:0:185667:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:0.0:1776194652.896572:0:185667:0:(ldlm_request.c:1026:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000 ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00000020:00100000:0.0:1776194652.896594:0:185667:0:(genops.c:2339:obd_get_mod_rpc_slot()) lustre-MDT0000-mdc-ffff92e388860000: modify RPC slot 1 is allocated opc 101, max 7 00000100:00100000:0.0:1776194652.896601:0:185667:0:(client.c:742:ptlrpc_reassign_next_xid()) @@@ reassign xid req@0000000078d15144 x1862468091193856/t0(0) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/131800 e 0 to 0 dl 0 ref 1 fl New:PQU/0/ffffffff rc 0/-1 job:'' 00010000:00010000:0.0:1776194652.896611:0:185667:0:(ldlm_request.c:1114:ldlm_cli_enqueue()) ### sending request ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00000100:00100000:0.0:1776194652.897883:0:185667:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000078d15144 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091193856:192.168.204.122@tcp:101:lfs.0 00000100:00100000:1.0:1776194652.902249:0:185667:0:(client.c:2500:ptlrpc_set_wait()) set 000000000e75c0a8 going to sleep for 41 seconds 00000100:00100000:2.0:1776194652.907207:0:185667:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000078d15144 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091193856:192.168.204.122@tcp:101:lfs.0 00010000:00010000:2.0:1776194652.907241:0:185667:0:(ldlm_request.c:641:ldlm_cli_enqueue_fini()) ### client-side enqueue END (ABORTED) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907260:0:185667:0:(ldlm_request.c:562:failed_lock_cleanup()) ### setting FL_LOCAL_ONLY | LDLM_FL_FAILED | LDLM_FL_ATOMIC_CB | LDLM_FL_CBPENDING ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907268:0:185667:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 4/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907276:0:185667:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 3/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x10206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907286:0:185667:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907292:0:185667:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000971b1b14 already unused, calling callback (00000000b6f2abc1) 00010000:00010000:2.0:1776194652.907297:0:185667:0:(ldlm_request.c:1546:ldlm_cli_convert()) ### client lock convert START ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907304:0:185667:0:(ldlm_request.c:1556:ldlm_cli_convert()) ### client lock convert END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 4/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x206400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907335:0:185667:0:(ldlm_request.c:1232:ldlm_cli_cancel_local()) ### client-side cancel ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 5/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x20e400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907343:0:185667:0:(ldlm_request.c:1248:ldlm_cli_cancel_local()) not sending request (at caller's instruction) 00010000:00010000:2.0:1776194652.907350:0:185667:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 3/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00010000:00010000:2.0:1776194652.907357:0:185667:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: lustre-MDT0000-mdc-ffff92e388860000 lock: 00000000971b1b14/0xf969c8b2a0475c11 lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x1 rrc: 3 type: IBT gid 0 flags: 0x4a0f400000000 nid: local remote: 0x0 expref: -99 pid: 185667 timeout: 0 lvb_type: 0 00000002:00100000:2.0:1776194652.907382:0:185667:0:(mdc_locks.c:743:mdc_finish_enqueue()) @@@ op=1 disposition=2b, status=0 req@0000000078d15144 x1862468091193856/t34359738376(34359738376) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/600 e 0 to 0 dl 1776194694 ref 2 fl Complete:RPQU/4/0 rc 301/301 job:'lfs.0' 00000002:00100000:2.0:1776194652.907397:0:185667:0:(mdc_request.c:833:mdc_set_open_replay_data()) @@@ Set up open replay data req@0000000078d15144 x1862468091193856/t34359738376(34359738376) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/600 e 0 to 0 dl 1776194694 ref 2 fl Complete:RPQU/4/0 rc 301/301 job:'lfs.0' 00000080:00200000:2.0:1776194652.907439:0:185667:0:(llite_lib.c:2760:ll_update_inode()) inode=[0x200002b11:0xec2:0x0], updating i_size 512 00000080:00200000:2.0:1776194652.907443:0:185667:0:(namei.c:157:ll_iget()) got inode: [0x200002b11:0xec2:0x0](00000000221b4fb6): rc = 0 00000080:00010000:2.0:1776194652.907449:0:185667:0:(llite_internal.h:1711:ll_set_lock_data()) setting l_data to inode [0x200002b11:0xec2:0x0](00000000221b4fb6) for lock 0x0 00000080:00200000:2.0:1776194652.907477:0:185667:0:(file.c:837:ll_file_open()) VFS Op:inode=[0x200002b11:0xec2:0x0](00000000221b4fb6), flags 320400 00000002:00100000:2.0:1776194652.907494:0:185667:0:(mdc_request.c:833:mdc_set_open_replay_data()) @@@ Set up open replay data req@0000000078d15144 x1862468091193856/t34359738376(34359738376) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/600 e 0 to 0 dl 1776194694 ref 2 fl Complete:RPQU/4/0 rc 301/301 job:'lfs.0' 00000080:00200000:2.0:1776194652.907737:0:185667:0:(file.c:5661:ll_inode_permission()) VFS Op:inode=[0x200002b11:0xec2:0x0](00000000221b4fb6), inode mode 41ed mask 44 00000080:00200000:2.0:1776194652.907787:0:185667:0:(dir.c:1423:ll_dir_ioctl()) VFS Op:inode=[0x200002b11:0xec2:0x0](00000000221b4fb6), cmd=0x4008669a 00000020:00100000:2.0:1776194652.907868:0:185667:0:(genops.c:2339:obd_get_mod_rpc_slot()) lustre-MDT0000-mdc-ffff92e388860000: modify RPC slot 1 is allocated opc 36, max 7 00000100:00100000:2.0:1776194652.907876:0:185667:0:(client.c:742:ptlrpc_reassign_next_xid()) @@@ reassign xid req@00000000ab5a4fd1 x1862468091193984/t0(0) o36->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 520/512 e 0 to 0 dl 0 ref 1 fl New:QU/0/ffffffff rc 0/-1 job:'' 00000100:00100000:2.0:1776194652.907905:0:185667:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000ab5a4fd1 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091193984:192.168.204.122@tcp:36:lfs.0 00000100:00100000:2.0:1776194652.908005:0:185667:0:(client.c:2500:ptlrpc_set_wait()) set 00000000fc402b96 going to sleep for 41 seconds 00000100:00100000:2.0:1776194652.912641:0:185667:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000ab5a4fd1 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091193984:192.168.204.122@tcp:36:lfs.0 00000080:00200000:2.0:1776194652.912749:0:185667:0:(file.c:410:ll_file_release()) VFS Op:inode=[0x200002b11:0xec2:0x0](00000000221b4fb6) 00000002:00100000:2.0:1776194652.912824:0:185667:0:(mdc_request.c:944:mdc_close()) @@@ matched open req@0000000078d15144 x1862468091193856/t34359738376(34359738376) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/600 e 0 to 0 dl 1776194694 ref 1 fl Complete:RPQU/4/ffffffff rc 301/-1 job:'lfs.0' 00000020:00100000:2.0:1776194652.912861:0:185667:0:(genops.c:2339:obd_get_mod_rpc_slot()) lustre-MDT0000-mdc-ffff92e388860000: modify RPC slot 1 is allocated opc 35, max 7 00000100:00100000:2.0:1776194652.912867:0:185667:0:(client.c:742:ptlrpc_reassign_next_xid()) @@@ reassign xid req@00000000cbd59c36 x1862468091194112/t0(0) o35->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:23/10 lens 392/624 e 0 to 0 dl 0 ref 1 fl New:QU/0/ffffffff rc 0/-1 job:'' 00000100:00100000:2.0:1776194652.912890:0:185667:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000cbd59c36 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091194112:192.168.204.122@tcp:35:lfs.0 00000100:00100000:2.0:1776194652.912947:0:185667:0:(client.c:2500:ptlrpc_set_wait()) set 00000000fc402b96 going to sleep for 6 seconds 00000100:00100000:2.0:1776194652.919091:0:185667:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000cbd59c36 pname:cluuid:pid:xid:nid:opc:job lfs:9c577acc-8068-4558-bc36-a4a67c56c094:185667:1862468091194112:192.168.204.122@tcp:35:lfs.0 00000002:00100000:2.0:1776194652.919148:0:185667:0:(mdc_request.c:854:mdc_free_open()) @@@ free open request, rq_replay=0 req@0000000078d15144 x1862468091193856/t34359738376(34359738376) o101->lustre-MDT0000-mdc-ffff92e388860000@192.168.204.122@tcp:12/10 lens 528/600 e 0 to 0 dl 1776194694 ref 1 fl Complete:RQU/4/ffffffff rc 301/-1 job:'lfs.0' 00010000:00010000:2.0:1776194653.335851:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194654.362670:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:3.0:1776194655.387440:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1776194656.409535:0:165104:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00080000:0.0:1776194657.048448:0:169720:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194657.048460:0:169720:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0000_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00080000:0.0:1776194657.048463:0:169720:0:(pinger.c:251:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: level IDLE/11 force 0 force_next 0 deactive 0 pingable 1 suppress 0 00000100:00080000:0.0:1776194657.048465:0:169720:0:(pinger.c:265:ptlrpc_pinger_process_import()) 9c577acc-8068-4558-bc36-a4a67c56c094->lustre-OST0001_UUID: not pinging (in recovery or recovery disabled: IDLE) 00000100:00100000:0.0:1776194657.048552:0:2226:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000008551c194 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091194176:192.168.204.122@tcp:400:kworker/u8:0.0 00000100:00100000:0.0:1776194657.048687:0:2226:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0] 00000100:00100000:0.0:1776194657.048695:0:2226:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000572d3eda pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:9c577acc-8068-4558-bc36-a4a67c56c094:2226:1862468091194240:192.168.204.122@tcp:400:kworker/u8:0.0 00000100:00100000:0.0:1776194657.052275:0:2226:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000008551c194 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:5f5c1c40-b1db-4d76-936f-e7582a955e7e:2226:1862468091194176:192.168.204.122@tcp:400:kworker/u8:0.0 00000100:00100000:1.0:1776194657.060128:0:2226:0:(client.c:2868:ptlrpc_free_committed()) lustre-MDT0000-mdc-ffff92e388860000: committing for last_committed 34359738378 gen 1 00000100:00100000:1.0:1776194657.060184:0:2226:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000572d3eda pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:9c577acc-8068-4558-bc36-a4a67c56c094:2226:1862468091194240:192.168.204.122@tcp:400:kworker/u8:0.0 00010000:00010000:3.0:1776194657.431778:0:165105:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) Debug log: 342 lines, 342 kept, 0 dropped, 0 bad.