00000001:02000400:1.0F:1787761107.843504:0:26110:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg219-server.virtnet: executing load_modules_local 00000001:01000000:3.0F:1787761108.425124:0:26154:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm adler32 speed = 1015 MB/s 00000001:01000000:3.0:1787761108.675635:0:26154:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32 speed = 1679 MB/s 00000001:01000000:3.0:1787761108.925114:0:26154:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32c speed = 11243 MB/s 00000020:02000000:3.0:1787761109.035449:0:26201:0:(class_obd.c:771:obdclass_init()) Lustre: Build Version: 2.17.57_116_g5de3d4c 00000400:02000000:0.0F:1787761109.123430:0:26216:0:(api-ni.c:2823:lnet_startup_lndni()) Added LNI 192.168.202.119@tcp [8/256/0/180] 00008000:02000000:3.0:1787761111.120577:0:26356:0:(echo_client.c:2574:obdecho_init()) Echo OBD driver; http://www.lustre.org/ 00000020:01000004:2.0F:1787761116.947684:0:27097:0:(obd_mount.c:923:lmd_print()) mount data: 00000020:01000004:2.0:1787761116.947694:0:27097:0:(obd_mount.c:926:lmd_print()) device: /dev/mapper/mds1_flakey 00000020:01000004:2.0:1787761116.947695:0:27097:0:(obd_mount.c:929:lmd_print()) options: user_xattr,errors=remount-ro 00000080:01200004:2.0:1787761116.947848:0:27097:0:(super25.c:131:lustre_fill_super()) VFS Op: sb 00000000e473d46f 00000080:02000400:2.0:1787761116.947856:0:27097:0:(super25.c:149:lustre_fill_super()) lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' 00000020:01000004:2.0:1787761116.950101:0:27097:0:(tgt_mount.c:2500:osd_start()) Attempting to start lustre-MDT0000, type=osd-ldiskfs, lsifl=200005, mountfl=0 00000020:01000004:2.0:1787761116.950107:0:27097:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD lustre-MDT0000-osd (typ=osd-ldiskfs) 00000020:00000080:2.0:1787761116.950125:0:27097:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-osd (00000000af2e0ff0) 00000020:00000080:2.0:1787761116.950135:0:27097:0:(obd_config.c:720:class_attach_name()) OBD: dev 0 attached type osd-ldiskfs with refcount 2 00100000:10000000:1.0:1787761116.975677:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x13:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.976300:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000001:0x3:0x0] (8/24) registered 00100000:10000000:1.0:1787761116.977473:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.978670:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x2:0x0] (8/8) registered 00100000:10000000:1.0:1787761116.978938:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xa:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.979125:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xb:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.979271:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x3:0x0] (8/8) registered 00100000:10000000:1.0:1787761116.979454:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x1:0x0] (8/8) registered 00100000:10000000:1.0:1787761116.979686:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xe:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.979832:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x9:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.979967:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xc:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.980115:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xd:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.980257:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x20001:0x0] (8/8) registered 00100000:10000000:1.0:1787761116.980422:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x20002:0x0] (8/8) registered 00100000:10000000:1.0:1787761116.980812:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x20003:0x0] (8/8) registered 00100000:10000000:1.0:1787761116.981943:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x23:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.982232:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2c:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.982610:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x34:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.982993:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2e:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.983375:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x30:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.983666:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x27:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.983858:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x28:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.984081:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2d:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.984393:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x32:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.984711:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x18:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.984908:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x19:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.985359:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x22:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.985694:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1f:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.985864:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1c:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.986077:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x21:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.986272:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x16:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.986455:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2b:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.986671:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x33:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.986812:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1a:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.986965:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x17:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.987136:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x29:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.987279:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1e:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.987512:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x26:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.987929:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2f:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.988078:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x31:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.988458:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x14:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.988668:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x25:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.988847:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2a:0x0] (24/16) registered 00100000:10000000:1.0:1787761116.989015:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x15:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.989272:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x20:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.989445:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1d:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.989676:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1b:0x0] (16/1) registered 00100000:10000000:1.0:1787761116.989998:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x1010000:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.990383:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x2010000:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.990622:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x10000:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.990945:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x2020000:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.991107:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x20000:0x0] (8/32) registered 00100000:10000000:1.0:1787761116.991282:0:27097:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x1020000:0x0] (8/32) registered 00080000:01000000:1.0:1787761116.992236:0:27097:0:(osd_lproc.c:911:osd_procfs_init()) lustre-MDT0000: register osd-ldiskfs tunable parameters 00000020:00000080:1.0:1787761116.992442:0:27097:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-osd (uuid lustre-MDT0000-osd_UUID) 00080000:01000000:1.0:1787761116.992449:0:27097:0:(osd_handler.c:8895:osd_obd_connect()) connect #0 00000020:00000080:1.0:1787761116.992459:0:27097:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2bb2 00000020:01000004:1.0:1787761116.992464:0:27097:0:(tgt_mount.c:2585:server_fill_super()) Found service lustre-MDT0000 on device /dev/mapper/mds1_flakey 00000020:01000000:1.0:1787761116.992469:0:27097:0:(tgt_mount.c:219:server_start_mgs()) Start MGS service MGS 00000020:01000004:1.0:1787761116.992473:0:27097:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000e473d46f from MGS 00000020:01000004:1.0:1787761116.992477:0:27097:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGS (typ=mgs) 00000020:00000080:1.0:1787761116.992492:0:27097:0:(genops.c:413:class_newdev()) Allocate new device MGS (000000004e3bd08b) 00000020:00000080:1.0:1787761116.992500:0:27097:0:(obd_config.c:720:class_attach_name()) OBD: dev 1 attached type mgs with refcount 2 00000020:01000004:1.0:1787761116.992602:0:27097:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000e473d46f from MGS, refs=2 00080000:01000000:1.0:1787761116.992608:0:27097:0:(osd_handler.c:8895:osd_obd_connect()) connect #1 00000020:00000080:1.0:1787761116.992612:0:27097:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2bc0 00000100:00100000:1.0:1787761116.992696:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_cbd: allocate 1 new 8192-byte reqbufs (0/1 left), rc = 0 00000100:00100000:1.0:1787761116.992815:0:27097:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 0 min 2 max 56 00000100:00100000:1.0:1787761116.992821:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_000' 00000100:00100000:1.0:1787761116.993424:0:27097:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 1 min 2 max 56 00000100:00100000:1.0:1787761116.993429:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_001' 00000100:00100000:1.0:1787761116.993931:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_canceld: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:1.0:1787761116.994223:0:27097:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 0 min 3 max 56 00000100:00100000:1.0:1787761116.994228:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_000' 00000100:00100000:1.0:1787761116.994803:0:27097:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 1 min 3 max 56 00000100:00100000:1.0:1787761116.994809:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_001' 00000100:00100000:1.0:1787761116.995113:0:27097:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 2 min 3 max 56 00000100:00100000:1.0:1787761116.995118:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_002' 00010000:00010000:2.0:1787761116.995714:0:27106:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761116.995717:0:27106:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761116.995719:0:27106:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761116.995964:0:27107:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761116.995966:0:27107:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761116.995968:0:27107:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:1.0:1787761116.996526:0:27097:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGS-0 is initialized 00010000:00010000:2.0:1787761117.001148:0:27106:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000001:01000000:0.0:1787761117.246092:0:27097:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip512 speed = 6043 MB/s 00000001:01000000:1.0:1787761117.496198:0:27097:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip4K speed = 7111 MB/s 00000001:01000000:1.0:1787761117.746262:0:27097:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc512 speed = 1423 MB/s 00000001:01000000:1.0:1787761117.996597:0:27097:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc4K speed = 1847 MB/s 00010000:00010000:2.0:1787761118.002152:0:27107:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000040:01000000:1.0:1787761118.002571:0:27097:0:(llog_obd.c:197:llog_setup()) obd MGS ctxt 0 is initialized 10000000:01000000:1.0:1787761118.004805:0:27109:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x2 (params) 20000000:01000000:2.0:1787761118.004835:0:27097:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2 20000000:01000000:2.0:1787761118.004879:0:27097:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:2.0:1787761118.005447:0:27097:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 00000100:00100000:2.0:1787761118.005742:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mgs: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1787761118.005901:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 0 min 3 max 32 00000100:00100000:2.0:1787761118.005907:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0000' 00000100:00100000:1.0:1787761118.007730:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 1 min 3 max 32 00000100:00100000:1.0:1787761118.007743:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0001' 00000100:00100000:3.0:1787761118.008309:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 2 min 3 max 32 00000100:00100000:3.0:1787761118.008333:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0002' 00000100:00080000:1.0:1787761118.008783:0:27114:0:(pinger.c:466:ping_evictor_main()) Starting Ping Evictor 00000020:00000080:3.0:1787761118.008994:0:27097:0:(obd_config.c:826:class_setup()) finished setup of obd MGS (uuid MGS) 00000020:01000004:3.0:1787761118.009013:0:27097:0:(obd_mount.c:411:lustre_start_mgc()) Start MGC 'MGC192.168.202.119@tcp' 00000020:01000004:3.0:1787761118.009014:0:27097:0:(obd_mount.c:420:lustre_start_mgc()) mgs NIDs (null). 00000020:01000004:3.0:1787761118.009220:0:27097:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGC192.168.202.119@tcp (typ=mgc) 00000020:00000080:3.0:1787761118.009241:0:27097:0:(genops.c:413:class_newdev()) Allocate new device MGC192.168.202.119@tcp (00000000fac89deb) 00000020:00000080:3.0:1787761118.009257:0:27097:0:(obd_config.c:720:class_attach_name()) OBD: dev 2 attached type mgc with refcount 2 00010000:00080000:3.0:1787761118.009382:0:27097:0:(ldlm_lib.c:102:import_set_conn()) imp 0000000042b4d148@MGC192.168.202.119@tcp: add connection 192.168.202.119@tcp at head 00010000:00010000:3.0:1787761118.009560:0:27097:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGC192.168.202.119@tcp-0 is initialized 00000040:01000000:3.0:1787761118.009565:0:27097:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.202.119@tcp ctxt 1 is initialized 10000000:01000000:1.0:1787761118.010714:0:27115:0:(mgc_request.c:631:mgc_requeue_thread()) Starting requeue thread 00000020:00000080:2.0:1787761118.010807:0:27097:0:(obd_config.c:826:class_setup()) finished setup of obd MGC192.168.202.119@tcp (uuid c73e603f-74af-422b-8b68-88272a5bb5a4) 00000020:00000080:2.0:1787761118.010824:0:27097:0:(genops.c:1385:class_connect()) connect: client c73e603f-74af-422b-8b68-88272a5bb5a4, cookie 0x1ae94944360d2bce 00000100:00080000:2.0:1787761118.010832:0:27097:0:(import.c:510:import_select_connection()) MGC192.168.202.119@tcp: connect to NID 0@lo last attempt 0 00000100:00080000:2.0:1787761118.010836:0:27097:0:(import.c:624:import_select_connection()) MGC192.168.202.119@tcp: import 0000000042b4d148 using connection 192.168.202.119@tcp/0@lo 00000100:00100000:2.0:1787761118.010860:0:27097:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@0000000060d36610 x1874603392630912/t0(0) o250->MGC192.168.202.119@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl New:NQU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 00000100:00080000:2.0:1787761118.010877:0:27097:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import c73e603f-74af-422b-8b68-88272a5bb5a4->MGS 00000020:01000004:2.0:1787761118.010892:0:27097:0:(tgt_mount.c:1809:server_start_targets()) starting target lustre-MDT0000 00000020:01000004:2.0:1787761118.010895:0:27097:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MDS (typ=mds) 00000020:00000080:2.0:1787761118.010923:0:27097:0:(genops.c:413:class_newdev()) Allocate new device MDS (0000000098887d63) 00000020:00000080:2.0:1787761118.010934:0:27097:0:(obd_config.c:720:class_attach_name()) OBD: dev 3 attached type mds with refcount 2 00000100:00100000:1.0:1787761118.011002:0:26231:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000060d36610 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:c73e603f-74af-422b-8b68-88272a5bb5a4:26231:1874603392630912:0@lo:250: 00000100:00100000:1.0:1787761118.011259:0:26231:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761118.014342:0:27111:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392630912 00000100:00100000:1.0:1787761118.014353:0:27111:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392630912 00000100:00100000:1.0:1787761118.014396:0:27112:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1787761118.014403:0:27112:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000fb56869b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:0+-99:26231:x1874603392630912:12345-0@lo:250: 00010000:00080000:1.0:1787761118.014431:0:27112:0:(ldlm_lib.c:1482:target_handle_connect()) MGS: connection from c73e603f-74af-422b-8b68-88272a5bb5a4@0@lo t0 exp 0000000000000000 cur 1027 last 0 00000020:00000080:1.0:1787761118.014459:0:27112:0:(genops.c:1385:class_connect()) connect: client c73e603f-74af-422b-8b68-88272a5bb5a4, cookie 0x1ae94944360d2bdc 00000100:00080000:1.0:1787761118.014640:0:27112:0:(import.c:65:import_set_state_nolock()) 00000000fbb87241 : changing import state from RECOVER to FULL 00000100:00100000:1.0:1787761118.014718:0:27112:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000fb56869b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+5:26231:x1874603392630912:12345-0@lo:250: Request processed in 315us (3460us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.014726:0:27112:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1787761118.014771:0:26231:0:(client.c:3125:ptlrpc_free_committed()) MGC192.168.202.119@tcp: committing for last_committed 0 gen 1 00000100:00080000:1.0:1787761118.014779:0:26231:0:(import.c:1132:ptlrpc_connect_interpret()) MGC192.168.202.119@tcp: connect to target with instance 0 00000100:00080000:1.0:1787761118.014786:0:26231:0:(import.c:956:ptlrpc_connect_set_flags()) MGC192.168.202.119@tcp: Resetting ns_connect_flags to server flags: 0xa000011001002060 10000000:01000000:1.0:1787761118.014790:0:26231:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808005 00000100:00080000:1.0:1787761118.014793:0:26231:0:(import.c:65:import_set_state_nolock()) 0000000042b4d148 MGS: changing import state from CONNECTING to FULL 10000000:01000000:1.0:1787761118.014795:0:26231:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808004 00000100:00080000:1.0:1787761118.014804:0:26231:0:(pinger.c:186:ptlrpc_pinger_ir_up()) IR up 00000100:00100000:1.0:1787761118.014808:0:26231:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@0000000060d36610 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:c73e603f-74af-422b-8b68-88272a5bb5a4:26231:1874603392630912:0@lo:250: 00000100:00100000:2.0:1787761118.017593:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt: allocate 64 new 262144-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1787761118.017769:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 0 min 3 max 116 00000100:00100000:2.0:1787761118.017775:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_000' 00000100:00100000:3.0:1787761118.018304:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 1 min 3 max 116 00000100:00100000:3.0:1787761118.018311:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_001' 00000100:00100000:3.0:1787761118.018757:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 2 min 3 max 116 00000100:00100000:3.0:1787761118.018763:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_002' 00000100:00100000:3.0:1787761118.019648:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_readpage: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:3.0:1787761118.019852:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 0 min 2 max 80 00000100:00100000:3.0:1787761118.019857:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_000' 00000100:00100000:2.0:1787761118.020445:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 1 min 2 max 80 00000100:00100000:2.0:1787761118.020451:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_001' 00000100:00100000:3.0:1787761118.050957:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_out: allocate 64 new 1048576-byte reqbufs (0/64 left), rc = 0 00000100:00100000:3.0:1787761118.051130:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 0 min 2 max 116 00000100:00100000:3.0:1787761118.051135:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_000' 00000100:00100000:3.0:1787761118.051924:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 1 min 2 max 116 00000100:00100000:3.0:1787761118.051931:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_001' 00000100:00100000:2.0:1787761118.053119:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqs: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1787761118.053239:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 0 min 2 max 256 00000100:00100000:2.0:1787761118.053243:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0000' 00000100:00100000:3.0:1787761118.053564:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 1 min 2 max 256 00000100:00100000:3.0:1787761118.053571:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0001' 00000100:00100000:2.0:1787761118.053936:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqm: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1787761118.054038:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 0 min 2 max 256 00000100:00100000:2.0:1787761118.054042:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0000' 00000100:00100000:3.0:1787761118.054377:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 1 min 2 max 256 00000100:00100000:3.0:1787761118.054383:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0001' 00000100:00100000:2.0:1787761118.054720:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_fld: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1787761118.054832:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 0 min 2 max 256 00000100:00100000:2.0:1787761118.054836:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0000' 00000100:00100000:3.0:1787761118.055199:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 1 min 2 max 256 00000100:00100000:3.0:1787761118.055207:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0001' 00000100:00100000:2.0:1787761118.067015:0:27097:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_io: allocate 64 new 524288-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1787761118.067237:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 0 min 3 max 116 00000100:00100000:2.0:1787761118.067245:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_000' 00000100:00100000:3.0:1787761118.069188:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 1 min 3 max 116 00000100:00100000:3.0:1787761118.069198:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_001' 00000100:00100000:2.0:1787761118.070118:0:27097:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 2 min 3 max 116 00000100:00100000:2.0:1787761118.070125:0:27097:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_002' 00000020:00000080:3.0:1787761118.071036:0:27097:0:(obd_config.c:826:class_setup()) finished setup of obd MDS (uuid MDS_uuid) 00000020:01000004:3.0:1787761118.071095:0:27097:0:(tgt_mount.c:280:server_mgc_set_fs()) Set mgc disk for /dev/mapper/mds1_flakey 10000000:01000000:3.0:1787761118.071102:0:27097:0:(mgc_request_server.c:89:mgc_fs_setup()) MGC192.168.202.119@tcp: cl_mgc_mutex lustre-MDT0000-osd for locked: rc = 0 00000040:01000000:3.0:1787761118.071190:0:27097:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.202.119@tcp ctxt 0 is initialized 00000020:01000004:3.0:1787761118.071220:0:27097:0:(tgt_mount.c:1418:server_register_target()) Registration lustre-MDT0000, fs=lustre, 192.168.202.119@tcp, index=0000, flags=0x20005 00000020:01000004:3.0:1787761118.071224:0:27097:0:(tgt_mount.c:1175:server_mti_print()) mti - server_register_target 00000020:01000004:3.0:1787761118.071225:0:27097:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:3.0:1787761118.071226:0:27097:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:3.0:1787761118.071228:0:27097:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1787761118.071229:0:27097:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1787761118.071230:0:27097:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1787761118.071231:0:27097:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1787761118.071232:0:27097:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1787761118.071234:0:27097:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1787761118.071235:0:27097:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 10000000:01000000:3.0:1787761118.071237:0:27097:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target lustre-MDT0000 0x10020005 00000020:01000004:3.0:1787761118.071327:0:27097:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req 00000020:01000004:3.0:1787761118.071329:0:27097:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:3.0:1787761118.071330:0:27097:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:3.0:1787761118.071330:0:27097:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1787761118.071331:0:27097:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1787761118.071332:0:27097:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1787761118.071332:0:27097:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1787761118.071333:0:27097:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1787761118.071334:0:27097:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1787761118.071335:0:27097:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 10000000:01000000:3.0:1787761118.071367:0:27097:0:(mgc_request_server.c:281:mgc_target_register()) register lustre-MDT0000 00000100:00100000:3.0:1787761118.071381:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631040:0@lo:253: 00000100:00100000:3.0:1787761118.071441:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761118.071491:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631040 00000100:00100000:3.0:1787761118.071494:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000069aede1f going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.071497:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631040 00000100:00100000:1.0:1787761118.071532:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 1 00000100:00100000:1.0:1787761118.071538:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000005714cca8 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+5:27097:x1874603392631040:12345-0@lo:253: 20000000:01000000:1.0:1787761118.071582:0:27113:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:1.0:1787761118.071587:0:27113:0:(mgs_handler.c:479:mgs_target_reg()) fs: lustre index: 0 is registered to MGS. 20000000:01000000:1.0:1787761118.071590:0:27113:0:(mgs_handler.c:529:mgs_target_reg()) Server lustre-MDT0000 is running on 0@lo 10000000:01000000:2.0:1787761118.071772:0:27134:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x2 (lustre) 20000000:01000000:1.0:1787761118.072062:0:27113:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 10 20000000:01000000:2.0:1787761118.072993:0:27135:0:(mgs_llog.c:340:mgs_fsdb_handler()) MDT index is 0 20000000:01000000:2.0:1787761118.072997:0:27135:0:(mgs_llog.c:340:mgs_fsdb_handler()) MDT index is 1 20000000:01000000:2.0:1787761118.073000:0:27135:0:(mgs_llog.c:324:mgs_fsdb_handler()) OST index for lustre-OST0000_UUID is 0 (0) 20000000:01000000:2.0:1787761118.073002:0:27135:0:(mgs_llog.c:324:mgs_fsdb_handler()) OST index for lustre-OST0001_UUID is 1 (1) 00000040:00080000:2.0:1787761118.073139:0:27135:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 52 count 51 20000000:01000000:1.0:1787761118.073224:0:27113:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:1.0:1787761118.073229:0:27113:0:(mgs_handler.c:637:mgs_target_reg()) replying with lustre-MDT0000, index=0, rc=0 00000100:00100000:1.0:1787761118.073997:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000005714cca8 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+5:27097:x1874603392631040:12345-0@lo:253: Request processed in 2458us (2556us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.074006:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 1 00000100:00100000:3.0:1787761118.074031:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631040:0@lo:253: 10000000:01000000:3.0:1787761118.074040:0:27097:0:(mgc_request_server.c:302:mgc_target_register()) register lustre-MDT0000 got index = 0 00000020:01000004:3.0:1787761118.074042:0:27097:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: rep 00000020:01000004:3.0:1787761118.074068:0:27097:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:3.0:1787761118.074070:0:27097:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:3.0:1787761118.074071:0:27097:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1787761118.074072:0:27097:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1787761118.074074:0:27097:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1787761118.074075:0:27097:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1787761118.074077:0:27097:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1787761118.074078:0:27097:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1787761118.074079:0:27097:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 00000020:01000004:3.0:1787761118.074093:0:27097:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000e473d46f from lustre-MDT0000 10000000:01000000:3.0:1787761118.074106:0:27097:0:(mgc_request.c:1944:mgc_process_config()) parse_log lustre-MDT0000 from 0 10000000:01000000:3.0:1787761118.074107:0:27097:0:(mgc_request.c:329:config_log_add()) add config log lustre-MDT0000-0000000000000000 10000000:01000000:3.0:1787761118.074110:0:27097:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-sptlrpc-ffff8bbebff38000 10000000:01000000:3.0:1787761118.074112:0:27097:0:(mgc_request.c:68:mgc_name2resid()) log lustre-sptlrpc to resid 0x65727473756c/0x0 (lustre) 10000000:01000000:3.0:1787761118.074116:0:27097:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-sptlrpc-ffff8bbebff38000 from 1 10000000:01000000:3.0:1787761118.074118:0:27097:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-sptlrpc (res 0x65727473756c) 00010000:00010000:3.0:1787761118.074139:0:27097:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.119@tcp lock: 000000004d003fcf/0x1ae94944360d2be3 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074148:0:27097:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.119@tcp lock: 000000004d003fcf/0x1ae94944360d2be3 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074156:0:27097:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.119@tcp lock: 000000004d003fcf/0x1ae94944360d2be3 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.074168:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631168:0@lo:101: 00000100:00100000:3.0:1787761118.074188:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.074210:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000063b2acf5 going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.074225:0:27111:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631168 00000100:00100000:1.0:1787761118.074230:0:27111:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631168 00000100:00100000:1.0:1787761118.074255:0:27111:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 2 00000100:00100000:1.0:1787761118.074263:0:27111:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000aaee2b79 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+5:27097:x1874603392631168:12345-0@lo:101: 00010000:00010000:1.0:1787761118.074271:0:27111:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:1.0:1787761118.074284:0:27111:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 0000000052d8de92/0x1ae94944360d2bea lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x1ae94944360d2be3 expref: -99 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.074302:0:27111:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 0000000052d8de92/0x1ae94944360d2bea lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x1ae94944360d2be3 expref: 6 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.074310:0:27111:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 0000000052d8de92/0x1ae94944360d2bea lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x1ae94944360d2be3 expref: 6 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.074330:0:27111:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 0000000052d8de92, rc 0) 00000100:00100000:1.0:1787761118.074361:0:27111:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000aaee2b79 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+6:27097:x1874603392631168:12345-0@lo:101: Request processed in 99us (171us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.074367:0:27111:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 2 00000100:00100000:3.0:1787761118.074397:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631168:0@lo:101: 00010000:00010000:3.0:1787761118.074411:0:27097:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.119@tcp lock: 000000004d003fcf/0x1ae94944360d2be3 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2bea expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074420:0:27097:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.119@tcp lock: 000000004d003fcf/0x1ae94944360d2be3 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x1ae94944360d2bea expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.074470:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631296:0@lo:501: 00000100:00100000:3.0:1787761118.074497:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.074514:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000063b2acf5 going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.074533:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631296 00000100:00100000:1.0:1787761118.074537:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631296 00000100:00100000:1.0:1787761118.074559:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 3 00000100:00100000:1.0:1787761118.074564:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000009d8d3caa pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+6:27097:x1874603392631296:12345-0@lo:501: 00000100:00100000:1.0:1787761118.074631:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000009d8d3caa pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+6:27097:x1874603392631296:12345-0@lo:501: Request processed in 67us (134us total) trans 0 rc -2/-2 00000100:00100000:1.0:1787761118.074636:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 3 00000100:00100000:3.0:1787761118.074660:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631296:0@lo:501: 10000000:01000000:3.0:1787761118.074682:0:27097:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.202.119@tcp: configuration from log 'lustre-sptlrpc' failed (-2). 00010000:00010000:3.0:1787761118.074693:0:27097:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.119@tcp lock: 000000004d003fcf/0x1ae94944360d2be3 lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2bea expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074700:0:27097:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.119@tcp lock: 000000004d003fcf/0x1ae94944360d2be3 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2bea expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761118.074708:0:27097:0:(mgc_request.c:194:do_config_log_add()) do adding config log params-ffff8bbd940ac000 10000000:01000000:3.0:1787761118.074711:0:27097:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x3 (params) 10000000:01000000:3.0:1787761118.074716:0:27097:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-barrier-ffff8bbd940ac000 10000000:01000000:3.0:1787761118.074718:0:27097:0:(mgc_request.c:68:mgc_name2resid()) log lustre-barrier to resid 0x65727473756c/0x5 (lustre) 10000000:01000000:3.0:1787761118.074720:0:27097:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-barrier-ffff8bbd940ac000 from 1 10000000:01000000:3.0:1787761118.074722:0:27097:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-barrier (res 0x65727473756c) 00010000:00010000:3.0:1787761118.074735:0:27097:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.119@tcp lock: 000000005b037af5/0x1ae94944360d2bf1 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074742:0:27097:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.119@tcp lock: 000000005b037af5/0x1ae94944360d2bf1 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074748:0:27097:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.119@tcp lock: 000000005b037af5/0x1ae94944360d2bf1 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.074759:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631424:0@lo:101: 00000100:00100000:3.0:1787761118.074789:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.074806:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000063b2acf5 going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.074812:0:27111:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631424 00000100:00100000:1.0:1787761118.074817:0:27111:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631424 00000100:00100000:1.0:1787761118.074840:0:27111:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 4 00000100:00100000:1.0:1787761118.074853:0:27111:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000087d31f83 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+6:27097:x1874603392631424:12345-0@lo:101: 00010000:00010000:1.0:1787761118.074859:0:27111:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:1.0:1787761118.074865:0:27111:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 000000006ca828ac/0x1ae94944360d2bf8 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x1ae94944360d2bf1 expref: -99 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.074873:0:27111:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 000000006ca828ac/0x1ae94944360d2bf8 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x1ae94944360d2bf1 expref: 7 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.074878:0:27111:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 000000006ca828ac/0x1ae94944360d2bf8 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x1ae94944360d2bf1 expref: 7 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.074882:0:27111:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 000000006ca828ac, rc 0) 00000100:00100000:1.0:1787761118.074903:0:27111:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000087d31f83 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+7:27097:x1874603392631424:12345-0@lo:101: Request processed in 59us (115us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.074908:0:27111:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 4 00000100:00100000:3.0:1787761118.074938:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631424:0@lo:101: 00010000:00010000:3.0:1787761118.074947:0:27097:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.119@tcp lock: 000000005b037af5/0x1ae94944360d2bf1 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2bf8 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074953:0:27097:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.119@tcp lock: 000000005b037af5/0x1ae94944360d2bf1 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x1ae94944360d2bf8 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761118.074962:0:27097:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.202.119@tcp: configuration from log 'lustre-barrier' succeeded (0). 00010000:00010000:3.0:1787761118.074971:0:27097:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.119@tcp lock: 000000005b037af5/0x1ae94944360d2bf1 lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2bf8 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.074977:0:27097:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.119@tcp lock: 000000005b037af5/0x1ae94944360d2bf1 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2bf8 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761118.074984:0:27097:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-MDT0000-0000000000000000 10000000:01000000:3.0:1787761118.074988:0:27097:0:(mgc_request.c:68:mgc_name2resid()) log lustre-MDT0000 to resid 0x65727473756c/0x0 (lustre) 10000000:01000000:3.0:1787761118.074992:0:27097:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-mdtir-ffff8bbd940ac000 10000000:01000000:3.0:1787761118.074995:0:27097:0:(mgc_request.c:68:mgc_name2resid()) log lustre-mdtir to resid 0x65727473756c/0x2 (lustre) 10000000:01000000:3.0:1787761118.074997:0:27097:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-MDT0000-0000000000000000 from 1 10000000:01000000:3.0:1787761118.074999:0:27097:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-MDT0000 (res 0x65727473756c) 00010000:00010000:3.0:1787761118.075010:0:27097:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.119@tcp lock: 00000000097664e4/0x1ae94944360d2bff lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.075016:0:27097:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.119@tcp lock: 00000000097664e4/0x1ae94944360d2bff lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.075022:0:27097:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.119@tcp lock: 00000000097664e4/0x1ae94944360d2bff lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.075038:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631552:0@lo:101: 00000100:00100000:3.0:1787761118.075080:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.075102:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000063b2acf5 going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.075109:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631552 00000100:00100000:1.0:1787761118.075114:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631552 00000100:00100000:1.0:1787761118.075154:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 5 00000100:00100000:1.0:1787761118.075159:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000c54de17e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+7:27097:x1874603392631552:12345-0@lo:101: 00010000:00010000:1.0:1787761118.075165:0:27113:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:1.0:1787761118.075171:0:27113:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 00000000653dd013/0x1ae94944360d2c06 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: local remote: 0x1ae94944360d2bff expref: -99 pid: 27113 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.075194:0:27113:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000653dd013/0x1ae94944360d2c06 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x1ae94944360d2bff expref: 8 pid: 27113 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.075201:0:27113:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 00000000653dd013/0x1ae94944360d2c06 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x1ae94944360d2bff expref: 8 pid: 27113 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.075207:0:27113:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 00000000653dd013, rc 0) 00000100:00100000:1.0:1787761118.075239:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000c54de17e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+8:27097:x1874603392631552:12345-0@lo:101: Request processed in 80us (159us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.075244:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 5 00000100:00100000:3.0:1787761118.075266:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631552:0@lo:101: 00010000:00010000:3.0:1787761118.075277:0:27097:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.119@tcp lock: 00000000097664e4/0x1ae94944360d2bff lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2c06 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.075285:0:27097:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.119@tcp lock: 00000000097664e4/0x1ae94944360d2bff lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x1000000000000 nid: local remote: 0x1ae94944360d2c06 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.075330:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631680:0@lo:501: 00000100:00100000:3.0:1787761118.075355:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.075374:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000063b2acf5 going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.075396:0:27111:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631680 00000100:00100000:1.0:1787761118.075400:0:27111:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631680 00000100:00100000:1.0:1787761118.075423:0:27111:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 6 00000100:00100000:1.0:1787761118.075427:0:27111:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000098c24fc8 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+8:27097:x1874603392631680:12345-0@lo:501: 00000100:00100000:1.0:1787761118.075493:0:27111:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000098c24fc8 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27097:x1874603392631680:12345-0@lo:501: Request processed in 66us (138us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.075499:0:27111:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 6 00000100:00100000:3.0:1787761118.075521:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631680:0@lo:501: 00000100:00100000:3.0:1787761118.075545:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631808:0@lo:503: 00000100:00100000:3.0:1787761118.075592:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.075607:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000063b2acf5 going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.075616:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631808 00000100:00100000:1.0:1787761118.075621:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631808 00000100:00100000:1.0:1787761118.075640:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 7 00000100:00100000:1.0:1787761118.075646:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000009ab38e85 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27097:x1874603392631808:12345-0@lo:503: 00000100:00100000:1.0:1787761118.076235:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000009ab38e85 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27097:x1874603392631808:12345-0@lo:503: Request processed in 590us (644us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.076242:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 7 00000100:00100000:3.0:1787761118.076278:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392631808:0@lo:503: 00000100:00100000:3.0:1787761118.076527:0:27136:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27136:1874603392631936:0@lo:502: 00000100:00100000:3.0:1787761118.076556:0:27136:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761118.076581:0:27111:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392631936 00000100:00100000:1.0:1787761118.076585:0:27111:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392631936 00000100:00100000:3.0:1787761118.076586:0:27136:0:(client.c:2715:ptlrpc_set_wait()) set 000000008300cc8e going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.076610:0:27111:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 8 00000100:00100000:1.0:1787761118.076618:0:27111:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000883c27ec pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27136:x1874603392631936:12345-0@lo:502: 00000100:00100000:1.0:1787761118.076932:0:27111:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000883c27ec pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27136:x1874603392631936:12345-0@lo:502: Request processed in 314us (375us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.076937:0:27111:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 8 00000100:00100000:3.0:1787761118.076963:0:27136:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009fe3eb78 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27136:1874603392631936:0@lo:502: 00000020:01000000:3.0:1787761118.076979:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:3.0:1787761118.076986:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:3.0:1787761118.076991:0:27136:0:(obd_config.c:1563:class_process_config()) marker 2 (0x1) lustre-MDT0000-m lov setup 00000020:01000000:3.0:1787761118.076994:0:27136:0:(obd_config.c:1967:class_config_llog_handler()) For 2.x interoperability, rename obd type from lov to lod (lustre-MDT0000) 00000020:00000080:3.0:1787761118.076996:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:3.0:1787761118.077004:0:27136:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-mdtlov (00000000f1d256e4) 00000020:00000080:3.0:1787761118.077017:0:27136:0:(obd_config.c:720:class_attach_name()) OBD: dev 4 attached type lod with refcount 2 00000020:00000080:3.0:1787761118.077022:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00080000:01000000:2.0:1787761118.077125:0:27136:0:(osd_handler.c:8895:osd_obd_connect()) connect #2 00000020:00000080:2.0:1787761118.077141:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2c14 00000020:00000080:2.0:1787761118.077331:0:27136:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-mdtlov (uuid lustre-MDT0000-mdtlov_UUID) 00000020:01000000:2.0:1787761118.077336:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:2.0:1787761118.077339:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:2.0:1787761118.077341:0:27136:0:(obd_config.c:1563:class_process_config()) marker 2 (0x2) lustre-MDT0000-m lov setup 00000020:01000000:2.0:1787761118.077344:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:2.0:1787761118.077351:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:2.0:1787761118.077353:0:27136:0:(obd_config.c:1563:class_process_config()) marker 3 (0x1) lustre-MDT0000 add mdt 00000020:00000080:2.0:1787761118.077356:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:2.0:1787761118.077362:0:27136:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000 (00000000a3b18441) 00000020:00000080:2.0:1787761118.077371:0:27136:0:(obd_config.c:720:class_attach_name()) OBD: dev 5 attached type mdt with refcount 2 00000020:00000080:2.0:1787761118.077375:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf007 00000020:00000080:2.0:1787761118.077376:0:27136:0:(obd_config.c:1516:class_process_config()) mountopt: profile lustre-MDT0000 osc lustre-MDT0000-mdtlov mdc (null) 00000020:01000000:2.0:1787761118.077379:0:27136:0:(obd_config.c:1149:class_add_profile()) Add profile lustre-MDT0000 00000020:00000080:2.0:1787761118.077384:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00000020:01000004:2.0:1787761118.077424:0:27136:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000e473d46f from lustre-MDT0000, refs=3 00000020:00000080:2.0:1787761118.077433:0:27136:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDD0000 (00000000a51411c7) 00000020:00000080:2.0:1787761118.077440:0:27136:0:(obd_config.c:720:class_attach_name()) OBD: dev 6 attached type mdd with refcount 2 00000004:01000000:2.0:1787761118.077480:0:27136:0:(lod_dev.c:2291:lod_obd_connect()) connect #0 00000020:00000080:2.0:1787761118.077484:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-mdtlov_UUID, cookie 0x1ae94944360d2c29 00000020:00000080:2.0:1787761118.077560:0:27136:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDD0000 (uuid lustre-MDD0000_UUID) 00000004:01000000:2.0:1787761118.077565:0:27136:0:(mdd_device.c:1598:mdd_obd_connect()) connect #0 00000020:00000080:2.0:1787761118.077569:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDD0000_UUID, cookie 0x1ae94944360d2c30 00080000:01000000:2.0:1787761118.077573:0:27136:0:(osd_handler.c:8895:osd_obd_connect()) connect #3 00000020:00000080:2.0:1787761118.077575:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2c37 00010000:00010000:2.0:1787761118.113121:0:27136:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-mdt-lustre-MDT0000_UUID-1 is initialized 00000001:00000004:2.0:1787761118.114201:0:27136:0:(tgt_lastrcvd.c:727:tgt_server_data_update()) lustre-MDT0000_UUID: mount_count is 3, last_transno is 8589935177 00000001:00080000:2.0:1787761118.114487:0:27136:0:(tgt_lastrcvd.c:222:tgt_reply_header_read()) lustre-MDT0000: read reply_data header. magic=0xbdabda01 header_size=32 reply_size=32 00000020:00000080:2.0:1787761118.114972:0:27136:0:(genops.c:413:class_newdev()) Allocate new device lustre-QMT0000 (0000000026f7de53) 00000020:00000080:2.0:1787761118.114990:0:27136:0:(obd_config.c:720:class_attach_name()) OBD: dev 7 attached type qmt with refcount 2 00080000:01000000:2.0:1787761118.115128:0:27136:0:(osd_handler.c:8895:osd_obd_connect()) connect #4 00000020:00000080:2.0:1787761118.115135:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2c45 00000020:00000080:1.0:1787761118.117003:0:27136:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-QMT0000 (uuid lustre-QMT0000_UUID) 00000020:00000080:1.0:1787761118.120840:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-QMT0000_UUID, cookie 0x1ae94944360d2c4c 00000020:00000080:3.0:1787761118.121160:0:27136:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000 (uuid lustre-MDT0000_UUID) 00000020:01000000:3.0:1787761118.121172:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:3.0:1787761118.121178:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:3.0:1787761118.121180:0:27136:0:(obd_config.c:1563:class_process_config()) marker 3 (0x2) lustre-MDT0000 add mdt 00000020:01000000:3.0:1787761118.121184:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:3.0:1787761118.121187:0:27136:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #9 00000020:01000000:3.0:1787761118.121188:0:27136:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:3.0:1787761118.121190:0:27136:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:3.0:1787761118.121192:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:3.0:1787761118.121195:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:3.0:1787761118.121196:0:27136:0:(obd_config.c:1563:class_process_config()) marker 9 (0x6) lustre sys.timeout 00000020:01000000:3.0:1787761118.121199:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:3.0:1787761118.121203:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:3.0:1787761118.121205:0:27136:0:(obd_config.c:1563:class_process_config()) marker 10 (0x1) lustre-MDT0000 mdt.identity_upcall 00000020:00000080:3.0:1787761118.121209:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00f 00000004:01000000:3.0:1787761118.121254:0:27136:0:(mdt_lproc.c:316:identity_upcall_store()) lustre-MDT0000: identity upcall set to /home/green/git/lustre-release/lustre/utils/l_getidentity 00000020:01000000:3.0:1787761118.121272:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:3.0:1787761118.121275:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:3.0:1787761118.121277:0:27136:0:(obd_config.c:1563:class_process_config()) marker 10 (0x2) lustre-MDT0000 mdt.identity_upcall 00000020:01000000:3.0:1787761118.121279:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:3.0:1787761118.121283:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:3.0:1787761118.121284:0:27136:0:(obd_config.c:1563:class_process_config()) marker 17 (0x1) lustre-MDT0001 add osp 00000020:00000080:3.0:1787761118.121288:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf005 00000020:00000080:3.0:1787761118.121304:0:27136:0:(obd_config.c:1487:class_process_config()) adding mapping from uuid 192.168.202.119@tcp to nid 0x20000c0a8ca77 (192.168.202.119@tcp) 00000020:00000080:3.0:1787761118.121481:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:3.0:1787761118.121494:0:27136:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0001-osp-MDT0000 (0000000081cb58f8) 00000020:00000080:3.0:1787761118.121507:0:27136:0:(obd_config.c:720:class_attach_name()) OBD: dev 8 attached type osp with refcount 2 00000020:00000080:3.0:1787761118.121520:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00000004:00080000:3.0:1787761118.121588:0:27136:0:(osp_dev.c:1203:osp_init0()) lustre-MDT0001-osp-MDT0000: connect to lustre-MDT0000-osd (lustre-MDT0001-osp-MDT0000) 00080000:01000000:3.0:1787761118.121594:0:27136:0:(osd_handler.c:8895:osd_obd_connect()) connect #5 00000020:00000080:3.0:1787761118.121602:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2c5a 00010000:00080000:3.0:1787761118.121643:0:27136:0:(ldlm_lib.c:102:import_set_conn()) imp 000000007585f9aa@lustre-MDT0001-osp-MDT0000: add connection 192.168.202.119@tcp at head 00010000:00010000:3.0:1787761118.124753:0:27136:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-lustre-MDT0001-osp-MDT0000-1 is initialized 00000020:00000080:1.0:1787761118.125788:0:27136:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0001-osp-MDT0000 (uuid lustre-MDT0000-mdtlov_UUID) 00000020:00000080:1.0:1787761118.125797:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf014 00000004:01000000:1.0:1787761118.125840:0:27136:0:(lod_lov.c:128:lod_add_device()) osp:lustre-MDT0001_UUID idx:1 gen:1 00000020:00000080:1.0:1787761118.125855:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-mdtlov_UUID, cookie 0x1ae94944360d2c61 00000100:00080000:1.0:1787761118.125863:0:27136:0:(import.c:510:import_select_connection()) lustre-MDT0001-osp-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:1.0:1787761118.125867:0:27136:0:(import.c:624:import_select_connection()) lustre-MDT0001-osp-MDT0000: import 000000007585f9aa using connection 192.168.202.119@tcp/0@lo 00000100:00100000:1.0:1787761118.125899:0:27136:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@000000009d806d00 x1874603392632064/t0(0) o38->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 520/544 e 0 to 0 dl 0 ref 1 fl New:NQU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 00000100:00080000:1.0:1787761118.125926:0:27136:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import lustre-MDT0000-mdtlov_UUID->lustre-MDT0001_UUID 00000020:01000000:1.0:1787761118.125978:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761118.125982:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.125984:0:27136:0:(obd_config.c:1563:class_process_config()) marker 17 (0x2) lustre-MDT0001 add osp 00000020:01000000:1.0:1787761118.125987:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:1.0:1787761118.125989:0:27136:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #20 00000020:01000000:1.0:1787761118.125991:0:27136:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:1.0:1787761118.125993:0:27136:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:1.0:1787761118.125994:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:1.0:1787761118.125997:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.125999:0:27136:0:(obd_config.c:1563:class_process_config()) marker 20 (0x6) lustre sys.timeout 00000100:00100000:2.0:1787761118.125999:0:26231:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000009d806d00 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-mdtlov_UUID:26231:1874603392632064:0@lo:38: 00000020:01000000:1.0:1787761118.126002:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:01000004:1.0:1787761118.126008:0:27136:0:(obd_mount.c:961:lustre_check_exclusion()) Check exclusion lustre-OST0000 (0) in 0 of /dev/mapper/mds1_flakey 00000020:00000080:1.0:1787761118.126012:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.126014:0:27136:0:(obd_config.c:1563:class_process_config()) marker 22 (0x1) lustre-OST0000 add osc 00000020:00000080:1.0:1787761118.126017:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf005 00000020:00000080:1.0:1787761118.126025:0:27136:0:(obd_config.c:1487:class_process_config()) adding mapping from uuid 192.168.202.119@tcp to nid 0x20000c0a8ca77 (192.168.202.119@tcp) 00000020:01000000:1.0:1787761118.126153:0:27136:0:(obd_config.c:1974:class_config_llog_handler()) For 2.x interoperability, rename obd type from osc to osp (lustre-MDT0000) 00000020:00000080:1.0:1787761118.126157:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:1.0:1787761118.126167:0:27136:0:(genops.c:413:class_newdev()) Allocate new device lustre-OST0000-osc-MDT0000 (00000000d7f91816) 00000020:00000080:1.0:1787761118.126178:0:27136:0:(obd_config.c:720:class_attach_name()) OBD: dev 9 attached type osp with refcount 2 00000020:00000080:1.0:1787761118.126184:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00000004:00080000:1.0:1787761118.126257:0:27136:0:(osp_dev.c:1203:osp_init0()) lustre-OST0000-osc-MDT0000: connect to lustre-MDT0000-osd (lustre-OST0000-osc-MDT0000) 00000100:00100000:2.0:1787761118.126257:0:26231:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00080000:01000000:1.0:1787761118.126264:0:27136:0:(osd_handler.c:8895:osd_obd_connect()) connect #6 00000020:00000080:1.0:1787761118.126270:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2c6f 00010000:00080000:1.0:1787761118.126293:0:27136:0:(ldlm_lib.c:102:import_set_conn()) imp 00000000face0306@lustre-OST0000-osc-MDT0000: add connection 192.168.202.119@tcp at head 00000100:00100000:0.0:1787761118.126357:0:27123:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392632064 00000100:00100000:0.0:1787761118.126363:0:27123:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392632064 00000100:00100000:0.0:1787761118.126399:0:27123:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:0.0:1787761118.126405:0:27123:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000a622025a pname:cluuid+ref:pid:xid:nid:opc:job mdt_out00_000:0+-99:26231:x1874603392632064:12345-0@lo:38: 00010000:00020000:0.0:1787761118.126416:0:27123:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. 00000100:00100000:0.0:1787761118.126491:0:27123:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000a622025a pname:cluuid+ref:pid:xid:nid:opc:job mdt_out00_000:0+-99:26231:x1874603392632064:12345-0@lo:38: Request processed in 85us (235us total) trans 0 rc -19/-19 00000100:00100000:0.0:1787761118.126497:0:27123:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00080000:2.0:1787761118.126520:0:26231:0:(import.c:65:import_set_state_nolock()) 000000007585f9aa lustre-MDT0001_UUID: changing import state from CONNECTING to DISCONN 00000100:00080000:2.0:1787761118.126533:0:26231:0:(import.c:1511:ptlrpc_connect_interpret()) recovery of lustre-MDT0001_UUID on 0@lo failed (-19) 00000100:00100000:2.0:1787761118.126537:0:26231:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000009d806d00 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-mdtlov_UUID:26231:1874603392632064:0@lo:38: 00010000:00010000:1.0:1787761118.126594:0:27136:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-lustre-OST0000-osc-MDT0000-2 is initialized 00000040:01000000:1.0:1787761118.127615:0:27136:0:(llog_osd.c:2246:llog_osd_get_cat_list()) cat list: disk size=64, read=32 00000040:01000000:1.0:1787761118.128289:0:27136:0:(llog_obd.c:197:llog_setup()) obd lustre-OST0000-osc-MDT0000 ctxt 2 is initialized 00000040:00080000:1.0:1787761118.130009:0:27136:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:3.0:1787761118.130335:0:27136:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0x2:0x0].3, 64 off8384 00000040:00080000:3.0:1787761118.133331:0:27136:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0xc:0x0].1, 64 off8256 00000040:00080000:3.0:1787761118.133863:0:27142:0:(llog.c:805:llog_process_thread()) index: 3, lh_last_idx: 3 synced_idx: 3 lgh_last_idx: 3 00000040:00080000:3.0:1787761118.133867:0:27142:0:(llog_cat.c:163:llog_cat_process_common()) processing log [0x1:0xc:0x0] at index 3 of catalog [0x1:0x2:0x0] 00000020:00000080:1.0:1787761118.134644:0:27136:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-OST0000-osc-MDT0000 (uuid lustre-MDT0000-mdtlov_UUID) 00000020:00000080:1.0:1787761118.134655:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00d 00000004:01000000:1.0:1787761118.134753:0:27136:0:(lod_lov.c:128:lod_add_device()) osp:lustre-OST0000_UUID idx:0 gen:1 00000020:00000080:1.0:1787761118.134769:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-mdtlov_UUID, cookie 0x1ae94944360d2c76 00000100:00080000:1.0:1787761118.134776:0:27136:0:(import.c:510:import_select_connection()) lustre-OST0000-osc-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:1.0:1787761118.134781:0:27136:0:(import.c:624:import_select_connection()) lustre-OST0000-osc-MDT0000: import 00000000face0306 using connection 192.168.202.119@tcp/0@lo 00000100:00100000:1.0:1787761118.134809:0:27136:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@00000000cf88db9b x1874603392632192/t0(0) o8->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 520/544 e 0 to 0 dl 0 ref 1 fl New:NQU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 00000100:00080000:1.0:1787761118.134838:0:27136:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import lustre-MDT0000-mdtlov_UUID->lustre-OST0000_UUID 00000020:01000000:1.0:1787761118.134894:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761118.134899:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.134901:0:27136:0:(obd_config.c:1563:class_process_config()) marker 22 (0x2) lustre-OST0000 add osc 00000020:01000000:1.0:1787761118.134904:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:1.0:1787761118.134907:0:27136:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #28 00000020:01000000:1.0:1787761118.134909:0:27136:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:1.0:1787761118.134911:0:27136:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:1.0:1787761118.134912:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:1.0:1787761118.134920:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.134921:0:27136:0:(obd_config.c:1563:class_process_config()) marker 28 (0x6) lustre sys.timeout 00000020:01000000:1.0:1787761118.134924:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:01000004:1.0:1787761118.134928:0:27136:0:(obd_mount.c:961:lustre_check_exclusion()) Check exclusion lustre-OST0001 (1) in 0 of /dev/mapper/mds1_flakey 00000020:00000080:1.0:1787761118.134931:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.134932:0:27136:0:(obd_config.c:1563:class_process_config()) marker 30 (0x1) lustre-OST0001 add osc 00000020:00000080:1.0:1787761118.134935:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf005 00000020:00000080:1.0:1787761118.134937:0:27136:0:(obd_config.c:1487:class_process_config()) adding mapping from uuid 192.168.202.119@tcp to nid 0x20000c0a8ca77 (192.168.202.119@tcp) 00000100:00100000:2.0:1787761118.135029:0:26231:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000cf88db9b pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-mdtlov_UUID:26231:1874603392632192:0@lo:8: 00000400:00000100:2.0:1787761118.135102:0:26231:0:(lib-move.c:4357:lnet_parse_put()) Dropping PUT from 12345-0@lo portal 28 match 1874603392632192 offset 0 length 520: 4 00000020:01000000:1.0:1787761118.135261:0:27136:0:(obd_config.c:1974:class_config_llog_handler()) For 2.x interoperability, rename obd type from osc to osp (lustre-MDT0000) 00000020:00000080:1.0:1787761118.135263:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:1.0:1787761118.135273:0:27136:0:(genops.c:413:class_newdev()) Allocate new device lustre-OST0001-osc-MDT0000 (000000007cf6c683) 00000020:00000080:1.0:1787761118.135283:0:27136:0:(obd_config.c:720:class_attach_name()) OBD: dev 10 attached type osp with refcount 2 00000020:00000080:1.0:1787761118.135288:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00000004:00080000:1.0:1787761118.135355:0:27136:0:(osp_dev.c:1203:osp_init0()) lustre-OST0001-osc-MDT0000: connect to lustre-MDT0000-osd (lustre-OST0001-osc-MDT0000) 00080000:01000000:1.0:1787761118.135361:0:27136:0:(osd_handler.c:8895:osd_obd_connect()) connect #7 00000020:00000080:1.0:1787761118.135366:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x1ae94944360d2c84 00010000:00080000:1.0:1787761118.135393:0:27136:0:(ldlm_lib.c:102:import_set_conn()) imp 000000002bfb1749@lustre-OST0001-osc-MDT0000: add connection 192.168.202.119@tcp at head 00010000:00010000:1.0:1787761118.135584:0:27136:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-lustre-OST0001-osc-MDT0000-3 is initialized 00000040:01000000:1.0:1787761118.135654:0:27136:0:(llog_osd.c:2246:llog_osd_get_cat_list()) cat list: disk size=64, read=32 00000040:01000000:1.0:1787761118.135667:0:27136:0:(llog_obd.c:197:llog_setup()) obd lustre-OST0001-osc-MDT0000 ctxt 2 is initialized 00000040:00080000:1.0:1787761118.137148:0:27136:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:1.0:1787761118.137379:0:27136:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0x5:0x0].3, 64 off8384 00000040:00080000:1.0:1787761118.137522:0:27136:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0xe:0x0].1, 64 off8256 00000040:00080000:3.0:1787761118.138083:0:27144:0:(llog.c:805:llog_process_thread()) index: 3, lh_last_idx: 3 synced_idx: 3 lgh_last_idx: 3 00000040:00080000:3.0:1787761118.138086:0:27144:0:(llog_cat.c:163:llog_cat_process_common()) processing log [0x1:0xe:0x0] at index 3 of catalog [0x1:0x5:0x0] 00000020:00000080:1.0:1787761118.138803:0:27136:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-OST0001-osc-MDT0000 (uuid lustre-MDT0000-mdtlov_UUID) 00000020:00000080:1.0:1787761118.138812:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00d 00000004:01000000:1.0:1787761118.138839:0:27136:0:(lod_lov.c:128:lod_add_device()) osp:lustre-OST0001_UUID idx:1 gen:1 00000020:00000080:1.0:1787761118.138853:0:27136:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-mdtlov_UUID, cookie 0x1ae94944360d2c8b 00000100:00080000:1.0:1787761118.138861:0:27136:0:(import.c:510:import_select_connection()) lustre-OST0001-osc-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:1.0:1787761118.138866:0:27136:0:(import.c:624:import_select_connection()) lustre-OST0001-osc-MDT0000: import 000000002bfb1749 using connection 192.168.202.119@tcp/0@lo 00000100:00100000:1.0:1787761118.138891:0:27136:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@0000000086d25f31 x1874603392632320/t0(0) o8->lustre-OST0001-osc-MDT0000@0@lo:28/4 lens 520/544 e 0 to 0 dl 0 ref 1 fl New:NQU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 00000100:00100000:2.0:1787761118.139005:0:26231:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000086d25f31 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-mdtlov_UUID:26231:1874603392632320:0@lo:8: 00000400:00000100:2.0:1787761118.139239:0:26231:0:(lib-move.c:4357:lnet_parse_put()) Dropping PUT from 12345-0@lo portal 28 match 1874603392632320 offset 0 length 520: 4 00000100:00080000:1.0:1787761118.139309:0:27136:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import lustre-MDT0000-mdtlov_UUID->lustre-OST0001_UUID 00000020:01000000:1.0:1787761118.139369:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761118.139374:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.139375:0:27136:0:(obd_config.c:1563:class_process_config()) marker 30 (0x2) lustre-OST0001 add osc 00000020:01000000:1.0:1787761118.139378:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:1.0:1787761118.139381:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.139383:0:27136:0:(obd_config.c:1563:class_process_config()) marker 37 (0x1) lustre sys.timeout 00000020:00000080:1.0:1787761118.139386:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf009 00000020:00000080:1.0:1787761118.139387:0:27136:0:(obd_config.c:1537:class_process_config()) changing lustre timeout from 100 to 20 00000020:01000000:1.0:1787761118.139389:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761118.139391:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.139392:0:27136:0:(obd_config.c:1563:class_process_config()) marker 37 (0x2) lustre sys.timeout 00000020:01000000:1.0:1787761118.139394:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:1.0:1787761118.139396:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.139397:0:27136:0:(obd_config.c:1563:class_process_config()) marker 42 (0x1) lustre sys.jobid_var 00000020:00000080:1.0:1787761118.139400:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00f 00000100:00100000:1.0:1787761118.139429:0:27136:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000b599d7bf pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27136:1874603392632448:0@lo:502:llog_process_th.0 00000100:00100000:1.0:1787761118.139478:0:27136:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761118.139509:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392632448 00000100:00100000:1.0:1787761118.139514:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392632448 00000100:00100000:1.0:1787761118.139548:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 9 00000100:00100000:1.0:1787761118.139555:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000747e7e0f pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27136:x1874603392632448:12345-0@lo:502:llog_process_th.0 00000100:00100000:1.0:1787761118.139639:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000747e7e0f pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27136:x1874603392632448:12345-0@lo:502:llog_process_th.0 Request processed in 83us (161us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.139647:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 9 00000100:00100000:1.0:1787761118.139694:0:27136:0:(client.c:2715:ptlrpc_set_wait()) set 00000000b46887fd going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.139712:0:27136:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000b599d7bf pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27136:1874603392632448:0@lo:502:llog_process_th.0 00000020:01000000:1.0:1787761118.139732:0:27136:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761118.139739:0:27136:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761118.139740:0:27136:0:(obd_config.c:1563:class_process_config()) marker 42 (0x2) lustre sys.jobid_var 00000040:00080000:1.0:1787761118.139743:0:27136:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 46 count 46 00000020:01000000:2.0:1787761118.139952:0:27097:0:(obd_config.c:2145:class_config_parse_llog()) Processed log lustre-MDT0000 gen 1-45 (rc=0) 10000000:01000000:2.0:1787761118.139973:0:27097:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.202.119@tcp: configuration from log 'lustre-MDT0000' succeeded (0). 00010000:00010000:2.0:1787761118.139990:0:27097:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.119@tcp lock: 00000000097664e4/0x1ae94944360d2bff lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2c06 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.140000:0:27097:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.119@tcp lock: 00000000097664e4/0x1ae94944360d2bff lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2c06 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:2.0:1787761118.140007:0:27097:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-mdtir-ffff8bbd940ac000 from 1 10000000:01000000:2.0:1787761118.140010:0:27097:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-mdtir (res 0x65727473756c) 00010000:00010000:2.0:1787761118.140043:0:27097:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.119@tcp lock: 000000006baa884d/0x1ae94944360d2c92 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.140068:0:27097:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.119@tcp lock: 000000006baa884d/0x1ae94944360d2c92 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.140076:0:27097:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.119@tcp lock: 000000006baa884d/0x1ae94944360d2c92 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1787761118.140089:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632576:0@lo:101:mount.lustre.0 00000100:00100000:2.0:1787761118.140116:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761118.140133:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000006b662fb going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.140252:0:27111:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392632576 00000100:00100000:1.0:1787761118.140257:0:27111:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392632576 00000100:00100000:1.0:1787761118.140288:0:27111:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 10 00000100:00100000:1.0:1787761118.140295:0:27111:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000444f9f94 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+9:27097:x1874603392632576:12345-0@lo:101:mount.lustre.0 00010000:00010000:1.0:1787761118.140302:0:27111:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:1.0:1787761118.140324:0:27111:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 00000000e31b3caf/0x1ae94944360d2c99 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x1ae94944360d2c92 expref: -99 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.140342:0:27111:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000e31b3caf/0x1ae94944360d2c99 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 10 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.140352:0:27111:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 00000000e31b3caf/0x1ae94944360d2c99 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 10 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.140360:0:27111:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 00000000e31b3caf, rc 0) 00000100:00100000:1.0:1787761118.140384:0:27111:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000444f9f94 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+10:27097:x1874603392632576:12345-0@lo:101:mount.lustre.0 Request processed in 91us (268us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.140389:0:27111:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 10 00000100:00100000:2.0:1787761118.140647:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632576:0@lo:101:mount.lustre.0 00010000:00010000:2.0:1787761118.140666:0:27097:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.119@tcp lock: 000000006baa884d/0x1ae94944360d2c92 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.140684:0:27097:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.119@tcp lock: 000000006baa884d/0x1ae94944360d2c92 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1787761118.141346:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632704:0@lo:256:mount.lustre.0 00000100:00100000:2.0:1787761118.141384:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761118.141418:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000006b662fb going to sleep for 11 seconds 00000100:00100000:0.0:1787761118.141421:0:27112:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392632704 00000100:00100000:0.0:1787761118.141427:0:27112:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392632704 00000100:00100000:0.0:1787761118.141497:0:27112:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 11 00000100:00100000:0.0:1787761118.141505:0:27112:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000fc2d668d pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+10:27097:x1874603392632704:12345-0@lo:256:mount.lustre.0 20000000:01000000:0.0:1787761118.141523:0:27112:0:(mgs_nids.c:914:mgs_get_ir_logs()) Reading IR log lustre-mdtir bufsize 1048576. 20000000:01000000:0.0:1787761118.141528:0:27112:0:(mgs_nids.c:318:mgs_nidtbl_read()) Read IR logs lustre return with 0, version 1 00000100:00100000:0.0:1787761118.141594:0:27112:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000fc2d668d pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+10:27097:x1874603392632704:12345-0@lo:256:mount.lustre.0 Request processed in 90us (211us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761118.141602:0:27112:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 11 00000100:00100000:2.0:1787761118.141613:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632704:0@lo:256:mount.lustre.0 10000000:01000000:2.0:1787761118.142248:0:27097:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.202.119@tcp: configuration from log 'lustre-mdtir' succeeded (0). 00010000:00010000:2.0:1787761118.142267:0:27097:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.119@tcp lock: 000000006baa884d/0x1ae94944360d2c92 lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.142275:0:27097:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.119@tcp lock: 000000006baa884d/0x1ae94944360d2c92 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:2.0:1787761118.142281:0:27097:0:(mgc_request.c:1802:mgc_process_log()) Process log params-ffff8bbd940ac000 from 1 10000000:01000000:2.0:1787761118.142284:0:27097:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for params (res 0x736d61726170) 00010000:00010000:2.0:1787761118.142299:0:27097:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.119@tcp lock: 00000000ea1e8254/0x1ae94944360d2ca0 lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.142304:0:27097:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.119@tcp lock: 00000000ea1e8254/0x1ae94944360d2ca0 lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.142327:0:27097:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.119@tcp lock: 00000000ea1e8254/0x1ae94944360d2ca0 lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1787761118.142340:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632832:0@lo:101:mount.lustre.0 00000100:00100000:2.0:1787761118.142369:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761118.142402:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392632832 00000100:00100000:2.0:1787761118.142404:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000006b662fb going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.142408:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392632832 00000100:00100000:1.0:1787761118.142436:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 12 00000100:00100000:1.0:1787761118.142442:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000003e39eb34 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+10:27097:x1874603392632832:12345-0@lo:101:mount.lustre.0 00010000:00010000:1.0:1787761118.142450:0:27113:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:1.0:1787761118.142464:0:27113:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 0000000011b436d0/0x1ae94944360d2ca7 lrc: 2/0,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x1ae94944360d2ca0 expref: -99 pid: 27113 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.142477:0:27113:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 0000000011b436d0/0x1ae94944360d2ca7 lrc: 3/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x1ae94944360d2ca0 expref: 11 pid: 27113 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.142491:0:27113:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 0000000011b436d0/0x1ae94944360d2ca7 lrc: 3/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x1ae94944360d2ca0 expref: 11 pid: 27113 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.142498:0:27113:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 0000000011b436d0, rc 0) 00000100:00100000:1.0:1787761118.142528:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000003e39eb34 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27097:x1874603392632832:12345-0@lo:101:mount.lustre.0 Request processed in 86us (158us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.142534:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 12 00000100:00100000:2.0:1787761118.142557:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632832:0@lo:101:mount.lustre.0 00010000:00010000:2.0:1787761118.142568:0:27097:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.119@tcp lock: 00000000ea1e8254/0x1ae94944360d2ca0 lrc: 4/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2ca7 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.142576:0:27097:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.119@tcp lock: 00000000ea1e8254/0x1ae94944360d2ca0 lrc: 4/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x1ae94944360d2ca7 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1787761118.142620:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632960:0@lo:501:mount.lustre.0 00000100:00100000:2.0:1787761118.142645:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761118.142667:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000006b662fb going to sleep for 11 seconds 00000100:00100000:0.0:1787761118.142755:0:27112:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392632960 00000100:00100000:0.0:1787761118.142759:0:27112:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392632960 00000100:00100000:0.0:1787761118.142793:0:27112:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 13 00000100:00100000:0.0:1787761118.142802:0:27112:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000006bb3332a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27097:x1874603392632960:12345-0@lo:501:mount.lustre.0 00000100:00100000:0.0:1787761118.142903:0:27112:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000006bb3332a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27097:x1874603392632960:12345-0@lo:501:mount.lustre.0 Request processed in 103us (258us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761118.142909:0:27112:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 13 00000100:00100000:2.0:1787761118.143012:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392632960:0@lo:501:mount.lustre.0 00000100:00100000:2.0:1787761118.143036:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633088:0@lo:503:mount.lustre.0 00000100:00100000:2.0:1787761118.143108:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761118.143136:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set 0000000006b662fb going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.143147:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633088 00000100:00100000:1.0:1787761118.143152:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633088 00000100:00100000:1.0:1787761118.143184:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 14 00000100:00100000:1.0:1787761118.143190:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000d8343fc2 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27097:x1874603392633088:12345-0@lo:503:mount.lustre.0 00000100:00100000:2.0:1787761118.143476:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633088:0@lo:503:mount.lustre.0 00000100:00100000:1.0:1787761118.143478:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000d8343fc2 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27097:x1874603392633088:12345-0@lo:503:mount.lustre.0 Request processed in 287us (369us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.143488:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 14 00000100:00100000:2.0:1787761118.143922:0:27146:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27146:1874603392633216:0@lo:502:llog_process_th.0 00000100:00100000:2.0:1787761118.144017:0:27146:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761118.144097:0:27146:0:(client.c:2715:ptlrpc_set_wait()) set 000000003f535133 going to sleep for 11 seconds 00000100:00100000:0.0:1787761118.144128:0:27112:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633216 00000100:00100000:0.0:1787761118.144132:0:27112:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633216 00000100:00100000:0.0:1787761118.144192:0:27112:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 15 00000100:00100000:0.0:1787761118.144199:0:27112:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000011b081f7 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27146:x1874603392633216:12345-0@lo:502:llog_process_th.0 00000100:00100000:0.0:1787761118.145325:0:27112:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000011b081f7 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27146:x1874603392633216:12345-0@lo:502:llog_process_th.0 Request processed in 1113us (1295us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761118.145332:0:27112:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 15 00000100:00100000:2.0:1787761118.145392:0:27146:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@000000006cfd0ce7 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27146:1874603392633216:0@lo:502:llog_process_th.0 00000020:01000000:2.0:1787761118.145414:0:27146:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:2.0:1787761118.145421:0:27146:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:2.0:1787761118.145422:0:27146:0:(obd_config.c:1563:class_process_config()) marker 2 (0x1) general debug_raw_pointers 00000020:01000000:2.0:1787761118.145428:0:27146:0:(obd_config.c:2004:class_config_llog_handler()) cmd ce032, instance name: general-ffff8bbd940ac000 00000020:00000080:2.0:1787761118.145436:0:27146:0:(obd_config.c:1472:class_process_config()) processing cmd: ce032 00000020:01000000:2.0:1787761118.145460:0:27146:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:2.0:1787761118.145464:0:27146:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:2.0:1787761118.145465:0:27146:0:(obd_config.c:1563:class_process_config()) marker 2 (0x2) general debug_raw_pointers 00000020:01000000:2.0:1787761118.145468:0:27146:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:2.0:1787761118.145471:0:27146:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:2.0:1787761118.145472:0:27146:0:(obd_config.c:1563:class_process_config()) marker 3 (0x1) general lod.*.mdt_hash 00000020:01000000:2.0:1787761118.145476:0:27146:0:(obd_config.c:2004:class_config_llog_handler()) cmd ce032, instance name: general-ffff8bbd940ac000 00000020:00000080:2.0:1787761118.145478:0:27146:0:(obd_config.c:1472:class_process_config()) processing cmd: ce032 00000100:00100000:2.0:1787761118.145586:0:27146:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8dcc6580 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27146:1874603392633344:0@lo:502:llog_process_th.0 00000100:00100000:2.0:1787761118.145620:0:27146:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761118.145650:0:27146:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbd86d10f00 going to sleep for 11 seconds 00000100:00100000:1.0:1787761118.145895:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633344 00000100:00100000:1.0:1787761118.145900:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633344 00000100:00100000:1.0:1787761118.145933:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 16 00000100:00100000:1.0:1787761118.145941:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5e050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27146:x1874603392633344:12345-0@lo:502:llog_process_th.0 00000100:00100000:1.0:1787761118.146014:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5e050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27146:x1874603392633344:12345-0@lo:502:llog_process_th.0 Request processed in 73us (393us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761118.146021:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 16 00000100:00100000:2.0:1787761118.146082:0:27146:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8dcc6580 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27146:1874603392633344:0@lo:502:llog_process_th.0 00000020:01000000:2.0:1787761118.146108:0:27146:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:2.0:1787761118.146114:0:27146:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:2.0:1787761118.146115:0:27146:0:(obd_config.c:1563:class_process_config()) marker 3 (0x2) general lod.*.mdt_hash 00000040:00080000:2.0:1787761118.146118:0:27146:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x2:0x0] index 7 count 7 00000020:01000000:1.0:1787761118.146201:0:27097:0:(obd_config.c:2145:class_config_parse_llog()) Processed log params gen 1-6 (rc=0) 10000000:01000000:1.0:1787761118.146221:0:27097:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.202.119@tcp: configuration from log 'params' succeeded (0). 00010000:00010000:1.0:1787761118.146237:0:27097:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1600/0x1ae94944360d2ca0 lrc: 3/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2ca7 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.146256:0:27097:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1600/0x1ae94944360d2ca0 lrc: 2/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2ca7 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:1.0:1787761118.146293:0:27097:0:(mgc_request.c:1944:mgc_process_config()) parse_log lustre-client from 0 10000000:01000000:1.0:1787761118.146296:0:27097:0:(mgc_request.c:329:config_log_add()) add config log lustre-client-ffff8bbd940ac000 10000000:01000000:1.0:1787761118.146299:0:27097:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-client-ffff8bbd940ac000 10000000:01000000:1.0:1787761118.146303:0:27097:0:(mgc_request.c:68:mgc_name2resid()) log lustre-client to resid 0x65727473756c/0x0 (lustre) 10000000:01000000:1.0:1787761118.146307:0:27097:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-client-ffff8bbd940ac000 from 1 10000000:01000000:1.0:1787761118.146310:0:27097:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-client (res 0x65727473756c) 00010000:00010000:1.0:1787761118.146340:0:27097:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.119@tcp lock: ffff8bbd9419b200/0x1ae94944360d2cae lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.146348:0:27097:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.119@tcp lock: ffff8bbd9419b200/0x1ae94944360d2cae lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761118.146356:0:27097:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.119@tcp lock: ffff8bbd9419b200/0x1ae94944360d2cae lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:1.0:1787761118.146369:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd893a1680 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633472:0@lo:101:mount.lustre.0 00000100:00100000:1.0:1787761118.146398:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761118.146425:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbd8ee4de40 going to sleep for 11 seconds 00000100:00100000:2.0:1787761118.146702:0:27112:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633472 00000100:00100000:2.0:1787761118.146707:0:27112:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633472 00000100:00100000:2.0:1787761118.146738:0:27112:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 17 00000100:00100000:2.0:1787761118.146745:0:27112:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5e850 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+11:27097:x1874603392633472:12345-0@lo:101:mount.lustre.0 00010000:00010000:2.0:1787761118.146753:0:27112:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1787761118.146763:0:27112:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: ffff8bbd93cc1400/0x1ae94944360d2cb5 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x40000000000000 nid: local remote: 0x1ae94944360d2cae expref: -99 pid: 27112 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.146781:0:27112:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: ffff8bbd93cc1400/0x1ae94944360d2cb5 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x1ae94944360d2cae expref: 12 pid: 27112 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.146792:0:27112:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: ffff8bbd93cc1400/0x1ae94944360d2cb5 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x1ae94944360d2cae expref: 12 pid: 27112 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.146811:0:27112:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock ffff8bbd93cc1400, rc 0) 00000100:00100000:2.0:1787761118.146891:0:27112:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5e850 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27097:x1874603392633472:12345-0@lo:101:mount.lustre.0 Request processed in 146us (492us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761118.146898:0:27112:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 17 00000100:00100000:3.0:1787761118.150623:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd893a1680 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633472:0@lo:101:mount.lustre.0 00010000:00010000:3.0:1787761118.150646:0:27097:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.119@tcp lock: ffff8bbd9419b200/0x1ae94944360d2cae lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2cb5 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.150659:0:27097:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.119@tcp lock: ffff8bbd9419b200/0x1ae94944360d2cae lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x1000000000000 nid: local remote: 0x1ae94944360d2cb5 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.150799:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633600:0@lo:501:mount.lustre.0 00000100:00100000:3.0:1787761118.150845:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.150887:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbeb2cc33c0 going to sleep for 11 seconds 00000100:00100000:2.0:1787761118.151011:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633600 00000100:00100000:2.0:1787761118.151017:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633600 00000100:00100000:2.0:1787761118.151122:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 18 00000100:00100000:2.0:1787761118.151133:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5d450 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27097:x1874603392633600:12345-0@lo:501:mount.lustre.0 00000100:00100000:2.0:1787761118.151245:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5d450 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27097:x1874603392633600:12345-0@lo:501:mount.lustre.0 Request processed in 114us (399us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761118.151254:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 18 00000100:00100000:3.0:1787761118.151344:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633600:0@lo:501:mount.lustre.0 00000100:00100000:3.0:1787761118.151379:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633728:0@lo:503:mount.lustre.0 00000100:00100000:3.0:1787761118.151423:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.151522:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbeb2cc33c0 going to sleep for 11 seconds 00000100:00100000:0.0:1787761118.151534:0:27112:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633728 00000100:00100000:0.0:1787761118.151538:0:27112:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633728 00000100:00100000:0.0:1787761118.151559:0:27112:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 19 00000100:00100000:0.0:1787761118.151565:0:27112:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5fc50 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27097:x1874603392633728:12345-0@lo:503:mount.lustre.0 00000100:00100000:0.0:1787761118.151637:0:27112:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5fc50 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27097:x1874603392633728:12345-0@lo:503:mount.lustre.0 Request processed in 72us (214us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761118.151645:0:27112:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 19 00000100:00100000:3.0:1787761118.151746:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392633728:0@lo:503:mount.lustre.0 00000100:00100000:3.0:1787761118.152335:0:27149:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27149:1874603392633856:0@lo:502:llog_process_th.0 00000100:00100000:3.0:1787761118.152368:0:27149:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.152423:0:27149:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbeb2cc39c0 going to sleep for 11 seconds 00000100:00100000:0.0:1787761118.152458:0:27112:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633856 00000100:00100000:0.0:1787761118.152462:0:27112:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633856 00000100:00100000:0.0:1787761118.152530:0:27112:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 20 00000100:00100000:0.0:1787761118.152538:0:27112:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5c450 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27149:x1874603392633856:12345-0@lo:502:llog_process_th.0 00000100:00100000:0.0:1787761118.152619:0:27112:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5c450 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27149:x1874603392633856:12345-0@lo:502:llog_process_th.0 Request processed in 81us (250us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761118.152626:0:27112:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 20 00000100:00100000:3.0:1787761118.152700:0:27149:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27149:1874603392633856:0@lo:502:llog_process_th.0 00000020:01000004:3.0:1787761118.152748:0:27149:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD lustre-MDT0000-lwp-MDT0000 (typ=lwp) 00000020:00000080:3.0:1787761118.152761:0:27149:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-lwp-MDT0000 (ffff8bbebff3b490) 00000020:00000080:3.0:1787761118.152778:0:27149:0:(obd_config.c:720:class_attach_name()) OBD: dev 11 attached type lwp with refcount 2 00000020:01000004:3.0:1787761118.152881:0:27149:0:(tgt_mount.c:153:server_get_mount()) get mount ffff8bbd940ac000 from lustre-MDT0000, refs=4 00000020:01000004:3.0:1787761118.152886:0:27149:0:(tgt_mount.c:187:server_put_mount()) put mount ffff8bbd940ac000 from lustre-MDT0000, refs=4 00000020:01000004:3.0:1787761118.152889:0:27149:0:(obd_mount.c:710:lustre_put_lsi()) put ffff8bbd940ac000 4 00010000:00080000:3.0:1787761118.152915:0:27149:0:(ldlm_lib.c:102:import_set_conn()) imp ffff8bbebea89000@lustre-MDT0000-lwp-MDT0000: add connection 192.168.202.119@tcp at head 00010000:00010000:3.0:1787761118.155025:0:27149:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-lustre-MDT0000-lwp-MDT0000-4 is initialized 00000020:00000080:3.0:1787761118.155370:0:27149:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-lwp-MDT0000 (uuid lustre-MDT0000-lwp-MDT0000_UUID) 00000010:01000000:3.0:1787761118.155401:0:27149:0:(lwp_dev.c:513:lwp_obd_connect()) connect #0 00000020:00000080:3.0:1787761118.155410:0:27149:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-lwp-MDT0000, cookie 0x1ae94944360d2cc3 00000100:00080000:3.0:1787761118.155417:0:27149:0:(import.c:510:import_select_connection()) lustre-MDT0000-lwp-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:3.0:1787761118.155423:0:27149:0:(import.c:624:import_select_connection()) lustre-MDT0000-lwp-MDT0000: import ffff8bbebea89000 using connection 192.168.202.119@tcp/0@lo 00000100:00100000:3.0:1787761118.155447:0:27149:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@ffff8bbd8f6f9680 x1874603392633984/t0(0) o38->lustre-MDT0000-lwp-MDT0000@0@lo:12/10 lens 520/544 e 0 to 0 dl 0 ref 1 fl New:NQU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 00000100:00100000:2.0:1787761118.155499:0:26231:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-lwp-MDT0000_UUID:26231:1874603392633984:0@lo:38:llog_process_th.0 00000100:00100000:2.0:1787761118.155561:0:26231:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00080000:3.0:1787761118.155609:0:27149:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import lustre-MDT0000-lwp-MDT0000_UUID->lustre-MDT0000_UUID 00000100:00100000:3.0:1787761118.156082:0:27118:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392633984 00000100:00100000:3.0:1787761118.156089:0:27118:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392633984 00000100:00100000:3.0:1787761118.156120:0:27118:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1787761118.156126:0:27118:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbd8dcc6580 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:0+-99:26231:x1874603392633984:12345-0@lo:38:llog_process_th.0 00000100:00100000:3.0:1787761118.158430:0:27118:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbd8dcc6580 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:0+-99:26231:x1874603392633984:12345-0@lo:38:llog_process_th.0 Request processed in 2299us (2865us total) trans 0 rc -11/-11 00000100:00100000:3.0:1787761118.158440:0:27118:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1787761118.158546:0:27149:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8f6fb0c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27149:1874603392634112:0@lo:502:llog_process_th.0 00000100:00100000:3.0:1787761118.158589:0:27149:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.158613:0:27149:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbeb2cc3b40 going to sleep for 11 seconds 00000100:00100000:2.0:1787761118.158719:0:26231:0:(client.c:3125:ptlrpc_free_committed()) lustre-MDT0000-lwp-MDT0000: committing for last_committed 0 gen 2 00000100:00080000:2.0:1787761118.158727:0:26231:0:(import.c:65:import_set_state_nolock()) ffff8bbebea89000 lustre-MDT0000_UUID: changing import state from CONNECTING to DISCONN 00000100:00080000:2.0:1787761118.158731:0:26231:0:(import.c:1511:ptlrpc_connect_interpret()) recovery of lustre-MDT0000_UUID on 0@lo failed (-11) 00000100:00100000:2.0:1787761118.158735:0:26231:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8f6f9680 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-lwp-MDT0000_UUID:26231:1874603392633984:0@lo:38:llog_process_th.0 00000100:00100000:2.0:1787761118.158764:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392634112 00000100:00100000:2.0:1787761118.158780:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392634112 00000100:00100000:2.0:1787761118.158818:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 21 00000100:00100000:2.0:1787761118.158827:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5f850 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27149:x1874603392634112:12345-0@lo:502:llog_process_th.0 00000100:00100000:2.0:1787761118.159201:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5f850 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27149:x1874603392634112:12345-0@lo:502:llog_process_th.0 Request processed in 375us (611us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761118.159209:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 21 00000100:00100000:3.0:1787761118.159925:0:27149:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8f6fb0c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27149:1874603392634112:0@lo:502:llog_process_th.0 00000100:00100000:3.0:1787761118.159965:0:27149:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8f6fb0c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27149:1874603392634240:0@lo:502:llog_process_th.0 00000100:00100000:3.0:1787761118.160000:0:27149:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.160033:0:27149:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbeb2cc3b40 going to sleep for 11 seconds 00000100:00100000:0.0:1787761118.160222:0:27111:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392634240 00000100:00100000:0.0:1787761118.160228:0:27111:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392634240 00000100:00100000:0.0:1787761118.160257:0:27111:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 22 00000100:00100000:0.0:1787761118.160266:0:27111:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5f050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27149:x1874603392634240:12345-0@lo:502:llog_process_th.0 00000100:00100000:0.0:1787761118.160369:0:27111:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5f050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27149:x1874603392634240:12345-0@lo:502:llog_process_th.0 Request processed in 104us (368us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761118.160378:0:27111:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 22 00000100:00100000:3.0:1787761118.160409:0:27149:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8f6fb0c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:c73e603f-74af-422b-8b68-88272a5bb5a4:27149:1874603392634240:0@lo:502:llog_process_th.0 00000040:00080000:3.0:1787761118.160435:0:27149:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 52 count 51 00000020:01000000:0.0:1787761118.160520:0:27097:0:(obd_config.c:2145:class_config_parse_llog()) Processed log lustre-client gen 1-51 (rc=0) 10000000:01000000:0.0:1787761118.160543:0:27097:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.202.119@tcp: configuration from log 'lustre-client' succeeded (0). 00010000:00010000:0.0:1787761118.160559:0:27097:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.119@tcp lock: ffff8bbd9419b200/0x1ae94944360d2cae lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2cb5 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:0.0:1787761118.160571:0:27097:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.119@tcp lock: ffff8bbd9419b200/0x1ae94944360d2cae lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0x1ae94944360d2cb5 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000020:01000004:0.0:1787761118.160617:0:27097:0:(tgt_mount.c:1175:server_mti_print()) mti - server_notify_target 00000020:01000004:0.0:1787761118.160619:0:27097:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:0.0:1787761118.160621:0:27097:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:0.0:1787761118.160623:0:27097:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:0.0:1787761118.160626:0:27097:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:0.0:1787761118.160628:0:27097:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:0.0:1787761118.160629:0:27097:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:0.0:1787761118.160631:0:27097:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:0.0:1787761118.160633:0:27097:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:0.0:1787761118.160635:0:27097:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 10000000:01000000:0.0:1787761118.160638:0:27097:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target lustre-MDT0000 0x40020005 00000020:01000004:0.0:1787761118.160641:0:27097:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req 00000020:01000004:0.0:1787761118.160642:0:27097:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:0.0:1787761118.160643:0:27097:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:0.0:1787761118.160645:0:27097:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:0.0:1787761118.160646:0:27097:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:0.0:1787761118.160647:0:27097:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:0.0:1787761118.160648:0:27097:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:0.0:1787761118.160649:0:27097:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:0.0:1787761118.160651:0:27097:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:0.0:1787761118.160652:0:27097:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 10000000:01000000:0.0:1787761118.160666:0:27097:0:(mgc_request_server.c:281:mgc_target_register()) register lustre-MDT0000 00000100:00100000:0.0:1787761118.160691:0:27097:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8adf2580 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392634368:0@lo:253:mount.lustre.0 00000100:00100000:0.0:1787761118.160726:0:27097:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761118.160757:0:27097:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbd906f6240 going to sleep for 11 seconds 00000100:00100000:3.0:1787761118.160896:0:27113:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392634368 00000100:00100000:3.0:1787761118.160902:0:27113:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392634368 00000100:00100000:3.0:1787761118.160933:0:27113:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 23 00000100:00100000:3.0:1787761118.160942:0:27113:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbeb1c5d050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27097:x1874603392634368:12345-0@lo:253:mount.lustre.0 20000000:01000000:3.0:1787761118.160962:0:27113:0:(mgs_handler.c:453:mgs_target_reg()) fs: lustre index: 0 is ready to reconnect. 20000000:01000000:3.0:1787761118.160976:0:27113:0:(mgs_nids.c:463:mgs_tnl_update()) nidtbl: write 1 NIDs to NET #0 20000000:01000000:3.0:1787761118.162422:0:27113:0:(mgs_nids.c:815:mgs_ir_update()) Try to revoke recover lock of lustre 20000000:01000000:3.0:1787761118.162438:0:27113:0:(mgs_handler.c:637:mgs_target_reg()) replying with lustre-MDT0000, index=0, rc=0 20000000:01000000:2.0:1787761118.162444:0:27134:0:(mgs_nids.c:712:mgs_ir_notify()) mgs_lustre_notify woken up, phase is 1 10000000:01000000:2.0:1787761118.162450:0:27134:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x2 (lustre) 00010000:00010000:2.0:1787761118.162468:0:27134:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(EX) ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 3/0,1 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.162532:0:27134:0:(ldlm_lock.c:687:ldlm_add_bl_work_item()) ### lock incompatible; sending blocking AST. ns: MGS lock: ffff8bbd9419b800/0x1ae94944360d2c99 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 12 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.162542:0:27134:0:(ldlm_resource.c:1750:ldlm_resource_add_lock()) ### About to add this lock ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 4/0,1 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.162570:0:27134:0:(ldlm_lockd.c:963:ldlm_server_blocking_ast()) ### server preparing blocking AST ns: MGS lock: ffff8bbd9419b800/0x1ae94944360d2c99 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50000000000020 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 12 pid: 27111 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.162586:0:27134:0:(ldlm_lockd.c:495:ldlm_add_waiting_lock()) ### adding to wait list(timeout: 150, AT: on) ns: MGS lock: ffff8bbd9419b800/0x1ae94944360d2c99 lrc: 4/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x70000400000020 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 12 pid: 27111 timeout: 1177 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1787761118.162600:0:27134:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8dcc7480 pname:cluuid:pid:xid:nid:opc:job mgs_lustre_noti:MGS:27134:1874603392634496:0@lo:104: 00000100:00100000:3.0:1787761118.162602:0:27113:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbeb1c5d050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:c73e603f-74af-422b-8b68-88272a5bb5a4+12:27097:x1874603392634368:12345-0@lo:253:mount.lustre.0 Request processed in 1659us (1873us total) trans 0 rc 0/0 00000100:00100000:3.0:1787761118.162614:0:27113:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 23 00000100:00100000:0.0:1787761118.162634:0:27097:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8adf2580 pname:cluuid:pid:xid:nid:opc:job mount.lustre:c73e603f-74af-422b-8b68-88272a5bb5a4:27097:1874603392634368:0@lo:253:mount.lustre.0 10000000:01000000:0.0:1787761118.162647:0:27097:0:(mgc_request_server.c:302:mgc_target_register()) register lustre-MDT0000 got index = 0 00000100:00100000:2.0:1787761118.162650:0:27134:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000020:01000004:0.0:1787761118.162656:0:27097:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: rep 00000020:01000004:0.0:1787761118.162658:0:27097:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:0.0:1787761118.162660:0:27097:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:0.0:1787761118.162661:0:27097:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:0.0:1787761118.162662:0:27097:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:0.0:1787761118.162664:0:27097:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:0.0:1787761118.162665:0:27097:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:0.0:1787761118.162666:0:27097:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:0.0:1787761118.162667:0:27097:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:0.0:1787761118.162669:0:27097:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 00000020:02000000:0.0:1787761118.162681:0:27097:0:(tgt_mount.c:2692:server_calc_timeout()) lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 00000100:00100000:3.0:1787761118.162696:0:27101:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392634496 00000100:00100000:2.0:1787761118.162697:0:27134:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbd86d10480 going to sleep for 11 seconds 00000100:00100000:3.0:1787761118.162702:0:27101:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392634496 00000100:00100000:3.0:1787761118.162739:0:27101:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1787761118.162747:0:27101:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbd8dcc4780 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cb00_000:c73e603f-74af-422b-8b68-88272a5bb5a4+3:27134:x1874603392634496:12345-0@lo:104: 00010000:00010000:3.0:1787761118.162759:0:27101:0:(ldlm_lockd.c:2506:ldlm_callback_handler()) ### blocking ast ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400000000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.162812:0:27101:0:(ldlm_lockd.c:2189:__ldlm_bl_to_thread()) added 1/1 locks to priority blp list, 1 blwis in pool 00000100:00100000:3.0:1787761118.162818:0:27101:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbd8dcc4780 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cb00_000:c73e603f-74af-422b-8b68-88272a5bb5a4+3:27134:x1874603392634496:12345-0@lo:104: Request processed in 73us (170us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761118.162825:0:27134:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8dcc7480 pname:cluuid:pid:xid:nid:opc:job mgs_lustre_noti:MGS:27134:1874603392634496:0@lo:104: 00000100:00100000:3.0:1787761118.162828:0:27101:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00010000:00010000:2.0:1787761118.162939:0:27134:0:(ldlm_request.c:298:ldlm_completion_ast()) ### client-side enqueue returned a blocked locksleeping ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 3/0,1 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.162958:0:27106:0:(ldlm_lockd.c:2801:ldlm_bl_get_work()) Got 1 locks of 0 total in blp. (0 blwis in pool) 00010000:00010000:2.0:1787761118.162964:0:27106:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400000000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.162971:0:27106:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock ffff8bbd93cc1200 already unused, calling callback (ffffffffc1322c20) 10000000:00010000:2.0:1787761118.162975:0:27106:0:(mgc_request.c:922:mgc_blocking_ast()) ### MGC blocking CB ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400400000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.163001:0:27106:0:(ldlm_request.c:1391:ldlm_cli_cancel_local()) ### client-side cancel ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1408400000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:00010000:2.0:1787761118.163028:0:27106:0:(mgc_request.c:928:mgc_blocking_ast()) ### MGC cancel CB ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1409400000000 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:2.0:1787761118.163035:0:27106:0:(mgc_request.c:932:mgc_blocking_ast()) Lock res [0x65727473756c:0x2:0x0].0x0 (lustre) 00010000:00010000:2.0:1787761118.163157:0:27106:0:(ldlm_request.c:1439:__ldlm_pack_lock()) ### packing ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.163164:0:27106:0:(ldlm_request.c:1498:ldlm_cancel_pack()) 1 locks packed 00010000:00010000:2.0:1787761118.163186:0:27106:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 1/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.163194:0:27106:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGC192.168.202.119@tcp lock: ffff8bbd93cc1200/0x1ae94944360d2c92 lrc: 0/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0x1ae94944360d2c99 expref: -99 pid: 27097 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.163206:0:27106:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761118.163209:0:27106:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761118.163210:0:27106:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00100000:1.0:1787761118.163228:0:26233:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff8bbd8dcc7480 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:c73e603f-74af-422b-8b68-88272a5bb5a4:26233:1874603392634624:0@lo:103:ldlm_bl.0 00000100:00100000:1.0:1787761118.163259:0:26233:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761118.163307:0:27103:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603392634624 00000100:00100000:3.0:1787761118.163326:0:27103:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603392634624 00010000:00010000:3.0:1787761118.163343:0:27103:0:(ldlm_lockd.c:2683:ldlm_cancel_hpreq_check()) ### hpreq cancel/convert lock ns: MGS lock: ffff8bbd9419b800/0x1ae94944360d2c99 lrc: 4/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x60000400000020 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 12 pid: 27111 timeout: 1177 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.163371:0:27103:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1787761118.163378:0:27103:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff8bbd893a2940 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cn00_000:c73e603f-74af-422b-8b68-88272a5bb5a4+12:26233:x1874603392634624:12345-0@lo:103:ldlm_bl.0 00000100:00100000:2.0:1787761118.163382:0:27104:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 3 min 3 max 56 00010000:00010000:3.0:1787761118.163388:0:27103:0:(ldlm_lockd.c:1747:ldlm_request_cancel()) ### server-side cancel handler START: 1 locks, starting at 0 00000100:00100000:2.0:1787761118.163390:0:27104:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_003' 00010000:00010000:3.0:1787761118.163395:0:27103:0:(ldlm_lockd.c:1796:ldlm_request_cancel()) ### server cancels blocked lock after 0s ns: MGS lock: ffff8bbd9419b800/0x1ae94944360d2c99 lrc: 4/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x60000400000020 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 12 pid: 27111 timeout: 1177 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163406:0:27103:0:(ldlm_lockd.c:568:ldlm_del_waiting_lock()) ### removed ns: MGS lock: ffff8bbd9419b800/0x1ae94944360d2c99 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x50000400000020 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 12 pid: 27111 timeout: 1177 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163417:0:27103:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: ffff8bbd9419b800/0x1ae94944360d2c99 lrc: 0/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x44801400000020 nid: 0@lo remote: 0x1ae94944360d2c92 expref: 12 pid: 27111 timeout: 1177 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163430:0:27103:0:(ldlm_lock.c:715:ldlm_add_cp_work_item()) ### lock granted; sending completion AST. ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 3/0,1 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40290000000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163437:0:27103:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 4/0,1 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40290000000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 20000000:01000000:3.0:1787761118.163447:0:27103:0:(mgs_nids.c:688:mgs_ir_notify_complete()) Revoke recover lock of lustre completed after 0.000997878s 00010000:00010000:3.0:1787761118.163456:0:27103:0:(ldlm_lock.c:954:ldlm_lock_decref_and_cancel()) ### ldlm_lock_decref(EX) ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 5/0,1 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163470:0:27103:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(EX) ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 5/0,1 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163476:0:27103:0:(ldlm_lock.c:887:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 4/0,0 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163483:0:27103:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 5/0,0 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163489:0:27103:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock ffff8bbd93cc0200 already unused, calling callback (ffffffffc0cec530) 00010000:00010000:3.0:1787761118.163492:0:27103:0:(ldlm_request.c:378:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 5/0,0 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163500:0:27103:0:(ldlm_request.c:1416:ldlm_cli_cancel_local()) ### server-side local cancel ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 6/0,0 mode: EX/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163519:0:27103:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 4/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.163527:0:27134:0:(ldlm_request.c:190:ldlm_completion_tail()) ### client-side enqueue: destroyed ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 2/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761118.163528:0:27103:0:(ldlm_lockd.c:1808:ldlm_request_cancel()) ### server-side cancel handler END 00010000:00010000:2.0:1787761118.163539:0:27134:0:(ldlm_request.c:557:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 1/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761118.163546:0:27134:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: ffff8bbd93cc0200/0x1ae94944360d2cca lrc: 0/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 27134 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761118.163565:0:27103:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff8bbd893a2940 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cn00_000:c73e603f-74af-422b-8b68-88272a5bb5a4+11:26233:x1874603392634624:12345-0@lo:103:ldlm_bl.0 Request processed in 187us (303us total) trans 0 rc 0/0 00000100:00100000:3.0:1787761118.163572:0:27103:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1787761118.163578:0:26233:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff8bbd8dcc7480 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:c73e603f-74af-422b-8b68-88272a5bb5a4:26233:1874603392634624:0@lo:103:ldlm_bl.0 00000040:01000000:1.0:1787761118.172359:0:27097:0:(llog_obd.c:197:llog_setup()) obd lustre-MDT0000-osd ctxt 16 is initialized 00000020:00080000:3.0:1787761118.172438:0:27155:0:(update_trans.c:1539:distribute_txn_commit_thread()) lustre-MDT0000: start commit thread committed batchid 0 00000020:00080000:3.0:1787761118.172443:0:27155:0:(update_trans.c:1590:distribute_txn_commit_thread()) lustre-MDT0000: batchid: 0 committed batchid 0 00000040:01000000:1.0:1787761118.172721:0:27156:0:(llog_osd.c:2246:llog_osd_get_cat_list()) cat list: disk size=64, read=32 00000040:01000000:3.0:1787761118.172739:0:27097:0:(llog_obd.c:197:llog_setup()) obd lustre-MDT0001-osp-MDT0000 ctxt 16 is initialized 00000100:00080000:3.0:1787761118.173438:0:27157:0:(client.c:1845:ptlrpc_send_new_req()) @@@ req waiting for recovery: (FULL != DISCONN) req@ffff8bbd8f6fb0c0 x1874603392634752/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 304/4320 e 0 to 0 dl 0 ref 2 fl Rpc:WQU/200/ffffffff rc 0/-1 job:'lod0000_rec0001.0' uid:0 gid:0 projid:4294967295 00000100:00100000:3.0:1787761118.173448:0:27157:0:(client.c:2715:ptlrpc_set_wait()) set ffff8bbd90da0540 going to sleep for 0 seconds 00000040:00080000:0.0:1787761118.173462:0:27156:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:01000000:1.0:1787761118.173757:0:27097:0:(llog_obd.c:197:llog_setup()) obd lustre-MDD0000 ctxt 12 is initialized 00000040:00080000:1.0:1787761118.173804:0:27097:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000004:00000080:1.0:1787761118.176425:0:27097:0:(mdd_device.c:555:mdd_changelog_llog_init()) changelog starting index=0 00000040:01000000:1.0:1787761118.176434:0:27097:0:(llog_obd.c:197:llog_setup()) obd lustre-MDD0000 ctxt 14 is initialized 00000040:00080000:1.0:1787761118.176524:0:27097:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:1.0:1787761118.180876:0:27097:0:(llog.c:862:llog_process_thread()) stop processing catalog [0xa:0x5:0x0] index 64768 count 1 00000040:00080000:1.0:1787761118.182562:0:27097:0:(llog.c:862:llog_process_thread()) stop processing catalog [0xa:0x6:0x0] index 64768 count 1 00000040:01000000:1.0:1787761118.182600:0:27097:0:(llog_obd.c:197:llog_setup()) obd lustre-MDD0000 ctxt 15 is initialized 00000040:00080000:1.0:1787761118.182695:0:27097:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00080000:10000000:1.0:1787761118.183235:0:27097:0:(osd_handler.c:5551:osd_index_try()) lustre-MDT0000: index object [0x200000003:0x36:0x0] (8/32) registered 00000040:00080000:0.0:1787761118.183968:0:27156:0:(llog.c:862:llog_process_thread()) stop processing catalog [0x200000400:0x1:0x0] index 261376 count 1 00000004:00080000:0.0:1787761118.184028:0:27156:0:(lod_dev.c:521:lod_sub_recovery_thread()) lustre-MDT0000-osd retrieved update log, duration 0, retries 0 00000001:00000004:1.0:1787761118.184856:0:27097:0:(tgt_lastrcvd.c:727:tgt_server_data_update()) lustre-MDT0000_UUID: mount_count is 3, last_transno is 12884901888 00000001:00080000:1.0:1787761118.185942:0:27097:0:(tgt_lastrcvd.c:222:tgt_reply_header_read()) lustre-MDT0000: read reply_data header. magic=0xbdabda01 header_size=32 reply_size=32 00000004:00000080:1.0:1787761118.185961:0:27097:0:(mdd_device.c:2304:mdd_iocontrol()) lustre-MDD0000: cmd=c00866e6 len=0 karg=ffff97f949f3f988 00100000:10000000:1.0:1787761118.185966:0:27097:0:(lfsck_lib.c:3085:lfsck_start()) lustre-MDT0000-osd: start master thread 00000020:01000004:0.0:1787761118.186667:0:27097:0:(tgt_mount.c:298:server_mgc_clear_fs()) Unassign mgc disk 10000000:01000000:0.0:1787761118.186680:0:27097:0:(mgc_request_server.c:166:mgc_fs_clear()) MGC192.168.202.119@tcp: cl_mgc_mutex unlock 00000020:01000004:0.0:1787761118.186700:0:27097:0:(tgt_mount.c:2458:server_fill_super_common()) Server sb, dev=46 00000080:00000004:0.0:1787761118.186720:0:27097:0:(super25.c:182:lustre_fill_super()) /dev/mapper/mds1_flakey: Mount complete 00000020:00000004:0.0:1787761118.188893:0:27097:0:(tgt_mount.c:2344:server_getattr()) lustre-MDT0000: root_inode from vfsmnt ino=2, dev=0 00000020:00000004:0.0:1787761118.189220:0:27097:0:(tgt_mount.c:2359:is_cmd_supported()) ioctl cmd=81009431 Debug log: 969 lines, 969 kept, 0 dropped, 0 bad.