00000001:02000400:0.0F:1787760916.684114:0:17814:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local 00000001:01000000:3.0F:1787760919.094994:0:17858:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm adler32 speed = 651 MB/s 00000001:01000000:2.0F:1787760919.344709:0:17858:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32 speed = 935 MB/s 00000001:01000000:3.0:1787760919.594745:0:17858:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32c speed = 7631 MB/s 00000020:02000000:1.0F:1787760919.875981:0:17906:0:(class_obd.c:771:obdclass_init()) Lustre: Build Version: 2.17.57_112_gb05577e 00000400:02000000:3.0:1787760920.290182:0:17921:0:(api-ni.c:2823:lnet_startup_lndni()) Added LNI 192.168.203.155@tcp [8/256/0/180] 00008000:02000000:2.0:1787760924.253656:0:18060:0:(echo_client.c:2574:obdecho_init()) Echo OBD driver; http://www.lustre.org/ 02000000:01000000:2.0:1787761257.861535:0:18838:0:(lproc_gss.c:195:rsi_upcall_store()) rsicache: rsi upcall set to /home/green/git/lustre-release/lustre/utils/gss/l_getauth 00000020:01000004:2.0:1787761262.102478:0:19341:0:(obd_mount.c:923:lmd_print()) mount data: 00000020:01000004:2.0:1787761262.102483:0:19341:0:(obd_mount.c:926:lmd_print()) device: /dev/mapper/mds1_flakey 00000020:01000004:2.0:1787761262.102485:0:19341:0:(obd_mount.c:929:lmd_print()) options: user_xattr,errors=remount-ro 00000080:01200004:2.0:1787761262.102588:0:19341:0:(super25.c:131:lustre_fill_super()) VFS Op: sb 00000000aa4d4506 00000080:02000400:2.0:1787761262.102597:0:19341:0:(super25.c:149:lustre_fill_super()) lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' 00000020:01000004:2.0:1787761262.105453:0:19341:0:(tgt_mount.c:2500:osd_start()) Attempting to start lustre-MDT0000, type=osd-ldiskfs, lsifl=200005, mountfl=0 00000020:01000004:2.0:1787761262.105461:0:19341:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD lustre-MDT0000-osd (typ=osd-ldiskfs) 00000020:00000080:2.0:1787761262.105483:0:19341:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-osd (00000000e372bf2b) 00000020:00000080:2.0:1787761262.105497:0:19341:0:(obd_config.c:720:class_attach_name()) OBD: dev 0 attached type osd-ldiskfs with refcount 2 00100000:10000000:2.0:1787761262.130711:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x13:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.131503:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000001:0x3:0x0] (8/24) registered 00100000:10000000:2.0:1787761262.131887:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x29:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.132033:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x32:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.132215:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x28:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.132378:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2d:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.132531:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x17:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.132686:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1e:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.132858:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1b:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.133039:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x26:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.133200:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2c:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.133372:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x31:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.133516:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x27:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.133694:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x20:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.133861:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2b:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.134017:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x21:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.134192:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x22:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.134364:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1d:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.134518:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1a:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.134691:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1f:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.134855:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x1c:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.135015:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x33:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.135168:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x19:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.135335:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x30:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.135500:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x14:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.135658:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2a:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.135835:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2f:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.135989:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x23:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.136145:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x34:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.136315:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x16:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.136468:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x18:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.136778:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x25:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.136933:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x15:0x0] (16/1) registered 00100000:10000000:2.0:1787761262.137084:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2e:0x0] (24/16) registered 00100000:10000000:2.0:1787761262.137733:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x2:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.138222:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xb:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.138407:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xa:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.138535:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x3:0x0] (8/8) registered 00100000:10000000:2.0:1787761262.138851:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x20003:0x0] (8/8) registered 00100000:10000000:2.0:1787761262.139026:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x20002:0x0] (8/8) registered 00100000:10000000:2.0:1787761262.139194:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x2:0x0] (8/8) registered 00100000:10000000:2.0:1787761262.139356:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xd:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.139501:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xc:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.139655:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0xe:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.139859:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x20001:0x0] (8/8) registered 00100000:10000000:2.0:1787761262.140008:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000003:0x9:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.140162:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000005:0x1:0x0] (8/8) registered 00100000:10000000:2.0:1787761262.141735:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x1020000:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.142078:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x20000:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.142236:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x2020000:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.142550:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x2010000:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.142708:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x1010000:0x0] (8/32) registered 00100000:10000000:2.0:1787761262.142951:0:19341:0:(osd_scrub.c:1808:osd_ios_index_register()) lustre-MDT0000: index object [0x200000006:0x10000:0x0] (8/32) registered 00080000:01000000:2.0:1787761262.143562:0:19341:0:(osd_lproc.c:911:osd_procfs_init()) lustre-MDT0000: register osd-ldiskfs tunable parameters 00000020:00000080:2.0:1787761262.143801:0:19341:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-osd (uuid lustre-MDT0000-osd_UUID) 00080000:01000000:2.0:1787761262.143808:0:19341:0:(osd_handler.c:8895:osd_obd_connect()) connect #0 00000020:00000080:2.0:1787761262.143817:0:19341:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x75911fc857d94a35 00000020:01000004:2.0:1787761262.143822:0:19341:0:(tgt_mount.c:2585:server_fill_super()) Found service lustre-MDT0000 on device /dev/mapper/mds1_flakey 00000020:01000000:2.0:1787761262.143827:0:19341:0:(tgt_mount.c:219:server_start_mgs()) Start MGS service MGS 00000020:01000004:2.0:1787761262.143831:0:19341:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000aa4d4506 from MGS 00000020:01000004:2.0:1787761262.143835:0:19341:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGS (typ=mgs) 00000020:00000080:2.0:1787761262.143842:0:19341:0:(genops.c:413:class_newdev()) Allocate new device MGS (00000000b447adb9) 00000020:00000080:2.0:1787761262.143851:0:19341:0:(obd_config.c:720:class_attach_name()) OBD: dev 1 attached type mgs with refcount 2 00000020:01000004:2.0:1787761262.143902:0:19341:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000aa4d4506 from MGS, refs=2 00080000:01000000:2.0:1787761262.143907:0:19341:0:(osd_handler.c:8895:osd_obd_connect()) connect #1 00000020:00000080:2.0:1787761262.143911:0:19341:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x75911fc857d94a43 00000100:00100000:2.0:1787761262.144002:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_cbd: allocate 1 new 8192-byte reqbufs (0/1 left), rc = 0 00000100:00100000:2.0:1787761262.144116:0:19341:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 0 min 2 max 56 00000100:00100000:2.0:1787761262.144122:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_000' 00000100:00100000:2.0:1787761262.144490:0:19341:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 1 min 2 max 56 00000100:00100000:2.0:1787761262.144496:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_001' 00000100:00100000:0.0:1787761262.145074:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_canceld: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:0.0:1787761262.145196:0:19341:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 0 min 3 max 56 00000100:00100000:0.0:1787761262.145209:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_000' 00000100:00100000:0.0:1787761262.145529:0:19341:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 1 min 3 max 56 00000100:00100000:0.0:1787761262.145536:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_001' 00000100:00100000:0.0:1787761262.145815:0:19341:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 2 min 3 max 56 00000100:00100000:0.0:1787761262.145821:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_002' 00010000:00010000:2.0:1787761262.146280:0:19350:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761262.146283:0:19350:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761262.146290:0:19350:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761262.146444:0:19351:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761262.146447:0:19351:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761262.146449:0:19351:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:0.0:1787761262.146711:0:19341:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGS-0 is initialized 00010000:00010000:2.0:1787761262.148737:0:19350:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000001:01000000:0.0:1787761262.396769:0:19341:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip512 speed = 7107 MB/s 00000001:01000000:0.0:1787761262.646768:0:19341:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip4K speed = 8095 MB/s 00000001:01000000:0.0:1787761262.897300:0:19341:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc512 speed = 1500 MB/s 00000001:01000000:0.0:1787761263.147162:0:19341:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc4K speed = 1855 MB/s 00000040:01000000:0.0:1787761263.149966:0:19341:0:(llog_obd.c:197:llog_setup()) obd MGS ctxt 0 is initialized 20000000:01000000:0.0:1787761263.150015:0:19341:0:(mgs_llog.c:152:class_dentry_readdir()) Not in white list, skipping lustre-sptlrpc 10000000:01000000:2.0:1787761263.150502:0:19353:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x2 (params) 20000000:01000000:0.0:1787761263.150519:0:19341:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2 20000000:01000000:0.0:1787761263.150553:0:19341:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:0.0:1787761263.150882:0:19341:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 00000100:00100000:0.0:1787761263.151322:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) mgs: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:0.0:1787761263.151481:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 0 min 3 max 32 00000100:00100000:0.0:1787761263.151486:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0000' 00000100:00100000:3.0:1787761263.151898:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 1 min 3 max 32 00000100:00100000:3.0:1787761263.151906:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0001' 00000100:00100000:1.0:1787761263.152146:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 2 min 3 max 32 00000100:00100000:1.0:1787761263.152154:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0002' 00000100:00080000:2.0:1787761263.152547:0:19358:0:(pinger.c:466:ping_evictor_main()) Starting Ping Evictor 00000020:00000080:1.0:1787761263.152772:0:19341:0:(obd_config.c:826:class_setup()) finished setup of obd MGS (uuid MGS) 00000020:01000004:1.0:1787761263.152791:0:19341:0:(obd_mount.c:411:lustre_start_mgc()) Start MGC 'MGC192.168.203.155@tcp' 00000020:01000004:1.0:1787761263.152793:0:19341:0:(obd_mount.c:420:lustre_start_mgc()) mgs NIDs (null). 00000020:01000004:1.0:1787761263.152841:0:19341:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGC192.168.203.155@tcp (typ=mgc) 00000020:00000080:1.0:1787761263.152860:0:19341:0:(genops.c:413:class_newdev()) Allocate new device MGC192.168.203.155@tcp (00000000e1cf58e3) 00000020:00000080:1.0:1787761263.152876:0:19341:0:(obd_config.c:720:class_attach_name()) OBD: dev 2 attached type mgc with refcount 2 00010000:00080000:1.0:1787761263.153007:0:19341:0:(ldlm_lib.c:102:import_set_conn()) imp 000000006ebb4043@MGC192.168.203.155@tcp: add connection 192.168.203.155@tcp at head 00010000:00010000:1.0:1787761263.153232:0:19341:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGC192.168.203.155@tcp-0 is initialized 00000040:01000000:1.0:1787761263.153239:0:19341:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.203.155@tcp ctxt 1 is initialized 10000000:01000000:3.0:1787761263.154125:0:19359:0:(mgc_request.c:631:mgc_requeue_thread()) Starting requeue thread 00000020:00000080:2.0:1787761263.154167:0:19341:0:(obd_config.c:826:class_setup()) finished setup of obd MGC192.168.203.155@tcp (uuid 907262e2-bb62-4cd8-a453-7ec537117069) 00000020:00000080:2.0:1787761263.154184:0:19341:0:(genops.c:1385:class_connect()) connect: client 907262e2-bb62-4cd8-a453-7ec537117069, cookie 0x75911fc857d94a51 00000100:00080000:2.0:1787761263.154193:0:19341:0:(import.c:510:import_select_connection()) MGC192.168.203.155@tcp: connect to NID 0@lo last attempt 0 00000100:00080000:2.0:1787761263.154198:0:19341:0:(import.c:624:import_select_connection()) MGC192.168.203.155@tcp: import 000000006ebb4043 using connection 192.168.203.155@tcp/0@lo 00000100:00100000:2.0:1787761263.154226:0:19341:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@00000000490d1aae x1874603194450048/t0(0) o250->MGC192.168.203.155@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:1787761263.154247:0:19341:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import 907262e2-bb62-4cd8-a453-7ec537117069->MGS 00000020:01000004:2.0:1787761263.154278:0:19341:0:(tgt_mount.c:1809:server_start_targets()) starting target lustre-MDT0000 00000020:01000004:2.0:1787761263.154282:0:19341:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MDS (typ=mds) 00000020:00000080:2.0:1787761263.154290:0:19341:0:(genops.c:413:class_newdev()) Allocate new device MDS (00000000b3856ba2) 00000020:00000080:2.0:1787761263.154302:0:19341:0:(obd_config.c:720:class_attach_name()) OBD: dev 3 attached type mds with refcount 2 00000100:00100000:3.0:1787761263.154441:0:17936:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000490d1aae pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:907262e2-bb62-4cd8-a453-7ec537117069:17936:1874603194450048:0@lo:250: 00000100:00100000:3.0:1787761263.154500:0:17936:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.154570:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450048 00000100:00100000:3.0:1787761263.154576:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450048 00000100:00100000:3.0:1787761263.154616:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1787761263.154621:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000ebbcb2aa pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:0+-99:17936:x1874603194450048:12345-0@lo:250: 00010000:00080000:3.0:1787761263.154645:0:19354:0:(ldlm_lib.c:1482:target_handle_connect()) MGS: connection from 907262e2-bb62-4cd8-a453-7ec537117069@0@lo t0 exp 0000000000000000 cur 1383 last 0 00000020:00000080:3.0:1787761263.154698:0:19354:0:(genops.c:1385:class_connect()) connect: client 907262e2-bb62-4cd8-a453-7ec537117069, cookie 0x75911fc857d94a5f 00000100:00080000:3.0:1787761263.154856:0:19354:0:(import.c:65:import_set_state_nolock()) 000000009189a560 : changing import state from RECOVER to FULL 00000100:00100000:3.0:1787761263.154904:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000ebbcb2aa pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+5:17936:x1874603194450048:12345-0@lo:250: Request processed in 282us (406us total) trans 0 rc 0/0 00000100:00100000:3.0:1787761263.154910:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1787761263.154940:0:17936:0:(client.c:3125:ptlrpc_free_committed()) MGC192.168.203.155@tcp: committing for last_committed 0 gen 1 00000100:00080000:3.0:1787761263.154946:0:17936:0:(import.c:1132:ptlrpc_connect_interpret()) MGC192.168.203.155@tcp: connect to target with instance 0 00000100:00080000:3.0:1787761263.154951:0:17936:0:(import.c:956:ptlrpc_connect_set_flags()) MGC192.168.203.155@tcp: Resetting ns_connect_flags to server flags: 0xa000011001002060 10000000:01000000:3.0:1787761263.154961:0:17936:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808005 00000100:00080000:3.0:1787761263.154963:0:17936:0:(import.c:65:import_set_state_nolock()) 000000006ebb4043 MGS: changing import state from CONNECTING to FULL 10000000:01000000:3.0:1787761263.154965:0:17936:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808004 00000100:00080000:3.0:1787761263.154971:0:17936:0:(pinger.c:186:ptlrpc_pinger_ir_up()) IR up 00000100:00100000:3.0:1787761263.154974:0:17936:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000490d1aae pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:907262e2-bb62-4cd8-a453-7ec537117069:17936:1874603194450048:0@lo:250: 00000100:00100000:2.0:1787761263.159499:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt: allocate 64 new 262144-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1787761263.159753:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 0 min 3 max 116 00000100:00100000:2.0:1787761263.159759:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_000' 00000100:00100000:2.0:1787761263.160279:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 1 min 3 max 116 00000100:00100000:2.0:1787761263.160292:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_001' 00000100:00100000:1.0:1787761263.160559:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 2 min 3 max 116 00000100:00100000:1.0:1787761263.160567:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_002' 00000100:00100000:3.0:1787761263.161168:0:19341: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:1787761263.161301:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 0 min 2 max 80 00000100:00100000:3.0:1787761263.161307:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_000' 00000100:00100000:3.0:1787761263.161711:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 1 min 2 max 80 00000100:00100000:3.0:1787761263.161720:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_001' 00010000:00010000:2.0:1787761263.175741:0:19351:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00100000:3.0:1787761263.180893:0:19341: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:1787761263.181033:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 0 min 2 max 116 00000100:00100000:3.0:1787761263.181037:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_000' 00000100:00100000:3.0:1787761263.181634:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 1 min 2 max 116 00000100:00100000:3.0:1787761263.181639:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_001' 00000100:00100000:3.0:1787761263.182021:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqs: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:3.0:1787761263.182101:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 0 min 2 max 256 00000100:00100000:3.0:1787761263.182105:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0000' 00000100:00100000:3.0:1787761263.182455:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 1 min 2 max 256 00000100:00100000:3.0:1787761263.182461:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0001' 00000100:00100000:3.0:1787761263.182919:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqm: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:3.0:1787761263.183035:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 0 min 2 max 256 00000100:00100000:3.0:1787761263.183044:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0000' 00000100:00100000:3.0:1787761263.183265:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 1 min 2 max 256 00000100:00100000:3.0:1787761263.183273:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0001' 00000100:00100000:3.0:1787761263.183655:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_fld: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:3.0:1787761263.183791:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 0 min 2 max 256 00000100:00100000:3.0:1787761263.183795:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0000' 00000100:00100000:3.0:1787761263.184077:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 1 min 2 max 256 00000100:00100000:3.0:1787761263.184082:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0001' 00000100:00100000:3.0:1787761263.194448:0:19341:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_io: allocate 64 new 524288-byte reqbufs (0/64 left), rc = 0 00000100:00100000:3.0:1787761263.194629:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 0 min 3 max 116 00000100:00100000:3.0:1787761263.194635:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_000' 00000100:00100000:3.0:1787761263.196015:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 1 min 3 max 116 00000100:00100000:3.0:1787761263.196023:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_001' 00000100:00100000:3.0:1787761263.196909:0:19341:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 2 min 3 max 116 00000100:00100000:3.0:1787761263.196916:0:19341:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_002' 00000020:00000080:3.0:1787761263.197783:0:19341:0:(obd_config.c:826:class_setup()) finished setup of obd MDS (uuid MDS_uuid) 00000020:01000004:3.0:1787761263.197809:0:19341:0:(tgt_mount.c:280:server_mgc_set_fs()) Set mgc disk for /dev/mapper/mds1_flakey 10000000:01000000:3.0:1787761263.197816:0:19341:0:(mgc_request_server.c:89:mgc_fs_setup()) MGC192.168.203.155@tcp: cl_mgc_mutex lustre-MDT0000-osd for locked: rc = 0 00000040:01000000:3.0:1787761263.197918:0:19341:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.203.155@tcp ctxt 0 is initialized 00000020:01000004:3.0:1787761263.197943:0:19341:0:(tgt_mount.c:1418:server_register_target()) Registration lustre-MDT0000, fs=lustre, 192.168.203.155@tcp, index=0000, flags=0x20005 00000020:01000004:3.0:1787761263.197946:0:19341:0:(tgt_mount.c:1175:server_mti_print()) mti - server_register_target 00000020:01000004:3.0:1787761263.197949:0:19341:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:3.0:1787761263.197950:0:19341:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:3.0:1787761263.197951:0:19341:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1787761263.197952:0:19341:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1787761263.197952:0:19341:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1787761263.197953:0:19341:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1787761263.197954:0:19341:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1787761263.197955:0:19341:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1787761263.197956:0:19341:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 10000000:01000000:3.0:1787761263.197957:0:19341:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target lustre-MDT0000 0x10020005 00000020:01000004:3.0:1787761263.197959:0:19341:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req 00000020:01000004:3.0:1787761263.197959:0:19341:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:3.0:1787761263.197960:0:19341:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:3.0:1787761263.197960:0:19341:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1787761263.197961:0:19341:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1787761263.197962:0:19341:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1787761263.197962:0:19341:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1787761263.197963:0:19341:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1787761263.197970:0:19341:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1787761263.197971:0:19341:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 10000000:01000000:3.0:1787761263.198001:0:19341:0:(mgc_request_server.c:281:mgc_target_register()) register lustre-MDT0000 00000100:00100000:3.0:1787761263.198022:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450176:0@lo:253: 00000100:00100000:3.0:1787761263.198078:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.198120:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 00000000af436d58 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.198143:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450176 00000100:00100000:2.0:1787761263.198151:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450176 00000100:00100000:2.0:1787761263.198199:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 1 00000100:00100000:2.0:1787761263.198208:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000ea4dcf9d pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+5:19341:x1874603194450176:12345-0@lo:253: 20000000:01000000:2.0:1787761263.198274:0:19357:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:2.0:1787761263.198277:0:19357:0:(mgs_handler.c:479:mgs_target_reg()) fs: lustre index: 0 is registered to MGS. 20000000:01000000:2.0:1787761263.198280:0:19357:0:(mgs_handler.c:529:mgs_target_reg()) Server lustre-MDT0000 is running on 0@lo 10000000:01000000:0.0:1787761263.198491:0:19378:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x2 (lustre) 20000000:01000000:2.0:1787761263.198884:0:19357:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 5 20000000:01000000:0.0:1787761263.199728:0:19379:0:(mgs_llog.c:340:mgs_fsdb_handler()) MDT index is 0 20000000:01000000:0.0:1787761263.199732:0:19379:0:(mgs_llog.c:324:mgs_fsdb_handler()) OST index for lustre-OST0000_UUID is 0 (0) 20000000:01000000:0.0:1787761263.199733:0:19379:0:(mgs_llog.c:324:mgs_fsdb_handler()) OST index for lustre-OST0001_UUID is 1 (1) 00000040:00080000:0.0:1787761263.199740:0:19379:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 42 count 42 00000040:00080000:0.0:1787761263.200496:0:19380:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0xa:0x0] index 19 count 19 20000000:01000000:2.0:1787761263.200557:0:19357:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:2.0:1787761263.200567:0:19357:0:(mgs_handler.c:637:mgs_target_reg()) replying with lustre-MDT0000, index=0, rc=0 00000100:00100000:2.0:1787761263.201516:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000ea4dcf9d pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+5:19341:x1874603194450176:12345-0@lo:253: Request processed in 3306us (3433us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.201528:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 1 00000100:00100000:3.0:1787761263.201558:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450176:0@lo:253: 10000000:01000000:3.0:1787761263.201572:0:19341:0:(mgc_request_server.c:302:mgc_target_register()) register lustre-MDT0000 got index = 0 00000020:01000004:3.0:1787761263.201575:0:19341:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: rep 00000020:01000004:3.0:1787761263.201577:0:19341:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:3.0:1787761263.201578:0:19341:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:3.0:1787761263.201580:0:19341:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1787761263.201581:0:19341:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1787761263.201582:0:19341:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1787761263.201584:0:19341:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1787761263.201586:0:19341:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1787761263.201587:0:19341:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1787761263.201589:0:19341:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 00000020:01000004:3.0:1787761263.201605:0:19341:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000aa4d4506 from lustre-MDT0000 10000000:01000000:3.0:1787761263.201627:0:19341:0:(mgc_request.c:1944:mgc_process_config()) parse_log lustre-MDT0000 from 0 10000000:01000000:3.0:1787761263.201634:0:19341:0:(mgc_request.c:329:config_log_add()) add config log lustre-MDT0000-0000000000000000 10000000:01000000:3.0:1787761263.201638:0:19341:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-sptlrpc-ffff96d34479b490 10000000:01000000:3.0:1787761263.201651:0:19341:0:(mgc_request.c:68:mgc_name2resid()) log lustre-sptlrpc to resid 0x65727473756c/0x0 (lustre) 10000000:01000000:3.0:1787761263.201657:0:19341:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-sptlrpc-ffff96d34479b490 from 1 10000000:01000000:3.0:1787761263.201660:0:19341:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-sptlrpc (res 0x65727473756c) 00010000:00010000:3.0:1787761263.201719:0:19341:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.203.155@tcp lock: 000000006d1357e2/0x75911fc857d94a66 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.201729:0:19341:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.203.155@tcp lock: 000000006d1357e2/0x75911fc857d94a66 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.201737:0:19341:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.203.155@tcp lock: 000000006d1357e2/0x75911fc857d94a66 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.201753:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450304:0@lo:101: 00000100:00100000:3.0:1787761263.201803:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761263.201840:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450304 00000100:00100000:2.0:1787761263.201847:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450304 00000100:00100000:3.0:1787761263.201851:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 0000000013fcd311 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.201891:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 2 00000100:00100000:2.0:1787761263.201899:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000002bcb955c pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+5:19341:x1874603194450304:12345-0@lo:101: 00010000:00010000:2.0:1787761263.201911:0:19354:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1787761263.201924:0:19354:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 000000009ae00a25/0x75911fc857d94a6d lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x75911fc857d94a66 expref: -99 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.201945:0:19354:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 000000009ae00a25/0x75911fc857d94a6d lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x75911fc857d94a66 expref: 6 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.201954:0:19354:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 000000009ae00a25/0x75911fc857d94a6d lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x75911fc857d94a66 expref: 6 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.201963:0:19354:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 000000009ae00a25, rc 0) 00000100:00100000:2.0:1787761263.202007:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000002bcb955c pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+6:19341:x1874603194450304:12345-0@lo:101: Request processed in 109us (204us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.202014:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 2 00000100:00100000:3.0:1787761263.202041:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450304:0@lo:101: 00010000:00010000:3.0:1787761263.202055:0:19341:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.203.155@tcp lock: 000000006d1357e2/0x75911fc857d94a66 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a6d expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.202069:0:19341:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.203.155@tcp lock: 000000006d1357e2/0x75911fc857d94a66 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x75911fc857d94a6d expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.202113:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450432:0@lo:501: 00000100:00100000:3.0:1787761263.202137:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.202159:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 0000000013fcd311 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.202183:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450432 00000100:00100000:2.0:1787761263.202188:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450432 00000100:00100000:2.0:1787761263.202213:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 3 00000100:00100000:2.0:1787761263.202219:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000047eb18a5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+6:19341:x1874603194450432:12345-0@lo:501: 00000100:00100000:2.0:1787761263.202325:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000047eb18a5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+7:19341:x1874603194450432:12345-0@lo:501: Request processed in 106us (187us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.202342:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 3 00000100:00100000:3.0:1787761263.202360:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450432:0@lo:501: 00000100:00100000:3.0:1787761263.202387:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450560:0@lo:503: 00000100:00100000:3.0:1787761263.202428:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.202447:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 0000000013fcd311 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.202504:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450560 00000100:00100000:2.0:1787761263.202510:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450560 00000100:00100000:2.0:1787761263.202538:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 4 00000100:00100000:2.0:1787761263.202544:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000031b6bab4 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+7:19341:x1874603194450560:12345-0@lo:503: 00000100:00100000:2.0:1787761263.202620:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000031b6bab4 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+7:19341:x1874603194450560:12345-0@lo:503: Request processed in 76us (192us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.202628:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 4 00000100:00100000:3.0:1787761263.202649:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450560:0@lo:503: 00000100:00100000:0.0:1787761263.202913:0:19381:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19381:1874603194450688:0@lo:502: 00000100:00100000:0.0:1787761263.202962:0:19381:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761263.202986:0:19381:0:(client.c:2715:ptlrpc_set_wait()) set 000000005f1da196 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.202995:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450688 00000100:00100000:2.0:1787761263.203000:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450688 00000100:00100000:2.0:1787761263.203026:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 5 00000100:00100000:2.0:1787761263.203032:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000c7fa7513 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+7:19381:x1874603194450688:12345-0@lo:502: 00000100:00100000:2.0:1787761263.203104:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000c7fa7513 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+7:19381:x1874603194450688:12345-0@lo:502: Request processed in 72us (142us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.203110:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 5 00000100:00100000:0.0:1787761263.203136:0:19381:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19381:1874603194450688:0@lo:502: 00000020:01000000:0.0:1787761263.203163:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:0.0:1787761263.203173:0:19381:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #28 00000020:01000000:0.0:1787761263.203175:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203178:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203180:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:0.0:1787761263.203184:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203187:0:19381:0:(obd_config.c:1563:class_process_config()) marker 28 (0x6) lustre srpc.flavor.default.cli2mdt 00000020:01000000:0.0:1787761263.203190:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:0.0:1787761263.203192:0:19381:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #29 00000020:01000000:0.0:1787761263.203194:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203196:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203197:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:0.0:1787761263.203199:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203201:0:19381:0:(obd_config.c:1563:class_process_config()) marker 29 (0x6) lustre srpc.flavor.default.cli2ost 00000020:01000000:0.0:1787761263.203203:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:0.0:1787761263.203205:0:19381:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #30 00000020:01000000:0.0:1787761263.203206:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203207:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203209:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:0.0:1787761263.203211:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203212:0:19381:0:(obd_config.c:1563:class_process_config()) marker 30 (0x6) lustre srpc.flavor.default.cli2mdt 00000020:01000000:0.0:1787761263.203214:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:0.0:1787761263.203215:0:19381:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #31 00000020:01000000:0.0:1787761263.203217:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203218:0:19381:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.203219:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:0.0:1787761263.203221:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203223:0:19381:0:(obd_config.c:1563:class_process_config()) marker 31 (0x6) lustre srpc.flavor.default.cli2ost 00000020:01000000:0.0:1787761263.203225:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1787761263.203228:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203229:0:19381:0:(obd_config.c:1563:class_process_config()) marker 32 (0x1) lustre srpc.flavor.default.cli2mdt 00000020:00000080:0.0:1787761263.203233:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: ce016 00000020:01000000:0.0:1787761263.203292:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1787761263.203295:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203297:0:19381:0:(obd_config.c:1563:class_process_config()) marker 32 (0x2) lustre srpc.flavor.default.cli2mdt 00000020:01000000:0.0:1787761263.203299:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1787761263.203302:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203307:0:19381:0:(obd_config.c:1563:class_process_config()) marker 33 (0x1) lustre srpc.flavor.default.cli2ost 00000020:00000080:0.0:1787761263.203310:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: ce016 00000100:00100000:0.0:1787761263.203341:0:19381:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19381:1874603194450816:0@lo:502: 00000100:00100000:0.0:1787761263.203372:0:19381:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761263.203389:0:19381:0:(client.c:2715:ptlrpc_set_wait()) set 00000000f5a30b89 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.203407:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450816 00000100:00100000:2.0:1787761263.203411:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450816 00000100:00100000:2.0:1787761263.203436:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 6 00000100:00100000:2.0:1787761263.203441:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000ebae9987 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+7:19381:x1874603194450816:12345-0@lo:502: 00000100:00100000:2.0:1787761263.203508:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000ebae9987 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+7:19381:x1874603194450816:12345-0@lo:502: Request processed in 67us (136us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.203515:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 6 00000100:00100000:0.0:1787761263.203536:0:19381:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19381:1874603194450816:0@lo:502: 00000020:01000000:0.0:1787761263.203554:0:19381:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1787761263.203558:0:19381:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.203560:0:19381:0:(obd_config.c:1563:class_process_config()) marker 33 (0x2) lustre srpc.flavor.default.cli2ost 00000040:00080000:0.0:1787761263.203563:0:19381:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0xa:0x0] index 19 count 19 00000020:01000000:3.0:1787761263.203625:0:19341:0:(obd_config.c:2145:class_config_parse_llog()) Processed log lustre-sptlrpc gen 1-18 (rc=0) 10000000:01000000:3.0:1787761263.203652:0:19341:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.203.155@tcp: configuration from log 'lustre-sptlrpc' succeeded (0). 00010000:00010000:3.0:1787761263.203688:0:19341:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.203.155@tcp lock: 000000006d1357e2/0x75911fc857d94a66 lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a6d expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.203699:0:19341:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.203.155@tcp lock: 000000006d1357e2/0x75911fc857d94a66 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a6d expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761263.203708:0:19341:0:(mgc_request.c:194:do_config_log_add()) do adding config log params-ffff96d348f11800 10000000:01000000:3.0:1787761263.203714:0:19341:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x3 (params) 10000000:01000000:3.0:1787761263.203720:0:19341:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-barrier-ffff96d348f11800 10000000:01000000:3.0:1787761263.203723:0:19341:0:(mgc_request.c:68:mgc_name2resid()) log lustre-barrier to resid 0x65727473756c/0x5 (lustre) 10000000:01000000:3.0:1787761263.203726:0:19341:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-barrier-ffff96d348f11800 from 1 10000000:01000000:3.0:1787761263.203728:0:19341:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-barrier (res 0x65727473756c) 00010000:00010000:3.0:1787761263.203746:0:19341:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.203.155@tcp lock: 00000000b349f776/0x75911fc857d94a74 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.203753:0:19341:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.203.155@tcp lock: 00000000b349f776/0x75911fc857d94a74 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.203760:0:19341:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.203.155@tcp lock: 00000000b349f776/0x75911fc857d94a74 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.203773:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450944:0@lo:101: 00000100:00100000:3.0:1787761263.203808:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.203834:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 0000000013fcd311 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.203849:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194450944 00000100:00100000:2.0:1787761263.203854:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194450944 00000100:00100000:2.0:1787761263.203884:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 7 00000100:00100000:2.0:1787761263.203891:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000000e441de0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+7:19341:x1874603194450944:12345-0@lo:101: 00010000:00010000:2.0:1787761263.203906:0:19357:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1787761263.203916:0:19357:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 0000000082671dc1/0x75911fc857d94a7b lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x75911fc857d94a74 expref: -99 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.203933:0:19357:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 0000000082671dc1/0x75911fc857d94a7b lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x75911fc857d94a74 expref: 8 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.203940:0:19357:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 0000000082671dc1/0x75911fc857d94a7b lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x75911fc857d94a74 expref: 8 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.203944:0:19357:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 0000000082671dc1, rc 0) 00000100:00100000:2.0:1787761263.203972:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000000e441de0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+8:19341:x1874603194450944:12345-0@lo:101: Request processed in 82us (165us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.203980:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 7 00000100:00100000:3.0:1787761263.204000:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194450944:0@lo:101: 00010000:00010000:3.0:1787761263.204011:0:19341:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.203.155@tcp lock: 00000000b349f776/0x75911fc857d94a74 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a7b expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.204019:0:19341:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.203.155@tcp lock: 00000000b349f776/0x75911fc857d94a74 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x75911fc857d94a7b expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761263.204031:0:19341:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.203.155@tcp: configuration from log 'lustre-barrier' succeeded (0). 00010000:00010000:3.0:1787761263.204043:0:19341:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.203.155@tcp lock: 00000000b349f776/0x75911fc857d94a74 lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a7b expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.204049:0:19341:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.203.155@tcp lock: 00000000b349f776/0x75911fc857d94a74 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a7b expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761263.204054:0:19341:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-MDT0000-0000000000000000 10000000:01000000:3.0:1787761263.204058:0:19341:0:(mgc_request.c:68:mgc_name2resid()) log lustre-MDT0000 to resid 0x65727473756c/0x0 (lustre) 10000000:01000000:3.0:1787761263.204062:0:19341:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-mdtir-ffff96d348f11800 10000000:01000000:3.0:1787761263.204064:0:19341:0:(mgc_request.c:68:mgc_name2resid()) log lustre-mdtir to resid 0x65727473756c/0x2 (lustre) 10000000:01000000:3.0:1787761263.204068:0:19341:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-MDT0000-0000000000000000 from 1 10000000:01000000:3.0:1787761263.204070:0:19341:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-MDT0000 (res 0x65727473756c) 00010000:00010000:3.0:1787761263.204083:0:19341:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.203.155@tcp lock: 00000000aa5fdf64/0x75911fc857d94a82 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.204088:0:19341:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.203.155@tcp lock: 00000000aa5fdf64/0x75911fc857d94a82 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.204094:0:19341:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.203.155@tcp lock: 00000000aa5fdf64/0x75911fc857d94a82 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.204105:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451072:0@lo:101: 00000100:00100000:3.0:1787761263.204136:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.204153:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 0000000013fcd311 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.204186:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194451072 00000100:00100000:2.0:1787761263.204191:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194451072 00000100:00100000:2.0:1787761263.204217:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 8 00000100:00100000:2.0:1787761263.204224:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000e2119edf pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+8:19341:x1874603194451072:12345-0@lo:101: 00010000:00010000:2.0:1787761263.204233:0:19354:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1787761263.204240:0:19354:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 0000000081b26337/0x75911fc857d94a89 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: local remote: 0x75911fc857d94a82 expref: -99 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.204264:0:19354:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 0000000081b26337/0x75911fc857d94a89 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x75911fc857d94a82 expref: 9 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.204272:0:19354:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 0000000081b26337/0x75911fc857d94a89 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x75911fc857d94a82 expref: 9 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.204278:0:19354:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 0000000081b26337, rc 0) 00000100:00100000:2.0:1787761263.204328:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000e2119edf pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+9:19341:x1874603194451072:12345-0@lo:101: Request processed in 105us (191us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.204335:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 8 00000100:00100000:3.0:1787761263.204357:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451072:0@lo:101: 00010000:00010000:3.0:1787761263.204369:0:19341:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.203.155@tcp lock: 00000000aa5fdf64/0x75911fc857d94a82 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a89 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.204377:0:19341:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.203.155@tcp lock: 00000000aa5fdf64/0x75911fc857d94a82 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x1000000000000 nid: local remote: 0x75911fc857d94a89 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.204416:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451200:0@lo:501: 00000100:00100000:3.0:1787761263.204439:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.204456:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 0000000013fcd311 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.204474:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194451200 00000100:00100000:2.0:1787761263.204478:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194451200 00000100:00100000:2.0:1787761263.204496:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 9 00000100:00100000:2.0:1787761263.204500:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000067a39b44 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+9:19341:x1874603194451200:12345-0@lo:501: 00000100:00100000:2.0:1787761263.204595:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000067a39b44 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+9:19341:x1874603194451200:12345-0@lo:501: Request processed in 93us (154us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.204603:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 9 00000100:00100000:3.0:1787761263.204617:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451200:0@lo:501: 00000100:00100000:3.0:1787761263.204644:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451328:0@lo:503: 00000100:00100000:3.0:1787761263.204695:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.204717:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 0000000013fcd311 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.204730:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194451328 00000100:00100000:2.0:1787761263.204735:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194451328 00000100:00100000:2.0:1787761263.204763:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 10 00000100:00100000:2.0:1787761263.204770:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000002397987c pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+9:19341:x1874603194451328:12345-0@lo:503: 00000100:00100000:2.0:1787761263.205319:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000002397987c pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+9:19341:x1874603194451328:12345-0@lo:503: Request processed in 550us (624us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.205327:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 10 00000100:00100000:3.0:1787761263.205358:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451328:0@lo:503: 00000100:00100000:0.0:1787761263.205600:0:19382:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19382:1874603194451456:0@lo:502: 00000100:00100000:0.0:1787761263.205626:0:19382:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761263.205638:0:19382:0:(client.c:2715:ptlrpc_set_wait()) set 00000000566d62a1 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.205655:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194451456 00000100:00100000:2.0:1787761263.205660:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194451456 00000100:00100000:2.0:1787761263.205722:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 11 00000100:00100000:2.0:1787761263.205730:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000089d8eb51 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+9:19382:x1874603194451456:12345-0@lo:502: 00000100:00100000:2.0:1787761263.206183:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000089d8eb51 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+9:19382:x1874603194451456:12345-0@lo:502: Request processed in 452us (553us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.206189:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 11 00000100:00100000:0.0:1787761263.206213:0:19382:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19382:1874603194451456:0@lo:502: 00000020:01000000:0.0:1787761263.206238:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1787761263.206248:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.206262:0:19382:0:(obd_config.c:1563:class_process_config()) marker 2 (0x1) lustre-MDT0000-m lov setup 00000020:01000000:0.0:1787761263.206266:0:19382:0:(obd_config.c:1967:class_config_llog_handler()) For 2.x interoperability, rename obd type from lov to lod (lustre-MDT0000) 00000020:00000080:0.0:1787761263.206269:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:0.0:1787761263.206286:0:19382:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-mdtlov (00000000e0879600) 00000020:00000080:0.0:1787761263.206300:0:19382:0:(obd_config.c:720:class_attach_name()) OBD: dev 4 attached type lod with refcount 2 00000020:00000080:0.0:1787761263.206305:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00080000:01000000:0.0:1787761263.206376:0:19382:0:(osd_handler.c:8895:osd_obd_connect()) connect #2 00000020:00000080:0.0:1787761263.206382:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x75911fc857d94a97 00000020:00000080:0.0:1787761263.206567:0:19382:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-mdtlov (uuid lustre-MDT0000-mdtlov_UUID) 00000020:01000000:0.0:1787761263.206571:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1787761263.206574:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.206575:0:19382:0:(obd_config.c:1563:class_process_config()) marker 2 (0x2) lustre-MDT0000-m lov setup 00000020:01000000:0.0:1787761263.206578:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1787761263.206580:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.206586:0:19382:0:(obd_config.c:1563:class_process_config()) marker 3 (0x1) lustre-MDT0000 add mdt 00000020:00000080:0.0:1787761263.206589:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:0.0:1787761263.206595:0:19382:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000 (00000000a5435a12) 00000020:00000080:0.0:1787761263.206603:0:19382:0:(obd_config.c:720:class_attach_name()) OBD: dev 5 attached type mdt with refcount 2 00000020:00000080:0.0:1787761263.206607:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf007 00000020:00000080:0.0:1787761263.206608:0:19382:0:(obd_config.c:1516:class_process_config()) mountopt: profile lustre-MDT0000 osc lustre-MDT0000-mdtlov mdc (null) 00000020:01000000:0.0:1787761263.206611:0:19382:0:(obd_config.c:1149:class_add_profile()) Add profile lustre-MDT0000 00000020:00000080:0.0:1787761263.206616:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00000020:01000004:0.0:1787761263.206650:0:19382:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000aa4d4506 from lustre-MDT0000, refs=3 00000020:00000080:0.0:1787761263.206660:0:19382:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDD0000 (00000000270f7cb3) 00000020:00000080:0.0:1787761263.206704:0:19382:0:(obd_config.c:720:class_attach_name()) OBD: dev 6 attached type mdd with refcount 2 00000004:01000000:0.0:1787761263.206768:0:19382:0:(lod_dev.c:2291:lod_obd_connect()) connect #0 00000020:00000080:0.0:1787761263.206772:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-mdtlov_UUID, cookie 0x75911fc857d94aac 00000020:00000080:0.0:1787761263.206873:0:19382:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDD0000 (uuid lustre-MDD0000_UUID) 00000004:01000000:0.0:1787761263.206879:0:19382:0:(mdd_device.c:1598:mdd_obd_connect()) connect #0 00000020:00000080:0.0:1787761263.206883:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDD0000_UUID, cookie 0x75911fc857d94ab3 00080000:01000000:0.0:1787761263.206887:0:19382:0:(osd_handler.c:8895:osd_obd_connect()) connect #3 00000020:00000080:0.0:1787761263.206890:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x75911fc857d94aba 00010000:00010000:0.0:1787761263.240852:0:19382:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-mdt-lustre-MDT0000_UUID-1 is initialized 00000001:00000004:0.0:1787761263.241181:0:19382:0:(tgt_lastrcvd.c:727:tgt_server_data_update()) lustre-MDT0000_UUID: mount_count is 2, last_transno is 4294976235 00000001:00080000:0.0:1787761263.241370:0:19382: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:0.0:1787761263.241717:0:19382:0:(genops.c:413:class_newdev()) Allocate new device lustre-QMT0000 (0000000059eec242) 00000020:00000080:0.0:1787761263.241733:0:19382:0:(obd_config.c:720:class_attach_name()) OBD: dev 7 attached type qmt with refcount 2 00080000:01000000:0.0:1787761263.241824:0:19382:0:(osd_handler.c:8895:osd_obd_connect()) connect #4 00000020:00000080:0.0:1787761263.241833:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x75911fc857d94ac8 00000020:00000080:1.0:1787761263.242127:0:19382:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-QMT0000 (uuid lustre-QMT0000_UUID) 00000020:00000080:1.0:1787761263.243495:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-QMT0000_UUID, cookie 0x75911fc857d94acf 00000020:00000080:0.0:1787761263.243687:0:19382:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000 (uuid lustre-MDT0000_UUID) 00000020:01000000:0.0:1787761263.243698:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1787761263.243703:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.243706:0:19382:0:(obd_config.c:1563:class_process_config()) marker 3 (0x2) lustre-MDT0000 add mdt 00000020:01000000:0.0:1787761263.243709:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:0.0:1787761263.243711:0:19382:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #9 00000020:01000000:0.0:1787761263.243713:0:19382:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.243715:0:19382:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:0.0:1787761263.243722:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000020:00000080:0.0:1787761263.243724:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.243726:0:19382:0:(obd_config.c:1563:class_process_config()) marker 9 (0x6) lustre sys.timeout 00000020:01000000:0.0:1787761263.243728:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1787761263.243731:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.243733:0:19382:0:(obd_config.c:1563:class_process_config()) marker 10 (0x1) lustre-MDT0000 mdt.identity_upcall 00000020:00000080:0.0:1787761263.243737:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00f 00000004:01000000:0.0:1787761263.243766:0:19382: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:0.0:1787761263.243779:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1787761263.243781:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.243782:0:19382:0:(obd_config.c:1563:class_process_config()) marker 10 (0x2) lustre-MDT0000 mdt.identity_upcall 00000020:01000000:0.0:1787761263.243784:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:01000004:0.0:1787761263.243786:0:19382:0:(obd_mount.c:961:lustre_check_exclusion()) Check exclusion lustre-OST0000 (0) in 0 of /dev/mapper/mds1_flakey 00000020:00000080:0.0:1787761263.243788:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.243789:0:19382:0:(obd_config.c:1563:class_process_config()) marker 12 (0x1) lustre-OST0000 add osc 00000020:00000080:0.0:1787761263.243791:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf005 00000020:00000080:0.0:1787761263.243795:0:19382:0:(obd_config.c:1487:class_process_config()) adding mapping from uuid 192.168.203.155@tcp to nid 0x20000c0a8cb9b (192.168.203.155@tcp) 00000020:01000000:0.0:1787761263.243812:0:19382:0:(obd_config.c:1974:class_config_llog_handler()) For 2.x interoperability, rename obd type from osc to osp (lustre-MDT0000) 00000020:00000080:0.0:1787761263.243814:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:0.0:1787761263.243826:0:19382:0:(genops.c:413:class_newdev()) Allocate new device lustre-OST0000-osc-MDT0000 (00000000aa42d779) 00000020:00000080:0.0:1787761263.243834:0:19382:0:(obd_config.c:720:class_attach_name()) OBD: dev 8 attached type osp with refcount 2 00000020:00000080:0.0:1787761263.243838:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00000004:00080000:0.0:1787761263.243885:0:19382:0:(osp_dev.c:1203:osp_init0()) lustre-OST0000-osc-MDT0000: connect to lustre-MDT0000-osd (lustre-OST0000-osc-MDT0000) 00080000:01000000:0.0:1787761263.243889:0:19382:0:(osd_handler.c:8895:osd_obd_connect()) connect #5 00000020:00000080:0.0:1787761263.243893:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x75911fc857d94add 00010000:00080000:0.0:1787761263.243916:0:19382:0:(ldlm_lib.c:102:import_set_conn()) imp 00000000bbccea73@lustre-OST0000-osc-MDT0000: add connection 192.168.203.155@tcp at head 00010000:00010000:0.0:1787761263.244114:0:19382:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-lustre-OST0000-osc-MDT0000-1 is initialized 00000040:01000000:0.0:1787761263.244474:0:19382:0:(llog_osd.c:2246:llog_osd_get_cat_list()) cat list: disk size=64, read=32 00000040:01000000:0.0:1787761263.244583:0:19382:0:(llog_obd.c:197:llog_setup()) obd lustre-OST0000-osc-MDT0000 ctxt 2 is initialized 00000040:00080000:0.0:1787761263.245430:0:19382:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:0.0:1787761263.245537:0:19382:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0x2:0x0].2, 64 off8320 00000040:00080000:0.0:1787761263.247809:0:19382:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0x8:0x0].1, 64 off8256 00000040:00080000:0.0:1787761263.248065:0:19386:0:(llog.c:805:llog_process_thread()) index: 2, lh_last_idx: 2 synced_idx: 2 lgh_last_idx: 2 00000040:00080000:0.0:1787761263.248069:0:19386:0:(llog_cat.c:163:llog_cat_process_common()) processing log [0x1:0x8:0x0] at index 2 of catalog [0x1:0x2:0x0] 00000020:00000080:1.0:1787761263.248516:0:19382:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-OST0000-osc-MDT0000 (uuid lustre-MDT0000-mdtlov_UUID) 00000020:00000080:1.0:1787761263.248527:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00d 00000004:01000000:1.0:1787761263.248560:0:19382:0:(lod_lov.c:128:lod_add_device()) osp:lustre-OST0000_UUID idx:0 gen:1 00000020:00000080:1.0:1787761263.248580:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-mdtlov_UUID, cookie 0x75911fc857d94ae4 00000100:00080000:1.0:1787761263.248589:0:19382:0:(import.c:510:import_select_connection()) lustre-OST0000-osc-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:1.0:1787761263.248594:0:19382:0:(import.c:624:import_select_connection()) lustre-OST0000-osc-MDT0000: import 00000000bbccea73 using connection 192.168.203.155@tcp/0@lo 00000100:00100000:1.0:1787761263.248657:0:19382:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@00000000eb758480 x1874603194451584/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:1787761263.248715:0:19382:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import lustre-MDT0000-mdtlov_UUID->lustre-OST0000_UUID 00000100:00100000:3.0:1787761263.248742:0:17936:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000eb758480 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-mdtlov_UUID:17936:1874603194451584:0@lo:8: 00000020:01000000:1.0:1787761263.248780:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761263.248797:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.248799:0:19382:0:(obd_config.c:1563:class_process_config()) marker 12 (0x2) lustre-OST0000 add osc 00000020:01000000:1.0:1787761263.248803:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x5 00000020:01000000:1.0:1787761263.248806:0:19382:0:(obd_config.c:1902:class_config_llog_handler()) SKIP #16 00000020:01000000:1.0:1787761263.248808:0:19382:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:1.0:1787761263.248810:0:19382:0:(obd_config.c:1928:class_config_llog_handler()) skipping 0x6 00000020:01000000:1.0:1787761263.248811:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x6 mark_flg=0x6 00000400:00000100:3.0:1787761263.248819:0:17936:0:(lib-move.c:4357:lnet_parse_put()) Dropping PUT from 12345-0@lo portal 28 match 1874603194451584 offset 0 length 520: 4 00000020:00000080:1.0:1787761263.248823:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.248826:0:19382:0:(obd_config.c:1563:class_process_config()) marker 16 (0x6) lustre sys.timeout 00000020:01000000:1.0:1787761263.248830:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:01000004:1.0:1787761263.248835:0:19382:0:(obd_mount.c:961:lustre_check_exclusion()) Check exclusion lustre-OST0001 (1) in 0 of /dev/mapper/mds1_flakey 00000020:00000080:1.0:1787761263.248839:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.248840:0:19382:0:(obd_config.c:1563:class_process_config()) marker 18 (0x1) lustre-OST0001 add osc 00000020:00000080:1.0:1787761263.248844:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf005 00000020:00000080:1.0:1787761263.248847:0:19382:0:(obd_config.c:1487:class_process_config()) adding mapping from uuid 192.168.203.155@tcp to nid 0x20000c0a8cb9b (192.168.203.155@tcp) 00000020:01000000:1.0:1787761263.248868:0:19382: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:1787761263.248871:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf001 00000020:00000080:1.0:1787761263.248882:0:19382:0:(genops.c:413:class_newdev()) Allocate new device lustre-OST0001-osc-MDT0000 (000000003c6f057d) 00000020:00000080:1.0:1787761263.248895:0:19382:0:(obd_config.c:720:class_attach_name()) OBD: dev 9 attached type osp with refcount 2 00000020:00000080:1.0:1787761263.248900:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf003 00000004:00080000:1.0:1787761263.248954:0:19382:0:(osp_dev.c:1203:osp_init0()) lustre-OST0001-osc-MDT0000: connect to lustre-MDT0000-osd (lustre-OST0001-osc-MDT0000) 00080000:01000000:1.0:1787761263.248959:0:19382:0:(osd_handler.c:8895:osd_obd_connect()) connect #6 00000020:00000080:1.0:1787761263.248964:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x75911fc857d94af2 00010000:00080000:1.0:1787761263.248999:0:19382:0:(ldlm_lib.c:102:import_set_conn()) imp 000000004aaed587@lustre-OST0001-osc-MDT0000: add connection 192.168.203.155@tcp at head 00010000:00010000:1.0:1787761263.249202:0:19382:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-lustre-OST0001-osc-MDT0000-2 is initialized 00000040:01000000:1.0:1787761263.249274:0:19382:0:(llog_osd.c:2246:llog_osd_get_cat_list()) cat list: disk size=64, read=32 00000040:01000000:1.0:1787761263.249286:0:19382:0:(llog_obd.c:197:llog_setup()) obd lustre-OST0001-osc-MDT0000 ctxt 2 is initialized 00000040:00080000:1.0:1787761263.250374:0:19382:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:1.0:1787761263.250563:0:19382:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0x5:0x0].2, 64 off8320 00000040:00080000:1.0:1787761263.250746:0:19382:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0x1:0xa:0x0].1, 64 off8256 00000040:00080000:1.0:1787761263.250980:0:19388:0:(llog.c:805:llog_process_thread()) index: 2, lh_last_idx: 2 synced_idx: 2 lgh_last_idx: 2 00000040:00080000:1.0:1787761263.250984:0:19388:0:(llog_cat.c:163:llog_cat_process_common()) processing log [0x1:0xa:0x0] at index 2 of catalog [0x1:0x5:0x0] 00000020:00000080:1.0:1787761263.251408:0:19382:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-OST0001-osc-MDT0000 (uuid lustre-MDT0000-mdtlov_UUID) 00000020:00000080:1.0:1787761263.251415:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00d 00000004:01000000:1.0:1787761263.251441:0:19382:0:(lod_lov.c:128:lod_add_device()) osp:lustre-OST0001_UUID idx:1 gen:1 00000020:00000080:1.0:1787761263.251453:0:19382:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-mdtlov_UUID, cookie 0x75911fc857d94af9 00000100:00080000:1.0:1787761263.251459:0:19382:0:(import.c:510:import_select_connection()) lustre-OST0001-osc-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:1.0:1787761263.251462:0:19382:0:(import.c:624:import_select_connection()) lustre-OST0001-osc-MDT0000: import 000000004aaed587 using connection 192.168.203.155@tcp/0@lo 00000100:00100000:1.0:1787761263.251490:0:19382:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@0000000075e8eca7 x1874603194451712/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:00080000:1.0:1787761263.251509:0:19382:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import lustre-MDT0000-mdtlov_UUID->lustre-OST0001_UUID 00000100:00100000:3.0:1787761263.251535:0:17936:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000075e8eca7 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-mdtlov_UUID:17936:1874603194451712:0@lo:8: 00000020:01000000:1.0:1787761263.251560:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761263.251566:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.251568:0:19382:0:(obd_config.c:1563:class_process_config()) marker 18 (0x2) lustre-OST0001 add osc 00000020:01000000:1.0:1787761263.251572:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000400:00000100:3.0:1787761263.251573:0:17936:0:(lib-move.c:4357:lnet_parse_put()) Dropping PUT from 12345-0@lo portal 28 match 1874603194451712 offset 0 length 520: 4 00000020:00000080:1.0:1787761263.251579:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.251582:0:19382:0:(obd_config.c:1563:class_process_config()) marker 23 (0x1) lustre sys.timeout 00000020:00000080:1.0:1787761263.251587:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf009 00000020:00000080:1.0:1787761263.251589:0:19382:0:(obd_config.c:1537:class_process_config()) changing lustre timeout from 100 to 20 00000020:01000000:1.0:1787761263.251592:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761263.251594:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.251596:0:19382:0:(obd_config.c:1563:class_process_config()) marker 23 (0x2) lustre sys.timeout 00000020:01000000:1.0:1787761263.251600:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:1.0:1787761263.251603:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.251604:0:19382:0:(obd_config.c:1563:class_process_config()) marker 27 (0x1) lustre sys.jobid_var 00000020:00000080:1.0:1787761263.251608:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf00f 00000100:00100000:1.0:1787761263.251636:0:19382:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000f3acce36 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19382:1874603194451840:0@lo:502:llog_process_th.0 00000100:00100000:1.0:1787761263.251734:0:19382:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.251762:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194451840 00000100:00100000:1.0:1787761263.251765:0:19382:0:(client.c:2715:ptlrpc_set_wait()) set 00000000350c702d going to sleep for 11 seconds 00000100:00100000:3.0:1787761263.251769:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194451840 00000100:00100000:3.0:1787761263.251816:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 12 00000100:00100000:3.0:1787761263.251825:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000cc5d6597 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+9:19382:x1874603194451840:12345-0@lo:502:llog_process_th.0 00000100:00100000:3.0:1787761263.251921:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000cc5d6597 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+9:19382:x1874603194451840:12345-0@lo:502:llog_process_th.0 Request processed in 97us (188us total) trans 0 rc 0/0 00000100:00100000:3.0:1787761263.251929:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 12 00000100:00100000:1.0:1787761263.251947:0:19382:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000f3acce36 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19382:1874603194451840:0@lo:502:llog_process_th.0 00000020:01000000:1.0:1787761263.251975:0:19382:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1787761263.251980:0:19382:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1787761263.251982:0:19382:0:(obd_config.c:1563:class_process_config()) marker 27 (0x2) lustre sys.jobid_var 00000040:00080000:1.0:1787761263.251984:0:19382:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 37 count 37 00000020:01000000:3.0:1787761263.252053:0:19341:0:(obd_config.c:2145:class_config_parse_llog()) Processed log lustre-MDT0000 gen 1-36 (rc=0) 10000000:01000000:3.0:1787761263.252081:0:19341:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.203.155@tcp: configuration from log 'lustre-MDT0000' succeeded (0). 00010000:00010000:3.0:1787761263.252095:0:19341:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.203.155@tcp lock: 00000000aa5fdf64/0x75911fc857d94a82 lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a89 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.252105:0:19341:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.203.155@tcp lock: 00000000aa5fdf64/0x75911fc857d94a82 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94a89 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761263.252112:0:19341:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-mdtir-ffff96d348f11800 from 1 10000000:01000000:3.0:1787761263.252115:0:19341:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-mdtir (res 0x65727473756c) 00010000:00010000:3.0:1787761263.252136:0:19341:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.203.155@tcp lock: 00000000abab4dc8/0x75911fc857d94b00 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.252142:0:19341:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.203.155@tcp lock: 00000000abab4dc8/0x75911fc857d94b00 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.252148:0:19341:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.203.155@tcp lock: 00000000abab4dc8/0x75911fc857d94b00 lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.252159:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451968:0@lo:101:mount.lustre.0 00000100:00100000:3.0:1787761263.252184:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.252200:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 000000003171a396 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.252222:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194451968 00000100:00100000:2.0:1787761263.252227:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194451968 00000100:00100000:2.0:1787761263.252268:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 13 00000100:00100000:2.0:1787761263.252276:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000006bb677fd pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+9:19341:x1874603194451968:12345-0@lo:101:mount.lustre.0 00010000:00010000:2.0:1787761263.252291:0:19357:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1787761263.252303:0:19357:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 00000000ecae969a/0x75911fc857d94b07 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x75911fc857d94b00 expref: -99 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.252323:0:19357:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000ecae969a/0x75911fc857d94b07 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x75911fc857d94b00 expref: 10 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.252333:0:19357:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 00000000ecae969a/0x75911fc857d94b07 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x75911fc857d94b00 expref: 10 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.252341:0:19357:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 00000000ecae969a, rc 0) 00000100:00100000:2.0:1787761263.252378:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000006bb677fd pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+10:19341:x1874603194451968:12345-0@lo:101:mount.lustre.0 Request processed in 104us (193us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.252385:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 13 00000100:00100000:3.0:1787761263.252401:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194451968:0@lo:101:mount.lustre.0 00010000:00010000:3.0:1787761263.252413:0:19341:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.203.155@tcp lock: 00000000abab4dc8/0x75911fc857d94b00 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.252429:0:19341:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.203.155@tcp lock: 00000000abab4dc8/0x75911fc857d94b00 lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.253102:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452096:0@lo:256:mount.lustre.0 00000100:00100000:3.0:1787761263.253130:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.253150:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 000000003171a396 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.253172:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452096 00000100:00100000:2.0:1787761263.253177:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452096 00000100:00100000:2.0:1787761263.253203:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 14 00000100:00100000:2.0:1787761263.253209:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000062a4c887 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+10:19341:x1874603194452096:12345-0@lo:256:mount.lustre.0 20000000:01000000:2.0:1787761263.253222:0:19354:0:(mgs_nids.c:914:mgs_get_ir_logs()) Reading IR log lustre-mdtir bufsize 1048576. 20000000:01000000:2.0:1787761263.253227:0:19354:0:(mgs_nids.c:318:mgs_nidtbl_read()) Read IR logs lustre return with 0, version 1 00000100:00100000:2.0:1787761263.253328:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000062a4c887 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+10:19341:x1874603194452096:12345-0@lo:256:mount.lustre.0 Request processed in 119us (196us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.253335:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 14 00000100:00100000:3.0:1787761263.253341:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452096:0@lo:256:mount.lustre.0 10000000:01000000:3.0:1787761263.253843:0:19341:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.203.155@tcp: configuration from log 'lustre-mdtir' succeeded (0). 00010000:00010000:3.0:1787761263.253854:0:19341:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.203.155@tcp lock: 00000000abab4dc8/0x75911fc857d94b00 lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.253861:0:19341:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.203.155@tcp lock: 00000000abab4dc8/0x75911fc857d94b00 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761263.253867:0:19341:0:(mgc_request.c:1802:mgc_process_log()) Process log params-ffff96d348f11800 from 1 10000000:01000000:3.0:1787761263.253869:0:19341:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for params (res 0x736d61726170) 00010000:00010000:3.0:1787761263.253883:0:19341:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.203.155@tcp lock: 00000000f5797bce/0x75911fc857d94b0e lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.253889:0:19341:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.203.155@tcp lock: 00000000f5797bce/0x75911fc857d94b0e lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.253895:0:19341:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.203.155@tcp lock: 00000000f5797bce/0x75911fc857d94b0e lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.253905:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452224:0@lo:101:mount.lustre.0 00000100:00100000:3.0:1787761263.253930:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.253955:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 000000003171a396 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.253977:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452224 00000100:00100000:2.0:1787761263.253982:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452224 00000100:00100000:2.0:1787761263.254008:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 15 00000100:00100000:2.0:1787761263.254015:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000045fc8781 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+10:19341:x1874603194452224:12345-0@lo:101:mount.lustre.0 00010000:00010000:2.0:1787761263.254022:0:19357:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1787761263.254036:0:19357:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 000000004fb3b371/0x75911fc857d94b15 lrc: 2/0,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x75911fc857d94b0e expref: -99 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.254049:0:19357:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 000000004fb3b371/0x75911fc857d94b15 lrc: 3/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x75911fc857d94b0e expref: 11 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.254056:0:19357:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 000000004fb3b371/0x75911fc857d94b15 lrc: 3/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x75911fc857d94b0e expref: 11 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.254063:0:19357:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 000000004fb3b371, rc 0) 00000100:00100000:2.0:1787761263.254094:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000045fc8781 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+11:19341:x1874603194452224:12345-0@lo:101:mount.lustre.0 Request processed in 80us (165us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.254101:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 15 00000100:00100000:3.0:1787761263.254111:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452224:0@lo:101:mount.lustre.0 00010000:00010000:3.0:1787761263.254122:0:19341:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.203.155@tcp lock: 00000000f5797bce/0x75911fc857d94b0e lrc: 4/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b15 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.254129:0:19341:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.203.155@tcp lock: 00000000f5797bce/0x75911fc857d94b0e lrc: 4/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x75911fc857d94b15 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.254163:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452352:0@lo:501:mount.lustre.0 00000100:00100000:3.0:1787761263.254184:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.254197:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 000000003171a396 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.254222:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452352 00000100:00100000:2.0:1787761263.254227:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452352 00000100:00100000:2.0:1787761263.254263:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 16 00000100:00100000:2.0:1787761263.254270:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000b96af0e5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+11:19341:x1874603194452352:12345-0@lo:501:mount.lustre.0 00000100:00100000:2.0:1787761263.254360:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000b96af0e5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+11:19341:x1874603194452352:12345-0@lo:501:mount.lustre.0 Request processed in 91us (174us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.254369:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 16 00000100:00100000:3.0:1787761263.254375:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452352:0@lo:501:mount.lustre.0 00000100:00100000:3.0:1787761263.254402:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452480:0@lo:503:mount.lustre.0 00000100:00100000:3.0:1787761263.254433:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.254448:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set 000000003171a396 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.254480:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452480 00000100:00100000:2.0:1787761263.254485:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452480 00000100:00100000:2.0:1787761263.254512:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 17 00000100:00100000:2.0:1787761263.254519:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000853ac3a5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+11:19341:x1874603194452480:12345-0@lo:503:mount.lustre.0 00000100:00100000:2.0:1787761263.254595:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000853ac3a5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+11:19341:x1874603194452480:12345-0@lo:503:mount.lustre.0 Request processed in 77us (161us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.254603:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 17 00000100:00100000:3.0:1787761263.254609:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000154e6230 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452480:0@lo:503:mount.lustre.0 00000100:00100000:0.0:1787761263.254849:0:19390:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19390:1874603194452608:0@lo:502:llog_process_th.0 00000100:00100000:0.0:1787761263.254885:0:19390:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761263.254904:0:19390:0:(client.c:2715:ptlrpc_set_wait()) set 00000000fd5446b7 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.254923:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452608 00000100:00100000:2.0:1787761263.254931:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452608 00000100:00100000:2.0:1787761263.254951:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 18 00000100:00100000:2.0:1787761263.254954:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000c403d974 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+11:19390:x1874603194452608:12345-0@lo:502:llog_process_th.0 00000100:00100000:2.0:1787761263.255195:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000c403d974 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+11:19390:x1874603194452608:12345-0@lo:502:llog_process_th.0 Request processed in 240us (309us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.255201:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 18 00000100:00100000:0.0:1787761263.255220:0:19390:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@0000000090312856 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19390:1874603194452608:0@lo:502:llog_process_th.0 00000020:01000000:0.0:1787761263.255240:0:19390:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1787761263.255244:0:19390:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.255246:0:19390:0:(obd_config.c:1563:class_process_config()) marker 2 (0x1) general debug_raw_pointers 00000020:01000000:0.0:1787761263.255260:0:19390:0:(obd_config.c:2004:class_config_llog_handler()) cmd ce032, instance name: general-ffff96d348f11800 00000020:00000080:0.0:1787761263.255263:0:19390:0:(obd_config.c:1472:class_process_config()) processing cmd: ce032 00000020:01000000:0.0:1787761263.255279:0:19390:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1787761263.255280:0:19390:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.255281:0:19390:0:(obd_config.c:1563:class_process_config()) marker 2 (0x2) general debug_raw_pointers 00000020:01000000:0.0:1787761263.255283:0:19390:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1787761263.255284:0:19390:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.255285:0:19390:0:(obd_config.c:1563:class_process_config()) marker 3 (0x1) general lod.*.mdt_hash 00000020:01000000:0.0:1787761263.255287:0:19390:0:(obd_config.c:2004:class_config_llog_handler()) cmd ce032, instance name: general-ffff96d348f11800 00000020:00000080:0.0:1787761263.255288:0:19390:0:(obd_config.c:1472:class_process_config()) processing cmd: ce032 00000100:00100000:0.0:1787761263.255346:0:19390:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d2454412c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19390:1874603194452736:0@lo:502:llog_process_th.0 00000100:00100000:0.0:1787761263.255378:0:19390:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761263.255397:0:19390:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d3439a4900 going to sleep for 11 seconds 00000100:00100000:3.0:1787761263.255414:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452736 00000100:00100000:3.0:1787761263.255420:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452736 00000100:00100000:3.0:1787761263.255444:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 19 00000100:00100000:3.0:1787761263.255449:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d38206e050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+11:19390:x1874603194452736:12345-0@lo:502:llog_process_th.0 00000100:00100000:3.0:1787761263.255519:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d38206e050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+11:19390:x1874603194452736:12345-0@lo:502:llog_process_th.0 Request processed in 69us (139us total) trans 0 rc 0/0 00000100:00100000:3.0:1787761263.255526:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 19 00000100:00100000:0.0:1787761263.255544:0:19390:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d2454412c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19390:1874603194452736:0@lo:502:llog_process_th.0 00000020:01000000:0.0:1787761263.255568:0:19390:0:(obd_config.c:1893:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1787761263.255572:0:19390:0:(obd_config.c:1472:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1787761263.255574:0:19390:0:(obd_config.c:1563:class_process_config()) marker 3 (0x2) general lod.*.mdt_hash 00000040:00080000:0.0:1787761263.255576:0:19390:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x2:0x0] index 7 count 7 00000020:01000000:3.0:1787761263.255627:0:19341:0:(obd_config.c:2145:class_config_parse_llog()) Processed log params gen 1-6 (rc=0) 10000000:01000000:3.0:1787761263.255650:0:19341:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.203.155@tcp: configuration from log 'params' succeeded (0). 00010000:00010000:3.0:1787761263.255658:0:19341:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.203.155@tcp lock: ffff96d24ae26a00/0x75911fc857d94b0e lrc: 3/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b15 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.255699:0:19341:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.203.155@tcp lock: ffff96d24ae26a00/0x75911fc857d94b0e lrc: 2/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b15 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1787761263.255744:0:19341:0:(mgc_request.c:1944:mgc_process_config()) parse_log lustre-client from 0 10000000:01000000:3.0:1787761263.255747:0:19341:0:(mgc_request.c:329:config_log_add()) add config log lustre-client-ffff96d348f11800 10000000:01000000:3.0:1787761263.255750:0:19341:0:(mgc_request.c:194:do_config_log_add()) do adding config log lustre-client-ffff96d348f11800 10000000:01000000:3.0:1787761263.255754:0:19341:0:(mgc_request.c:68:mgc_name2resid()) log lustre-client to resid 0x65727473756c/0x0 (lustre) 10000000:01000000:3.0:1787761263.255758:0:19341:0:(mgc_request.c:1802:mgc_process_log()) Process log lustre-client-ffff96d348f11800 from 1 10000000:01000000:3.0:1787761263.255760:0:19341:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for lustre-client (res 0x65727473756c) 00010000:00010000:3.0:1787761263.255776:0:19341:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.203.155@tcp lock: ffff96d24ae26800/0x75911fc857d94b1c lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.255783:0:19341:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.203.155@tcp lock: ffff96d24ae26800/0x75911fc857d94b1c lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.255789:0:19341:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.203.155@tcp lock: ffff96d24ae26800/0x75911fc857d94b1c lrc: 3/1,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.255801:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d242adf0c0 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452864:0@lo:101:mount.lustre.0 00000100:00100000:3.0:1787761263.255824:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.255849:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d377f5a600 going to sleep for 11 seconds 00000100:00100000:0.0:1787761263.255855:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452864 00000100:00100000:0.0:1787761263.255860:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452864 00000100:00100000:0.0:1787761263.255896:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 20 00000100:00100000:0.0:1787761263.255905:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d38206dc50 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+11:19341:x1874603194452864:12345-0@lo:101:mount.lustre.0 00010000:00010000:0.0:1787761263.255912:0:19354:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:0.0:1787761263.255923:0:19354:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: ffff96d24ae02800/0x75911fc857d94b23 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x40000000000000 nid: local remote: 0x75911fc857d94b1c expref: -99 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:0.0:1787761263.255937:0:19354:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: ffff96d24ae02800/0x75911fc857d94b23 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0x75911fc857d94b1c expref: 12 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:0.0:1787761263.255945:0:19354:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: ffff96d24ae02800/0x75911fc857d94b23 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x75911fc857d94b1c expref: 12 pid: 19354 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:0.0:1787761263.255952:0:19354:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock ffff96d24ae02800, rc 0) 00000100:00100000:0.0:1787761263.255984:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d38206dc50 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+12:19341:x1874603194452864:12345-0@lo:101:mount.lustre.0 Request processed in 81us (159us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761263.255991:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 20 00000100:00100000:3.0:1787761263.255998:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d242adf0c0 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452864:0@lo:101:mount.lustre.0 00010000:00010000:3.0:1787761263.256010:0:19341:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.203.155@tcp lock: ffff96d24ae26800/0x75911fc857d94b1c lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b23 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1787761263.256018:0:19341:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.203.155@tcp lock: ffff96d24ae26800/0x75911fc857d94b1c lrc: 4/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x1000000000000 nid: local remote: 0x75911fc857d94b23 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1787761263.256077:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d242adf0c0 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452992:0@lo:501:mount.lustre.0 00000100:00100000:3.0:1787761263.256108:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1787761263.256126:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d377f5a600 going to sleep for 11 seconds 00000100:00100000:0.0:1787761263.256135:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194452992 00000100:00100000:0.0:1787761263.256139:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194452992 00000100:00100000:0.0:1787761263.256160:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 21 00000100:00100000:0.0:1787761263.256166:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d343b70050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+12:19341:x1874603194452992:12345-0@lo:501:mount.lustre.0 00000100:00100000:0.0:1787761263.256229:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d343b70050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+12:19341:x1874603194452992:12345-0@lo:501:mount.lustre.0 Request processed in 63us (120us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761263.256234:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 21 00000100:00100000:3.0:1787761263.256243:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d242adf0c0 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194452992:0@lo:501:mount.lustre.0 00000100:00100000:3.0:1787761263.256288:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d242adf0c0 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194453120:0@lo:503:mount.lustre.0 00000100:00100000:3.0:1787761263.256326:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761263.256343:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194453120 00000100:00100000:3.0:1787761263.256344:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d377f5a600 going to sleep for 11 seconds 00000100:00100000:0.0:1787761263.256347:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194453120 00000100:00100000:0.0:1787761263.256371:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 22 00000100:00100000:0.0:1787761263.256376:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d24201f850 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+12:19341:x1874603194453120:12345-0@lo:503:mount.lustre.0 00000100:00100000:0.0:1787761263.256431:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d24201f850 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+12:19341:x1874603194453120:12345-0@lo:503:mount.lustre.0 Request processed in 55us (104us total) trans 0 rc 0/0 00000100:00100000:0.0:1787761263.256440:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 22 00000100:00100000:1.0:1787761263.256471:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d242adf0c0 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194453120:0@lo:503:mount.lustre.0 00000100:00100000:1.0:1787761263.256633:0:19392:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d2491d21c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19392:1874603194453248:0@lo:502:llog_process_th.0 00000100:00100000:1.0:1787761263.256685:0:19392:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761263.256715:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194453248 00000100:00100000:1.0:1787761263.256718:0:19392:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d24ae33780 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.256720:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194453248 00000100:00100000:2.0:1787761263.256747:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 23 00000100:00100000:2.0:1787761263.256754:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d24201dc50 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+12:19392:x1874603194453248:12345-0@lo:502:llog_process_th.0 00000100:00100000:2.0:1787761263.256826:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d24201dc50 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+12:19392:x1874603194453248:12345-0@lo:502:llog_process_th.0 Request processed in 73us (162us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.256832:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 23 00000100:00100000:1.0:1787761263.256851:0:19392:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d2491d21c0 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19392:1874603194453248:0@lo:502:llog_process_th.0 00000020:01000004:1.0:1787761263.256889:0:19392:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD lustre-MDT0000-lwp-MDT0000 (typ=lwp) 00000020:00000080:1.0:1787761263.256897:0:19392:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-lwp-MDT0000 (ffff96d344799a48) 00000020:00000080:1.0:1787761263.256907:0:19392:0:(obd_config.c:720:class_attach_name()) OBD: dev 10 attached type lwp with refcount 2 00000020:01000004:1.0:1787761263.256967:0:19392:0:(tgt_mount.c:153:server_get_mount()) get mount ffff96d348f11800 from lustre-MDT0000, refs=4 00000020:01000004:1.0:1787761263.256970:0:19392:0:(tgt_mount.c:187:server_put_mount()) put mount ffff96d348f11800 from lustre-MDT0000, refs=4 00000020:01000004:1.0:1787761263.256971:0:19392:0:(obd_mount.c:710:lustre_put_lsi()) put ffff96d348f11800 4 00010000:00080000:1.0:1787761263.256999:0:19392:0:(ldlm_lib.c:102:import_set_conn()) imp ffff96d351c7a800@lustre-MDT0000-lwp-MDT0000: add connection 192.168.203.155@tcp at head 00010000:00010000:1.0:1787761263.258459:0:19392:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-lustre-MDT0000-lwp-MDT0000-3 is initialized 00000020:00000080:1.0:1787761263.258629:0:19392:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-lwp-MDT0000 (uuid lustre-MDT0000-lwp-MDT0000_UUID) 00000010:01000000:1.0:1787761263.258661:0:19392:0:(lwp_dev.c:513:lwp_obd_connect()) connect #0 00000020:00000080:1.0:1787761263.258683:0:19392:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-lwp-MDT0000, cookie 0x75911fc857d94b31 00000100:00080000:1.0:1787761263.258689:0:19392:0:(import.c:510:import_select_connection()) lustre-MDT0000-lwp-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:1.0:1787761263.258693:0:19392:0:(import.c:624:import_select_connection()) lustre-MDT0000-lwp-MDT0000: import ffff96d351c7a800 using connection 192.168.203.155@tcp/0@lo 00000100:00100000:1.0:1787761263.258710:0:19392:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@ffff96d2491d21c0 x1874603194453376/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:00080000:1.0:1787761263.258726:0:19392:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import lustre-MDT0000-lwp-MDT0000_UUID->lustre-MDT0000_UUID 00000100:00100000:0.0:1787761263.258746:0:17936:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d2491d21c0 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-lwp-MDT0000_UUID:17936:1874603194453376:0@lo:38:llog_process_th.0 00000100:00100000:0.0:1787761263.258809:0:17936:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761263.258851:0:19362:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194453376 00000100:00100000:1.0:1787761263.258855:0:19362:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194453376 00000100:00100000:1.0:1787761263.258878:0:19362:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1787761263.258881:0:19362:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d2454412c0 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:0+-99:17936:x1874603194453376:12345-0@lo:38:llog_process_th.0 00000100:00100000:0.0:1787761263.258884:0:19363:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 3 min 3 max 116 00000100:00100000:0.0:1787761263.258892:0:19363:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_003' 00000100:00100000:1.0:1787761263.258922:0:19362:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d2454412c0 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:0+-99:17936:x1874603194453376:12345-0@lo:38:llog_process_th.0 Request processed in 39us (114us total) trans 0 rc -11/-11 00000100:00100000:1.0:1787761263.258927:0:19362:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:0.0:1787761263.258936:0:17936:0:(client.c:3125:ptlrpc_free_committed()) lustre-MDT0000-lwp-MDT0000: committing for last_committed 0 gen 2 00000100:00080000:0.0:1787761263.258942:0:17936:0:(import.c:65:import_set_state_nolock()) ffff96d351c7a800 lustre-MDT0000_UUID: changing import state from CONNECTING to DISCONN 00000100:00080000:0.0:1787761263.258947:0:17936:0:(import.c:1511:ptlrpc_connect_interpret()) recovery of lustre-MDT0000_UUID on 0@lo failed (-11) 00000100:00100000:0.0:1787761263.258951:0:17936:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d2491d21c0 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:lustre-MDT0000-lwp-MDT0000_UUID:17936:1874603194453376:0@lo:38:llog_process_th.0 00000100:00100000:1.0:1787761263.259032:0:19392:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d2491d2580 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19392:1874603194453504:0@lo:502:llog_process_th.0 00000100:00100000:1.0:1787761263.259075:0:19392:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1787761263.259101:0:19354:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194453504 00000100:00100000:1.0:1787761263.259104:0:19354:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194453504 00000100:00100000:1.0:1787761263.259129:0:19354:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 24 00000100:00100000:1.0:1787761263.259137:0:19354:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d24201f450 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+12:19392:x1874603194453504:12345-0@lo:502:llog_process_th.0 00000100:00100000:1.0:1787761263.259215:0:19354:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d24201f450 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:907262e2-bb62-4cd8-a453-7ec537117069+12:19392:x1874603194453504:12345-0@lo:502:llog_process_th.0 Request processed in 79us (139us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761263.259219:0:19354:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 24 00000100:00100000:1.0:1787761263.259245:0:19392:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d24ae33240 going to sleep for 11 seconds 00000100:00100000:1.0:1787761263.259271:0:19392:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d2491d2580 pname:cluuid:pid:xid:nid:opc:job llog_process_th:907262e2-bb62-4cd8-a453-7ec537117069:19392:1874603194453504:0@lo:502:llog_process_th.0 00000040:00080000:1.0:1787761263.259292:0:19392:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 42 count 42 00000020:01000000:0.0:1787761263.259345:0:19341:0:(obd_config.c:2145:class_config_parse_llog()) Processed log lustre-client gen 1-41 (rc=0) 10000000:01000000:0.0:1787761263.259374:0:19341:0:(mgc_request.c:1879:mgc_process_log()) MGC192.168.203.155@tcp: configuration from log 'lustre-client' succeeded (0). 00010000:00010000:0.0:1787761263.259387:0:19341:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.203.155@tcp lock: ffff96d24ae26800/0x75911fc857d94b1c lrc: 3/1,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b23 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:0.0:1787761263.259401:0:19341:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.203.155@tcp lock: ffff96d24ae26800/0x75911fc857d94b1c lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0x75911fc857d94b23 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000020:01000004:0.0:1787761263.259439:0:19341:0:(tgt_mount.c:1175:server_mti_print()) mti - server_notify_target 00000020:01000004:0.0:1787761263.259440:0:19341:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:0.0:1787761263.259441:0:19341:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:0.0:1787761263.259442:0:19341:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:0.0:1787761263.259443:0:19341:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:0.0:1787761263.259444:0:19341:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:0.0:1787761263.259445:0:19341:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:0.0:1787761263.259446:0:19341:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:0.0:1787761263.259448:0:19341:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:0.0:1787761263.259448:0:19341:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 10000000:01000000:0.0:1787761263.259451:0:19341:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target lustre-MDT0000 0x40020005 00000020:01000004:0.0:1787761263.259453:0:19341:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req 00000020:01000004:0.0:1787761263.259454:0:19341:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:0.0:1787761263.259459:0:19341:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:0.0:1787761263.259459:0:19341:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:0.0:1787761263.259460:0:19341:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:0.0:1787761263.259461:0:19341:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:0.0:1787761263.259462:0:19341:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:0.0:1787761263.259462:0:19341:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:0.0:1787761263.259463:0:19341:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:0.0:1787761263.259464:0:19341:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 10000000:01000000:0.0:1787761263.259474:0:19341:0:(mgc_request_server.c:281:mgc_target_register()) register lustre-MDT0000 00000100:00100000:0.0:1787761263.259482:0:19341:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d245443c00 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194453632:0@lo:253:mount.lustre.0 00000100:00100000:0.0:1787761263.259508:0:19341:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1787761263.259521:0:19341:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d3439a49c0 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.259938:0:19357:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194453632 00000100:00100000:2.0:1787761263.259942:0:19357:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194453632 00000100:00100000:2.0:1787761263.259968:0:19357:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 25 00000100:00100000:2.0:1787761263.259975:0:19357:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d24201c050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+12:19341:x1874603194453632:12345-0@lo:253:mount.lustre.0 20000000:01000000:2.0:1787761263.259990:0:19357:0:(mgs_handler.c:453:mgs_target_reg()) fs: lustre index: 0 is ready to reconnect. 20000000:01000000:2.0:1787761263.259998:0:19357:0:(mgs_nids.c:463:mgs_tnl_update()) nidtbl: write 1 NIDs to NET #0 20000000:01000000:2.0:1787761263.261157:0:19357:0:(mgs_nids.c:815:mgs_ir_update()) Try to revoke recover lock of lustre 20000000:01000000:2.0:1787761263.261168:0:19357:0:(mgs_handler.c:637:mgs_target_reg()) replying with lustre-MDT0000, index=0, rc=0 20000000:01000000:1.0:1787761263.261179:0:19378:0:(mgs_nids.c:712:mgs_ir_notify()) mgs_lustre_notify woken up, phase is 1 10000000:01000000:1.0:1787761263.261183:0:19378:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x2 (lustre) 00010000:00010000:1.0:1787761263.261195:0:19378:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(EX) ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 lrc: 3/0,1 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761263.261205:0:19378:0:(ldlm_lock.c:687:ldlm_add_bl_work_item()) ### lock incompatible; sending blocking AST. ns: MGS lock: ffff96d24b2ba200/0x75911fc857d94b07 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0x75911fc857d94b00 expref: 12 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761263.261211:0:19378:0:(ldlm_resource.c:1750:ldlm_resource_add_lock()) ### About to add this lock ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 lrc: 4/0,1 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761263.261228:0:19378:0:(ldlm_lockd.c:963:ldlm_server_blocking_ast()) ### server preparing blocking AST ns: MGS lock: ffff96d24b2ba200/0x75911fc857d94b07 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50000000000020 nid: 0@lo remote: 0x75911fc857d94b00 expref: 12 pid: 19357 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1787761263.261239:0:19378:0:(ldlm_lockd.c:495:ldlm_add_waiting_lock()) ### adding to wait list(timeout: 150, AT: on) ns: MGS lock: ffff96d24b2ba200/0x75911fc857d94b07 lrc: 4/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x70000400000020 nid: 0@lo remote: 0x75911fc857d94b00 expref: 12 pid: 19357 timeout: 1533 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:1.0:1787761263.261246:0:19378:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d2491d2580 pname:cluuid:pid:xid:nid:opc:job mgs_lustre_noti:MGS:19378:1874603194453760:0@lo:104: 00000100:00100000:1.0:1787761263.261299:0:19378:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761263.261317:0:19357:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d24201c050 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:907262e2-bb62-4cd8-a453-7ec537117069+12:19341:x1874603194453632:12345-0@lo:253:mount.lustre.0 Request processed in 1341us (1805us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.261324:0:19357:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 25 00000100:00100000:1.0:1787761263.261339:0:19378:0:(client.c:2715:ptlrpc_set_wait()) set ffff96d24ae33240 going to sleep for 11 seconds 00000100:00100000:2.0:1787761263.261356:0:19341:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d245443c00 pname:cluuid:pid:xid:nid:opc:job mount.lustre:907262e2-bb62-4cd8-a453-7ec537117069:19341:1874603194453632:0@lo:253:mount.lustre.0 00000100:00100000:1.0:1787761263.261359:0:19345:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194453760 00000100:00100000:1.0:1787761263.261363:0:19345:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194453760 10000000:01000000:2.0:1787761263.261364:0:19341:0:(mgc_request_server.c:302:mgc_target_register()) register lustre-MDT0000 got index = 0 00000020:01000004:2.0:1787761263.261367:0:19341:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: rep 00000020:01000004:2.0:1787761263.261373:0:19341:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000 00000020:01000004:2.0:1787761263.261375:0:19341:0:(tgt_mount.c:1177:server_mti_print()) fs: lustre 00000020:01000004:2.0:1787761263.261376:0:19341:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:2.0:1787761263.261377:0:19341:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:2.0:1787761263.261378:0:19341:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:2.0:1787761263.261379:0:19341:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:2.0:1787761263.261380:0:19341:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:2.0:1787761263.261381:0:19341:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:2.0:1787761263.261382:0:19341:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 00000020:02000000:2.0:1787761263.261392:0:19341:0:(tgt_mount.c:2692:server_calc_timeout()) lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 00000100:00100000:1.0:1787761263.261393:0:19345:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1787761263.261402:0:19345:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d2491d0780 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cb00_000:907262e2-bb62-4cd8-a453-7ec537117069+3:19378:x1874603194453760:12345-0@lo:104: 00000100:00100000:0.0:1787761263.261404:0:19346:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 2 min 2 max 56 00010000:00010000:1.0:1787761263.261410:0:19345:0:(ldlm_lockd.c:2506:ldlm_callback_handler()) ### blocking ast ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400000000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:0.0:1787761263.261414:0:19346:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_002' 00010000:00010000:1.0:1787761263.261450:0:19345:0:(ldlm_lockd.c:2189:__ldlm_bl_to_thread()) added 1/1 locks to priority blp list, 1 blwis in pool 00000100:00100000:1.0:1787761263.261454:0:19345:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d2491d0780 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cb00_000:907262e2-bb62-4cd8-a453-7ec537117069+3:19378:x1874603194453760:12345-0@lo:104: Request processed in 55us (156us total) trans 0 rc 0/0 00000100:00100000:1.0:1787761263.261458:0:19345:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:0.0:1787761263.261467:0:19378:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d2491d2580 pname:cluuid:pid:xid:nid:opc:job mgs_lustre_noti:MGS:19378:1874603194453760:0@lo:104: 00010000:00010000:0.0:1787761263.261483:0:19378:0:(ldlm_request.c:298:ldlm_completion_ast()) ### client-side enqueue returned a blocked locksleeping ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 lrc: 3/0,1 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263485:0:19350: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:1787761263.263491:0:19350:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400000000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263498:0:19350:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock ffff96d24ae26600 already unused, calling callback (ffffffffc12a9c20) 10000000:00010000:2.0:1787761263.263501:0:19350:0:(mgc_request.c:922:mgc_blocking_ast()) ### MGC blocking CB ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 2/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400400000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263507:0:19350:0:(ldlm_request.c:1391:ldlm_cli_cancel_local()) ### client-side cancel ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1408400000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:00010000:2.0:1787761263.263512:0:19350:0:(mgc_request.c:928:mgc_blocking_ast()) ### MGC cancel CB ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1409400000000 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:2.0:1787761263.263516:0:19350:0:(mgc_request.c:932:mgc_blocking_ast()) Lock res [0x65727473756c:0x2:0x0].0x0 (lustre) 00010000:00010000:2.0:1787761263.263547:0:19350:0:(ldlm_request.c:1439:__ldlm_pack_lock()) ### packing ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 2/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263552:0:19350:0:(ldlm_request.c:1498:ldlm_cancel_pack()) 1 locks packed 00010000:00010000:2.0:1787761263.263569:0:19350:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 1/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263574:0:19350:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGC192.168.203.155@tcp lock: ffff96d24ae26600/0x75911fc857d94b00 lrc: 0/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0x75911fc857d94b07 expref: -99 pid: 19341 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263595:0:19350:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761263.263597:0:19350:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1787761263.263598:0:19350:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00100000:1.0:1787761263.263648:0:17938:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@ffff96d342b0d680 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:907262e2-bb62-4cd8-a453-7ec537117069:17938:1874603194453888:0@lo:103:ldlm_bl.0 00000100:00100000:1.0:1787761263.263695:0:17938:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1787761263.263723:0:19347:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874603194453888 00000100:00100000:2.0:1787761263.263727:0:19347:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874603194453888 00010000:00010000:2.0:1787761263.263744:0:19347:0:(ldlm_lockd.c:2683:ldlm_cancel_hpreq_check()) ### hpreq cancel/convert lock ns: MGS lock: ffff96d24b2ba200/0x75911fc857d94b07 lrc: 4/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x60000400000020 nid: 0@lo remote: 0x75911fc857d94b00 expref: 12 pid: 19357 timeout: 1533 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1787761263.263768:0:19347:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1787761263.263772:0:19348:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 3 min 3 max 56 00000100:00100000:1.0:1787761263.263778:0:19348:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_003' 00000100:00100000:2.0:1787761263.263778:0:19347:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@ffff96d2491d3c00 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cn00_000:907262e2-bb62-4cd8-a453-7ec537117069+12:17938:x1874603194453888:12345-0@lo:103:ldlm_bl.0 00010000:00010000:2.0:1787761263.263791:0:19347:0:(ldlm_lockd.c:1747:ldlm_request_cancel()) ### server-side cancel handler START: 1 locks, starting at 0 00010000:00010000:2.0:1787761263.263797:0:19347:0:(ldlm_lockd.c:1796:ldlm_request_cancel()) ### server cancels blocked lock after 0s ns: MGS lock: ffff96d24b2ba200/0x75911fc857d94b07 lrc: 4/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x60000400000020 nid: 0@lo remote: 0x75911fc857d94b00 expref: 12 pid: 19357 timeout: 1533 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263808:0:19347:0:(ldlm_lockd.c:568:ldlm_del_waiting_lock()) ### removed ns: MGS lock: ffff96d24b2ba200/0x75911fc857d94b07 lrc: 3/0,0 mode: CR/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x50000400000020 nid: 0@lo remote: 0x75911fc857d94b00 expref: 12 pid: 19357 timeout: 1533 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263818:0:19347:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: ffff96d24b2ba200/0x75911fc857d94b07 lrc: 0/0,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x44801400000020 nid: 0@lo remote: 0x75911fc857d94b00 expref: 12 pid: 19357 timeout: 1533 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263827:0:19347:0:(ldlm_lock.c:715:ldlm_add_cp_work_item()) ### lock granted; sending completion AST. ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263832:0:19347:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 20000000:01000000:2.0:1787761263.263844:0:19347:0:(mgs_nids.c:688:mgs_ir_notify_complete()) Revoke recover lock of lustre completed after 0.002661043s 00010000:00010000:2.0:1787761263.263849:0:19347:0:(ldlm_lock.c:954:ldlm_lock_decref_and_cancel()) ### ldlm_lock_decref(EX) ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263867:0:19347:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(EX) ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263873:0:19347:0:(ldlm_lock.c:887:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263880:0:19347:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263885:0:19347:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock ffff96d24b238400 already unused, calling callback (ffffffffc0c73530) 00010000:00010000:2.0:1787761263.263889:0:19347:0:(ldlm_request.c:378:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263897:0:19347:0:(ldlm_request.c:1416:ldlm_cli_cancel_local()) ### server-side local cancel ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 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: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263916:0:19347:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 lrc: 4/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263924:0:19347:0:(ldlm_lockd.c:1808:ldlm_request_cancel()) ### server-side cancel handler END 00000100:00100000:2.0:1787761263.263955:0:19347:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@ffff96d2491d3c00 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cn00_000:907262e2-bb62-4cd8-a453-7ec537117069+11:17938:x1874603194453888:12345-0@lo:103:ldlm_bl.0 Request processed in 181us (260us total) trans 0 rc 0/0 00000100:00100000:2.0:1787761263.263961:0:19347:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1787761263.263970:0:17938:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@ffff96d342b0d680 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:907262e2-bb62-4cd8-a453-7ec537117069:17938:1874603194453888:0@lo:103:ldlm_bl.0 00010000:00010000:2.0:1787761263.263988:0:19378:0:(ldlm_request.c:190:ldlm_completion_tail()) ### client-side enqueue: destroyed ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 lrc: 1/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.263997:0:19378:0:(ldlm_request.c:557:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 lrc: 1/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1787761263.264003:0:19378:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: ffff96d24b238400/0x75911fc857d94b38 lrc: 0/0,0 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 19378 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000020:00080000:1.0:1787761263.266623:0:19401:0:(update_trans.c:1539:distribute_txn_commit_thread()) lustre-MDT0000: start commit thread committed batchid 0 00000040:01000000:3.0:1787761263.266624:0:19341:0:(llog_obd.c:197:llog_setup()) obd lustre-MDT0000-osd ctxt 16 is initialized 00000020:00080000:1.0:1787761263.266628:0:19401:0:(update_trans.c:1590:distribute_txn_commit_thread()) lustre-MDT0000: batchid: 0 committed batchid 0 00000040:01000000:1.0:1787761263.266776:0:19402:0:(llog_osd.c:2246:llog_osd_get_cat_list()) cat list: disk size=32, read=32 00000040:01000000:3.0:1787761263.267030:0:19341:0:(llog_obd.c:197:llog_setup()) obd lustre-MDD0000 ctxt 12 is initialized 00000040:00080000:3.0:1787761263.267061:0:19341:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:1.0:1787761263.267197:0:19402:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000004:00000080:3.0:1787761263.270302:0:19341:0:(mdd_device.c:555:mdd_changelog_llog_init()) changelog starting index=0 00000040:01000000:3.0:1787761263.270332:0:19341:0:(llog_obd.c:197:llog_setup()) obd lustre-MDD0000 ctxt 14 is initialized 00000040:00080000:3.0:1787761263.270373:0:19341:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:3.0:1787761263.281700:0:19341:0:(llog.c:862:llog_process_thread()) stop processing catalog [0xa:0x5:0x0] index 64768 count 1 00000040:00080000:1.0:1787761263.283628:0:19402:0:(llog.c:862:llog_process_thread()) stop processing catalog [0x200000400:0x1:0x0] index 261376 count 1 00000004:00080000:1.0:1787761263.283695:0:19402:0:(lod_dev.c:521:lod_sub_recovery_thread()) lustre-MDT0000-osd retrieved update log, duration 0, retries 0 00000004:00080000:1.0:1787761263.283699:0:19402:0:(lod_dev.c:545:lod_sub_recovery_thread()) lustre-MDT0000 got update logs from all MDTs. 00000040:00080000:3.0:1787761263.283881:0:19341:0:(llog.c:862:llog_process_thread()) stop processing catalog [0xa:0x6:0x0] index 64768 count 1 00000040:01000000:3.0:1787761263.283908:0:19341:0:(llog_obd.c:197:llog_setup()) obd lustre-MDD0000 ctxt 15 is initialized 00000040:00080000:3.0:1787761263.284037:0:19341:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00080000:10000000:3.0:1787761263.284518:0:19341:0:(osd_handler.c:5551:osd_index_try()) lustre-MDT0000: index object [0x200000003:0x35:0x0] (8/32) registered 00000001:00000004:3.0:1787761263.285538:0:19341:0:(tgt_lastrcvd.c:727:tgt_server_data_update()) lustre-MDT0000_UUID: mount_count is 2, last_transno is 8589934592 00000001:00080000:3.0:1787761263.286725:0:19341: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:3.0:1787761263.286742:0:19341:0:(mdd_device.c:2304:mdd_iocontrol()) lustre-MDD0000: cmd=c00866e6 len=0 karg=ffffbc5a81877988 00100000:10000000:3.0:1787761263.286747:0:19341:0:(lfsck_lib.c:3085:lfsck_start()) lustre-MDT0000-osd: start master thread 00000020:01000004:2.0:1787761263.287044:0:19341:0:(tgt_mount.c:298:server_mgc_clear_fs()) Unassign mgc disk 10000000:01000000:2.0:1787761263.287055:0:19341:0:(mgc_request_server.c:166:mgc_fs_clear()) MGC192.168.203.155@tcp: cl_mgc_mutex unlock 00000020:01000004:2.0:1787761263.287075:0:19341:0:(tgt_mount.c:2458:server_fill_super_common()) Server sb, dev=46 00000080:00000004:2.0:1787761263.287088:0:19341:0:(super25.c:182:lustre_fill_super()) /dev/mapper/mds1_flakey: Mount complete 00000020:00000004:2.0:1787761263.287957:0:19341:0:(tgt_mount.c:2344:server_getattr()) lustre-MDT0000: root_inode from vfsmnt ino=2, dev=0 00000020:00000004:2.0:1787761263.288117:0:19341:0:(tgt_mount.c:2359:is_cmd_supported()) ioctl cmd=81009431 Debug log: 993 lines, 993 kept, 0 dropped, 0 bad.