00000001:02000400:2.0F:1782270212.616935:0:371540:0:(debug.c:654:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg225-server.virtnet: executing set_hostid 00000001:02000400:3.0F:1782270220.526985:0:371736:0:(debug.c:654:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg225-server.virtnet: executing load_modules_local 00000001:01000000:3.0:1782270221.299771:0:371798:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm adler32 speed = 1315 MB/s 00000001:01000000:3.0:1782270221.549216:0:371798:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32 speed = 1739 MB/s 00000001:01000000:3.0:1782270221.799148:0:371798:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32c speed = 11115 MB/s 00000020:02000000:2.0:1782270221.910732:0:371835:0:(class_obd.c:804:obdclass_init()) Lustre: Build Version: 2.17.54_83_g947bf2b 00000400:02000000:3.0:1782270222.009443:0:371850:0:(api-ni.c:2752:lnet_startup_lndni()) Added LNI 192.168.202.125@tcp [8/256/0/180] 00008000:02000000:2.0:1782270224.106282:0:371990:0:(echo_client.c:2573:obdecho_init()) Echo OBD driver; http://www.lustre.org/ 00000020:01000004:2.0:1782270238.342570:0:373621:0:(obd_mount.c:914:lmd_print()) mount data: 00000020:01000004:2.0:1782270238.342579:0:373621:0:(obd_mount.c:917:lmd_print()) device: /dev/mapper/mds1_flakey 00000020:01000004:2.0:1782270238.342581:0:373621:0:(obd_mount.c:920:lmd_print()) options: user_xattr,errors=remount-ro 00000080:01200004:2.0:1782270238.342710:0:373621:0:(super25.c:130:lustre_fill_super()) VFS Op: sb 00000000a7a21454 00000080:02000400:2.0:1782270238.342723:0:373621:0:(super25.c:154:lustre_fill_super()) tst250fs-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' 00000020:01000004:2.0:1782270238.346739:0:373621:0:(tgt_mount.c:2500:osd_start()) Attempting to start tst250fs-MDT0000, type=osd-ldiskfs, lsifl=200065, mountfl=0 00000020:01000004:2.0:1782270238.346751:0:373621:0:(obd_mount.c:221:lustre_start_simple()) Starting OBD tst250fs-MDT0000-osd (typ=osd-ldiskfs) 00000020:00000080:2.0:1782270238.346786:0:373621:0:(genops.c:413:class_newdev()) Allocate new device tst250fs-MDT0000-osd (00000000616b552b) 00000020:00000080:2.0:1782270238.346819:0:373621:0:(obd_config.c:720:class_attach_name()) OBD: dev 0 attached type osd-ldiskfs with refcount 2 00100000:10000000:3.0:1782270238.371830:0:373621:0:(scrub.c:229:scrub_file_store()) tst250fs-MDT0000: store scrub file: rc = 0 00100000:10000000:3.0:1782270238.371925:0:373621:0:(scrub.c:229:scrub_file_store()) tst250fs-MDT0000: store scrub file: rc = 0 00080000:01000000:3.0:1782270238.384937:0:373621:0:(osd_lproc.c:911:osd_procfs_init()) tst250fs-MDT0000: register osd-ldiskfs tunable parameters 00000020:00000080:3.0:1782270238.385335:0:373621:0:(obd_config.c:826:class_setup()) finished setup of obd tst250fs-MDT0000-osd (uuid tst250fs-MDT0000-osd_UUID) 00080000:01000000:3.0:1782270238.385345:0:373621:0:(osd_handler.c:8929:osd_obd_connect()) connect #0 00000020:00000080:3.0:1782270238.385363:0:373621:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDT0000-osd_UUID, cookie 0xbc32a8285684890c 00000020:01000004:3.0:1782270238.385372:0:373621:0:(tgt_mount.c:2585:server_fill_super()) Found service tst250fs-MDT0000 on device /dev/mapper/mds1_flakey 00000020:01000000:3.0:1782270238.385379:0:373621:0:(tgt_mount.c:219:server_start_mgs()) Start MGS service MGS 00000020:01000004:3.0:1782270238.385385:0:373621:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000a7a21454 from MGS 00000020:01000004:3.0:1782270238.385392:0:373621:0:(obd_mount.c:221:lustre_start_simple()) Starting OBD MGS (typ=mgs) 00000020:00000080:3.0:1782270238.385412:0:373621:0:(genops.c:413:class_newdev()) Allocate new device MGS (0000000050ea3c07) 00000020:00000080:3.0:1782270238.385425:0:373621:0:(obd_config.c:720:class_attach_name()) OBD: dev 1 attached type mgs with refcount 2 00000020:01000004:3.0:1782270238.385561:0:373621:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000a7a21454 from MGS, refs=2 00080000:01000000:3.0:1782270238.385568:0:373621:0:(osd_handler.c:8929:osd_obd_connect()) connect #1 00000020:00000080:3.0:1782270238.385575:0:373621:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDT0000-osd_UUID, cookie 0xbc32a8285684891a 00000100:00100000:3.0:1782270238.385695:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_cbd: allocate 1 new 8192-byte reqbufs (0/1 left), rc = 0 00000100:00100000:3.0:1782270238.385855:0:373621:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 0 min 2 max 56 00000100:00100000:3.0:1782270238.385862:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_000' 00000100:00100000:2.0:1782270238.386572:0:373621:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 1 min 2 max 56 00000100:00100000:2.0:1782270238.386584:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_001' 00000100:00100000:2.0:1782270238.387629:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_canceld: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1782270238.387880:0:373621:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 0 min 3 max 56 00000100:00100000:2.0:1782270238.387887:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_000' 00000100:00100000:2.0:1782270238.388708:0:373621:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 1 min 3 max 56 00000100:00100000:2.0:1782270238.388715:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_001' 00000100:00100000:2.0:1782270238.389820:0:373621:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 2 min 3 max 56 00000100:00100000:2.0:1782270238.389826:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_002' 00010000:00010000:0.0F:1782270238.390531:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:0.0:1782270238.390537:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:0.0:1782270238.390540:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1782270238.390793:0:373633:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1782270238.390804:0:373633:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1782270238.390806:0:373633:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:2.0:1782270238.391281:0:373621:0:(ldlm_pool.c:925:ldlm_pool_init()) Lock pool ldlm-pool-MGS-0 is initialized 00010000:00010000:0.0:1782270238.395298:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000001:01000000:3.0:1782270238.641199:0:373621:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip512 speed = 6500 MB/s 00000001:01000000:3.0:1782270238.891167:0:373621:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip4K speed = 7719 MB/s 00000001:01000000:3.0:1782270239.141256:0:373621:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc512 speed = 1387 MB/s 00000001:01000000:3.0:1782270239.391620:0:373621:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc4K speed = 1475 MB/s 00080000:10000000:3.0:1782270239.395506:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0x2:0x0] (8/32) registered 00000040:01000000:3.0:1782270239.402173:0:373621:0:(llog_obd.c:197:llog_setup()) obd MGS ctxt 0 is initialized 10000000:01000000:2.0:1782270239.404641:0:373636:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x2 (params) 20000000:01000000:3.0:1782270239.404691:0:373621:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2 20000000:01000000:3.0:1782270239.404754:0:373621:0:(mgs_llog.c:683:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 00000040:00080000:3.0:1782270239.405051:0:373621:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 20000000:01000000:3.0:1782270239.405092:0:373621:0:(mgs_llog.c:683:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 00000100:00100000:3.0:1782270239.405625:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) mgs: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:3.0:1782270239.405868:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 0 min 3 max 32 00000100:00100000:3.0:1782270239.405876:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0000' 00000100:00100000:2.0:1782270239.407049:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 1 min 3 max 32 00000100:00100000:2.0:1782270239.407060:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0001' 00000100:00100000:3.0:1782270239.407441:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 2 min 3 max 32 00000100:00100000:3.0:1782270239.407448:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0002' 00000100:00080000:2.0:1782270239.408035:0:373641:0:(pinger.c:468:ping_evictor_main()) Starting Ping Evictor 00000020:00000080:3.0:1782270239.408105:0:373621:0:(obd_config.c:826:class_setup()) finished setup of obd MGS (uuid MGS) 00000020:01000004:3.0:1782270239.408157:0:373621:0:(obd_mount.c:402:lustre_start_mgc()) Start MGC 'MGC192.168.202.125@tcp' 00000020:01000004:3.0:1782270239.408160:0:373621:0:(obd_mount.c:411:lustre_start_mgc()) mgs NIDs (null). 00000020:01000004:3.0:1782270239.408212:0:373621:0:(obd_mount.c:221:lustre_start_simple()) Starting OBD MGC192.168.202.125@tcp (typ=mgc) 00010000:00010000:2.0:1782270239.408226:0:373633:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000020:00000080:3.0:1782270239.408227:0:373621:0:(genops.c:413:class_newdev()) Allocate new device MGC192.168.202.125@tcp (00000000041fe8c6) 00000020:00000080:3.0:1782270239.408249:0:373621:0:(obd_config.c:720:class_attach_name()) OBD: dev 2 attached type mgc with refcount 2 00010000:00080000:3.0:1782270239.408371:0:373621:0:(ldlm_lib.c:102:import_set_conn()) imp 000000003457fd84@MGC192.168.202.125@tcp: add connection 192.168.202.125@tcp at head 00010000:00010000:3.0:1782270239.408559:0:373621:0:(ldlm_pool.c:925:ldlm_pool_init()) Lock pool ldlm-pool-MGC192.168.202.125@tcp-0 is initialized 00000040:01000000:3.0:1782270239.408566:0:373621:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.202.125@tcp ctxt 1 is initialized 10000000:01000000:3.0:1782270239.409058:0:373642:0:(mgc_request.c:631:mgc_requeue_thread()) Starting requeue thread 00000020:00000080:2.0:1782270239.409176:0:373621:0:(obd_config.c:826:class_setup()) finished setup of obd MGC192.168.202.125@tcp (uuid 1bf7dd3d-5ee7-4e19-99af-a84d44812a4e) 00000020:00000080:2.0:1782270239.409196:0:373621:0:(genops.c:1406:class_connect()) connect: client 1bf7dd3d-5ee7-4e19-99af-a84d44812a4e, cookie 0xbc32a82856848928 00000100:00080000:2.0:1782270239.409209:0:373621:0:(import.c:512:import_select_connection()) MGC192.168.202.125@tcp: connect to NID 0@lo last attempt 0 00000100:00080000:2.0:1782270239.409215:0:373621:0:(import.c:626:import_select_connection()) MGC192.168.202.125@tcp: import 000000003457fd84 using connection 192.168.202.125@tcp/0@lo 00000100:00100000:2.0:1782270239.409812:0:373621:0:(import.c:828:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@000000008ac5d3aa x1868845780304000/t0(0) o250->MGC192.168.202.125@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:1782270239.409839:0:373621:0:(pinger.c:375:ptlrpc_pinger_add_import()) adding pingable import 1bf7dd3d-5ee7-4e19-99af-a84d44812a4e->MGS 00000020:01000004:2.0:1782270239.409856:0:373621:0:(tgt_mount.c:1809:server_start_targets()) starting target tst250fs-MDT0000 00000020:01000004:2.0:1782270239.409862:0:373621:0:(obd_mount.c:221:lustre_start_simple()) Starting OBD MDS (typ=mds) 00000020:00000080:2.0:1782270239.409876:0:373621:0:(genops.c:413:class_newdev()) Allocate new device MDS (00000000c3aec35a) 00000020:00000080:2.0:1782270239.409887:0:373621:0:(obd_config.c:720:class_attach_name()) OBD: dev 3 attached type mds with refcount 2 00000100:00100000:3.0:1782270239.409936:0:371865:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000008ac5d3aa pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:371865:1868845780304000:0@lo:250: 00000100:00100000:3.0:1782270239.410040:0:371865:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.410113:0:373638:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304000 00000100:00100000:3.0:1782270239.410159:0:373638:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304000 00000100:00100000:3.0:1782270239.410196:0:373638:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1782270239.410202:0:373638:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000008cc0edc5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:0+-99:371865:x1868845780304000:12345-0@lo:250: 00010000:00080000:3.0:1782270239.410227:0:373638:0:(ldlm_lib.c:1432:target_handle_connect()) MGS: connection from 1bf7dd3d-5ee7-4e19-99af-a84d44812a4e@0@lo t0 exp 0000000000000000 cur 13042 last 0 00000020:00000080:3.0:1782270239.410252:0:373638:0:(genops.c:1406:class_connect()) connect: client 1bf7dd3d-5ee7-4e19-99af-a84d44812a4e, cookie 0xbc32a82856848936 00000100:00080000:3.0:1782270239.410397:0:373638:0:(import.c:65:import_set_state_nolock()) 000000000f319c8c : changing import state from RECOVER to FULL 00000100:00100000:3.0:1782270239.410456:0:373638:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000008cc0edc5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+5:371865:x1868845780304000:12345-0@lo:250: Request processed in 251us (415us total) trans 0 rc 0/0 00000100:00100000:3.0:1782270239.410465:0:373638:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1782270239.410516:0:371865:0:(client.c:3111:ptlrpc_free_committed()) MGC192.168.202.125@tcp: committing for last_committed 0 gen 1 00000100:00080000:3.0:1782270239.410526:0:371865:0:(import.c:1134:ptlrpc_connect_interpret()) MGC192.168.202.125@tcp: connect to target with instance 0 00000100:00080000:3.0:1782270239.410534:0:371865:0:(import.c:961:ptlrpc_connect_set_flags()) MGC192.168.202.125@tcp: Resetting ns_connect_flags to server flags: 0xa000011001002060 10000000:01000000:3.0:1782270239.410545:0:371865:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808005 00000100:00080000:3.0:1782270239.410559:0:371865:0:(import.c:65:import_set_state_nolock()) 000000003457fd84 MGS: changing import state from CONNECTING to FULL 10000000:01000000:3.0:1782270239.410563:0:371865:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808004 00000100:00080000:3.0:1782270239.410573:0:371865:0:(pinger.c:186:ptlrpc_pinger_ir_up()) IR up 00000100:00100000:3.0:1782270239.410581:0:371865:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000008ac5d3aa pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:371865:1868845780304000:0@lo:250: 00000100:00100000:2.0:1782270239.423988:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt: allocate 64 new 262144-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1782270239.424266:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 0 min 3 max 116 00000100:00100000:2.0:1782270239.424274:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_000' 00000100:00100000:2.0:1782270239.424962:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 1 min 3 max 116 00000100:00100000:2.0:1782270239.424970:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_001' 00000100:00100000:2.0:1782270239.425330:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 2 min 3 max 116 00000100:00100000:2.0:1782270239.425336:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_002' 00000100:00100000:2.0:1782270239.426043:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_readpage: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1782270239.426257:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 0 min 2 max 80 00000100:00100000:2.0:1782270239.426261:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_000' 00000100:00100000:3.0:1782270239.426667:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 1 min 2 max 80 00000100:00100000:3.0:1782270239.426674:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_001' 00000100:00100000:2.0:1782270239.459473:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_out: allocate 64 new 1048576-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1782270239.459729:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 0 min 2 max 116 00000100:00100000:2.0:1782270239.459737:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_000' 00000100:00100000:2.0:1782270239.463797:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 1 min 2 max 116 00000100:00100000:2.0:1782270239.463814:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_001' 00000100:00100000:2.0:1782270239.464500:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqs: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1782270239.464660:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 0 min 2 max 256 00000100:00100000:2.0:1782270239.464665:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0000' 00000100:00100000:3.0:1782270239.465226:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 1 min 2 max 256 00000100:00100000:3.0:1782270239.465238:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0001' 00000100:00100000:2.0:1782270239.465885:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqm: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1782270239.465999:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 0 min 2 max 256 00000100:00100000:2.0:1782270239.466005:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0000' 00000100:00100000:3.0:1782270239.466458:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 1 min 2 max 256 00000100:00100000:3.0:1782270239.466512:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0001' 00000100:00100000:2.0:1782270239.466938:0:373621:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_fld: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0 00000100:00100000:2.0:1782270239.467087:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 0 min 2 max 256 00000100:00100000:2.0:1782270239.467093:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0000' 00000100:00100000:2.0:1782270239.467558:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 1 min 2 max 256 00000100:00100000:2.0:1782270239.467570:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0001' 00000100:00100000:3.0:1782270239.477953:0:373621: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:1782270239.478189:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 0 min 3 max 116 00000100:00100000:3.0:1782270239.478194:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_000' 00000100:00100000:3.0:1782270239.479434:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 1 min 3 max 116 00000100:00100000:3.0:1782270239.479443:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_001' 00000100:00100000:2.0:1782270239.480238:0:373621:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 2 min 3 max 116 00000100:00100000:2.0:1782270239.480247:0:373621:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_002' 00000020:00000080:2.0:1782270239.481051:0:373621:0:(obd_config.c:826:class_setup()) finished setup of obd MDS (uuid MDS_uuid) 00000020:01000004:2.0:1782270239.481081:0:373621:0:(tgt_mount.c:280:server_mgc_set_fs()) Set mgc disk for /dev/mapper/mds1_flakey 10000000:01000000:2.0:1782270239.481087:0:373621:0:(mgc_request_server.c:89:mgc_fs_setup()) MGC192.168.202.125@tcp: cl_mgc_mutex tst250fs-MDT0000-osd for locked: rc = 0 00000040:01000000:2.0:1782270239.481259:0:373621:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.202.125@tcp ctxt 0 is initialized 00000020:01000004:2.0:1782270239.481292:0:373621:0:(tgt_mount.c:1418:server_register_target()) Registration tst250fs-MDT0000, fs=tst250fs, 192.168.202.125@tcp, index=0000, flags=0x20065 00000020:01000004:2.0:1782270239.481296:0:373621:0:(tgt_mount.c:1175:server_mti_print()) mti - server_register_target 00000020:01000004:2.0:1782270239.481298:0:373621:0:(tgt_mount.c:1176:server_mti_print()) server: tst250fs-MDT0000 00000020:01000004:2.0:1782270239.481299:0:373621:0:(tgt_mount.c:1177:server_mti_print()) fs: tst250fs 00000020:01000004:2.0:1782270239.481300:0:373621:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:2.0:1782270239.481301:0:373621:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:2.0:1782270239.481302:0:373621:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:2.0:1782270239.481303:0:373621:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:2.0:1782270239.481305:0:373621:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:2.0:1782270239.481306:0:373621:0:(tgt_mount.c:1192:server_mti_print()) LDD_F_VIRIGIN 00000020:01000004:2.0:1782270239.481307:0:373621:0:(tgt_mount.c:1194:server_mti_print()) LDD_F_UPDATE 00000020:01000004:2.0:1782270239.481308:0:373621:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:2.0:1782270239.481310:0:373621:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 10000000:01000000:2.0:1782270239.481313:0:373621:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target tst250fs-MDT0000 0x10020065 00000020:01000004:2.0:1782270239.481315:0:373621:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req 00000020:01000004:2.0:1782270239.481316:0:373621:0:(tgt_mount.c:1176:server_mti_print()) server: tst250fs-MDT0000 00000020:01000004:2.0:1782270239.481317:0:373621:0:(tgt_mount.c:1177:server_mti_print()) fs: tst250fs 00000020:01000004:2.0:1782270239.481318:0:373621:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:2.0:1782270239.481319:0:373621:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:2.0:1782270239.481320:0:373621:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:2.0:1782270239.481321:0:373621:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:2.0:1782270239.481322:0:373621:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:2.0:1782270239.481323:0:373621:0:(tgt_mount.c:1192:server_mti_print()) LDD_F_VIRIGIN 00000020:01000004:2.0:1782270239.481323:0:373621:0:(tgt_mount.c:1194:server_mti_print()) LDD_F_UPDATE 00000020:01000004:2.0:1782270239.481324:0:373621:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:2.0:1782270239.481325:0:373621:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 10000000:01000000:2.0:1782270239.481351:0:373621:0:(mgc_request_server.c:281:mgc_target_register()) register tst250fs-MDT0000 00000100:00100000:2.0:1782270239.481364:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000001af174e6 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304128:0@lo:253: 00000100:00100000:2.0:1782270239.481439:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.481519:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 0000000059451e57 going to sleep for 11 seconds 00000100:00100000:3.0:1782270239.481562:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304128 00000100:00100000:3.0:1782270239.481567:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304128 00000100:00100000:3.0:1782270239.481610:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 1 00000100:00100000:3.0:1782270239.481618:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000002b38fc9e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+5:373621:x1868845780304128:12345-0@lo:253: 20000000:01000000:3.0:1782270239.481662:0:373640:0:(mgs_llog.c:683:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:3.0:1782270239.481665:0:373640:0:(mgs_handler.c:479:mgs_target_reg()) fs: tst250fs index: 0 is registered to MGS. 10000000:01000000:3.0:1782270239.481961:0:373661:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs to resid 0x7366303532747374/0x2 (tst250fs) 20000000:01000000:1.0F:1782270239.481985:0:373640:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2 00000040:00080000:1.0:1782270239.482296:0:373640:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:3.0:1782270239.483087:0:373662:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 64768 count 1 20000000:01000000:1.0:1782270239.483205:0:373640:0:(mgs_llog.c:683:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0 20000000:01000000:1.0:1782270239.483209:0:373640:0:(mgs_handler.c:599:mgs_target_reg()) updating tst250fs-MDT0000, index=0 20000000:01000000:1.0:1782270239.483214:0:373640:0:(mgs_llog.c:867:mgs_set_index()) Set index for tst250fs-MDT0000 to 0 20000000:01000000:1.0:1782270239.483216:0:373640:0:(mgs_llog.c:3603:mgs_write_log_mdt()) writing new mdt tst250fs-MDT0000 20000000:01000000:1.0:1782270239.483225:0:373640:0:(mgs_llog.c:3163:mgs_write_log_lov()) Writing lov(tst250fs-MDT0000-mdtlov) log for tst250fs-MDT0000 00000040:00080000:1.0:1782270239.483343:0:373640:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:1.0:1782270239.483509:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].1, 224 off8416 20000000:01000000:1.0:1782270239.483522:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-MDT0000-mdtlov 0xcf001 lov tst250fs-MDT0000-mdtlov_UUID (null) (null) 00000040:00080000:1.0:1782270239.483538:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].2, 136 off8552 00000040:00080000:1.0:1782270239.483550:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].3, 176 off8728 00000040:00080000:1.0:1782270239.483563:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].4, 224 off8952 00000040:00080000:1.0:1782270239.483616:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].5, 224 off9176 20000000:01000000:1.0:1782270239.483623:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-MDT0000 0xcf001 mdt tst250fs-MDT0000_UUID (null) (null) 00000040:00080000:1.0:1782270239.483633:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].6, 128 off9304 20000000:01000000:1.0:1782270239.483637:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg (null) 0xcf007 tst250fs-MDT0000 tst250fs-MDT0000-mdtlov (null) (null) 00000040:00080000:1.0:1782270239.483647:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].7, 120 off9424 20000000:01000000:1.0:1782270239.483651:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-MDT0000 0xcf003 tst250fs-MDT0000_UUID 0 tst250fs-MDT0000-mdtlov f 00000040:00080000:1.0:1782270239.483659:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].8, 168 off9592 00000040:00080000:1.0:1782270239.483670:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].9, 224 off9816 00000040:00080000:1.0:1782270239.483691:0:373640:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 20000000:01000000:1.0:1782270239.483695:0:373640:0:(mgs_llog.c:3163:mgs_write_log_lov()) Writing lov(tst250fs-clilov) log for tst250fs-client 00000040:00080000:1.0:1782270239.483702:0:373640:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:1.0:1782270239.483783:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].1, 224 off8416 20000000:01000000:1.0:1782270239.483805:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-clilov 0xcf001 lov tst250fs-clilov_UUID (null) (null) 00000040:00080000:1.0:1782270239.483829:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].2, 120 off8536 00000040:00080000:1.0:1782270239.483846:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].3, 168 off8704 00000040:00080000:1.0:1782270239.483861:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].4, 224 off8928 20000000:01000000:1.0:1782270239.483871:0:373640:0:(mgs_llog.c:3120:mgs_write_log_lmv()) Writing lmv(tst250fs-clilmv) log for tst250fs-client 00000040:00080000:1.0:1782270239.483892:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].5, 224 off9152 20000000:01000000:1.0:1782270239.483899:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-clilmv 0xcf001 lmv tst250fs-clilmv_UUID (null) (null) 00000040:00080000:1.0:1782270239.483911:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].6, 120 off9272 00000040:00080000:1.0:1782270239.483937:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].7, 168 off9440 00000040:00080000:1.0:1782270239.483951:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].8, 224 off9664 20000000:01000000:1.0:1782270239.483961:0:373640:0:(mgs_llog.c:3085:mgs_write_log_mount_opt()) Writing mount options log for tst250fs-client 00000040:00080000:1.0:1782270239.483995:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].9, 224 off9888 20000000:01000000:1.0:1782270239.484003:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg (null) 0xcf007 tst250fs-client tst250fs-clilov tst250fs-clilmv (null) 00000040:00080000:1.0:1782270239.484016:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].10, 120 off10008 00000040:00080000:1.0:1782270239.484030:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].11, 224 off10232 00000040:00080000:1.0:1782270239.484079:0:373640:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 12 count 12 20000000:01000000:1.0:1782270239.484097:0:373640:0:(mgs_llog.c:3300:mgs_write_log_mdc_to_lmv()) adding mdc for tst250fs-MDT0000 to log tst250fs-client:lmv(tst250fs-clilmv) 20000000:01000000:1.0:1782270239.484104:0:373640:0:(mgs_llog.c:1106:mgs_modify()) modify tst250fs-client/tst250fs-MDT0000/add mdc fl=4 00000040:00080000:3.0:1782270239.484578:0:373663:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 12 count 12 00000040:00080000:1.0:1782270239.484688:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].12, 224 off10456 20000000:01000000:1.0:1782270239.484706:0:373640:0:(mgs_llog.c:3346:mgs_write_log_mdc_to_lmv()) add nid 192.168.202.125@tcp for mdt 20000000:01000000:1.0:1782270239.484707:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg (null) 0xcf005 192.168.202.125@tcp (null) (null) (null) 00000040:00080000:1.0:1782270239.484723:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].13, 88 off10544 20000000:01000000:1.0:1782270239.484729:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-MDT0000-mdc 0xcf001 mdc tst250fs-clilmv_UUID (null) (null) 00000040:00080000:1.0:1782270239.484741:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].14, 128 off10672 20000000:01000000:1.0:1782270239.484745:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-MDT0000-mdc 0xcf003 tst250fs-MDT0000_UUID 192.168.202.125@tcp (null) (null) 00000040:00080000:1.0:1782270239.484755:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].15, 144 off10816 20000000:01000000:1.0:1782270239.484761:0:373640:0:(mgs_llog.c:1536:record_base_raw()) lcfg tst250fs-clilmv 0xcf014 tst250fs-MDT0000_UUID 0 1 tst250fs-MDT0000-mdc_UUID 00000040:00080000:1.0:1782270239.484772:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].16, 168 off10984 00000040:00080000:1.0:1782270239.484801:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].17, 224 off11208 20000000:01000000:1.0:1782270239.484898:0:373640:0:(mgs_llog.c:5244:mgs_write_log_target()) remaining string: ' mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity ', param: 'sys.timeout=20' 20000000:01000000:1.0:1782270239.484901:0:373640:0:(mgs_llog.c:4738:mgs_write_log_param()) next param 'sys.timeout=20' 20000000:01000000:1.0:1782270239.484905:0:373640:0:(mgs_llog.c:4172:mgs_write_log_sys()) global 'sys.timeout=20' val=20 20000000:01000000:1.0:1782270239.484955:0:373640:0:(mgs_llog.c:2541:mgs_write_log_direct_all()) Changing log tst250fs-MDT0000 20000000:01000000:1.0:1782270239.484956:0:373640:0:(mgs_llog.c:1106:mgs_modify()) modify tst250fs-MDT0000/tst250fs/sys.timeout fl=4 00000040:00080000:3.0:1782270239.485238:0:373664:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 10 count 10 00000040:00080000:1.0:1782270239.485326:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].10, 224 off10040 00000040:00080000:1.0:1782270239.485359:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].11, 80 off10120 00000040:00080000:1.0:1782270239.485375:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].12, 224 off10344 20000000:01000000:1.0:1782270239.485384:0:373640:0:(mgs_llog.c:2541:mgs_write_log_direct_all()) Changing log tst250fs-client 20000000:01000000:1.0:1782270239.485386:0:373640:0:(mgs_llog.c:1106:mgs_modify()) modify tst250fs-client/tst250fs/sys.timeout fl=4 00000040:00080000:3.0:1782270239.485805:0:373665:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 18 count 18 00000040:00080000:1.0:1782270239.485923:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].18, 224 off11432 00000040:00080000:1.0:1782270239.485943:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].19, 80 off11512 00000040:00080000:1.0:1782270239.485958:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].20, 224 off11736 00000020:00000080:1.0:1782270239.485968:0:373640:0:(obd_config.c:1470:class_process_config()) processing cmd: cf009 00000020:00000080:1.0:1782270239.485970:0:373640:0:(obd_config.c:1535:class_process_config()) changing lustre timeout from 100 to 20 20000000:01000000:1.0:1782270239.485974:0:373640:0:(mgs_llog.c:5244:mgs_write_log_target()) remaining string: ' ', param: 'mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity' 20000000:01000000:1.0:1782270239.485976:0:373640:0:(mgs_llog.c:4738:mgs_write_log_param()) next param 'mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity' 20000000:01000000:1.0:1782270239.485979:0:373640:0:(mgs_llog.c:5063:mgs_write_log_param()) mdt param identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity 20000000:01000000:1.0:1782270239.485985:0:373640:0:(mgs_llog.c:1376:mgs_modify_param()) modify tst250fs-MDT0000/tst250fs-MDT0000/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity del=0 00000040:00080000:3.0:1782270239.486300:0:373666:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 13 count 13 20000000:02000000:1.0:1782270239.486367:0:373640:0:(mgs_llog.c:4111:mgs_wlp_lcfg()) Setting parameter tst250fs-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log tst250fs-MDT0000 00000040:00080000:1.0:1782270239.491653:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].13, 224 off10568 00000040:00080000:1.0:1782270239.491690:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].14, 168 off10736 00000040:00080000:1.0:1782270239.491707:0:373640:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].15, 224 off10960 10000000:01000000:1.0:1782270239.491730:0:373640:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs to resid 0x7366303532747374/0x0 (tst250fs) 00010000:00010000:1.0:1782270239.491750:0:373640:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(EX) ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 3/0,1 mode: --/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491765:0:373640:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 3/0,1 mode: EX/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491774:0:373640:0:(ldlm_lock.c:954:ldlm_lock_decref_and_cancel()) ### ldlm_lock_decref(EX) ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 4/0,1 mode: EX/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491780:0:373640:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(EX) ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 4/0,1 mode: EX/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491801:0:373640:0:(ldlm_lock.c:887:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 3/0,0 mode: EX/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491808:0:373640:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 4/0,0 mode: EX/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491827:0:373640:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock 000000005328941a already unused, calling callback (0000000069812618) 00010000:00010000:1.0:1782270239.491830:0:373640:0:(ldlm_request.c:378:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 4/0,0 mode: EX/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491837:0:373640:0:(ldlm_request.c:1416:ldlm_cli_cancel_local()) ### server-side local cancel ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 5/0,0 mode: EX/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491848:0:373640:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 3/0,0 mode: --/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491856:0:373640:0:(ldlm_request.c:557:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 1/0,0 mode: --/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.491861:0:373640:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: 000000005328941a/0xbc32a8285684893d lrc: 0/0,0 mode: --/EX res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 20000000:01000000:1.0:1782270239.491883:0:373640:0:(mgs_handler.c:637:mgs_target_reg()) replying with tst250fs-MDT0000, index=0, rc=0 00000100:00100000:1.0:1782270239.496191:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000002b38fc9e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+5:373621:x1868845780304128:12345-0@lo:253: Request processed in 14566us (14745us total) trans 0 rc 0/0 00000100:00100000:1.0:1782270239.496209:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 1 00000100:00100000:3.0:1782270239.496284:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000001af174e6 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304128:0@lo:253: 10000000:01000000:3.0:1782270239.496300:0:373621:0:(mgc_request_server.c:302:mgc_target_register()) register tst250fs-MDT0000 got index = 0 00000020:01000004:3.0:1782270239.496310:0:373621:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: rep 00000020:01000004:3.0:1782270239.496312:0:373621:0:(tgt_mount.c:1176:server_mti_print()) server: tst250fs-MDT0000 00000020:01000004:3.0:1782270239.496313:0:373621:0:(tgt_mount.c:1177:server_mti_print()) fs: tst250fs 00000020:01000004:3.0:1782270239.496314:0:373621:0:(tgt_mount.c:1178:server_mti_print()) uuid: tst250fs-MDT0000_UUID 00000020:01000004:3.0:1782270239.496315:0:373621:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1782270239.496317:0:373621:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1782270239.496319:0:373621:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1782270239.496320:0:373621:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1782270239.496321:0:373621:0:(tgt_mount.c:1196:server_mti_print()) LDD_F_REWRITE_LDD 00000020:01000004:3.0:1782270239.496322:0:373621:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1782270239.496323:0:373621:0:(tgt_mount.c:1216:server_mti_print()) LDD_F_OPC_REG 00000020:01000004:3.0:1782270239.496341:0:373621:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000a7a21454 from tst250fs-MDT0000 10000000:01000000:3.0:1782270239.496371:0:373621:0:(mgc_request.c:1945:mgc_process_config()) parse_log tst250fs-MDT0000 from 0 10000000:01000000:3.0:1782270239.496373:0:373621:0:(mgc_request.c:329:config_log_add()) add config log tst250fs-MDT0000-0000000000000000 10000000:01000000:3.0:1782270239.496377:0:373621:0:(mgc_request.c:194:do_config_log_add()) do adding config log tst250fs-sptlrpc-ffff89f330aab380 10000000:01000000:3.0:1782270239.496381:0:373621:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs-sptlrpc to resid 0x7366303532747374/0x0 (tst250fs) 10000000:01000000:3.0:1782270239.496388:0:373621:0:(mgc_request.c:1803:mgc_process_log()) Process log tst250fs-sptlrpc-ffff89f330aab380 from 1 10000000:01000000:3.0:1782270239.496391:0:373621:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for tst250fs-sptlrpc (res 0x7366303532747374) 00010000:00010000:3.0:1782270239.496425:0:373621:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.125@tcp lock: 00000000c600d965/0xbc32a82856848944 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.496446:0:373621:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.125@tcp lock: 00000000c600d965/0xbc32a82856848944 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.496454:0:373621:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.125@tcp lock: 00000000c600d965/0xbc32a82856848944 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.496471:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304256:0@lo:101: 00000100:00100000:3.0:1782270239.496505:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.496553:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304256 00000100:00100000:3.0:1782270239.496559:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 000000005fef6302 going to sleep for 11 seconds 00000100:00100000:2.0:1782270239.496561:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304256 00000100:00100000:2.0:1782270239.496612:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 2 00000100:00100000:2.0:1782270239.496619:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000006cabe690 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+5:373621:x1868845780304256:12345-0@lo:101: 00010000:00010000:2.0:1782270239.496632:0:373639:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1782270239.496644:0:373639:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 000000006758faba/0xbc32a8285684894b lrc: 2/0,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0xbc32a82856848944 expref: -99 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.496666:0:373639:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 000000006758faba/0xbc32a8285684894b lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0xbc32a82856848944 expref: 6 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.496677:0:373639:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 000000006758faba/0xbc32a8285684894b lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0xbc32a82856848944 expref: 6 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.496686:0:373639:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 000000006758faba, rc 0) 00000100:00100000:2.0:1782270239.496723:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000006cabe690 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+6:373621:x1868845780304256:12345-0@lo:101: Request processed in 105us (219us total) trans 0 rc 0/0 00000100:00100000:2.0:1782270239.496729:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 2 00000100:00100000:3.0:1782270239.496754:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304256:0@lo:101: 00010000:00010000:3.0:1782270239.496768:0:373621:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.125@tcp lock: 00000000c600d965/0xbc32a82856848944 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a8285684894b expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.496783:0:373621:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.125@tcp lock: 00000000c600d965/0xbc32a82856848944 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0xbc32a8285684894b expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.496840:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304384:0@lo:501: 00000100:00100000:3.0:1782270239.496865:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.496883:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 000000005fef6302 going to sleep for 11 seconds 00000100:00100000:1.0:1782270239.496898:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304384 00000100:00100000:1.0:1782270239.496903:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304384 00000100:00100000:1.0:1782270239.496944:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 3 00000100:00100000:1.0:1782270239.496950:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000002051a29 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+6:373621:x1868845780304384:12345-0@lo:501: 00000100:00100000:1.0:1782270239.497032:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000002051a29 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+6:373621:x1868845780304384:12345-0@lo:501: Request processed in 82us (166us total) trans 0 rc -2/-2 00000100:00100000:1.0:1782270239.497039:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 3 00000100:00100000:3.0:1782270239.497075:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304384:0@lo:501: 10000000:01000000:3.0:1782270239.497101:0:373621:0:(mgc_request.c:1880:mgc_process_log()) MGC192.168.202.125@tcp: configuration from log 'tst250fs-sptlrpc' failed (-2). 00010000:00010000:3.0:1782270239.497217:0:373621:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.125@tcp lock: 00000000c600d965/0xbc32a82856848944 lrc: 3/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a8285684894b expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.497226:0:373621:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.125@tcp lock: 00000000c600d965/0xbc32a82856848944 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a8285684894b expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1782270239.497233:0:373621:0:(mgc_request.c:194:do_config_log_add()) do adding config log params-ffff89f3058b9000 10000000:01000000:3.0:1782270239.497500:0:373621:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x3 (params) 10000000:01000000:3.0:1782270239.497506:0:373621:0:(mgc_request.c:194:do_config_log_add()) do adding config log tst250fs-barrier-ffff89f3058b9000 10000000:01000000:3.0:1782270239.497509:0:373621:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs-barrier to resid 0x7366303532747374/0x5 (tst250fs) 10000000:01000000:3.0:1782270239.497512:0:373621:0:(mgc_request.c:1803:mgc_process_log()) Process log tst250fs-barrier-ffff89f3058b9000 from 1 10000000:01000000:3.0:1782270239.497514:0:373621:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for tst250fs-barrier (res 0x7366303532747374) 00010000:00010000:3.0:1782270239.497530:0:373621:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.125@tcp lock: 0000000053aa08fe/0xbc32a82856848952 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.497537:0:373621:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.125@tcp lock: 0000000053aa08fe/0xbc32a82856848952 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.497544:0:373621:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.125@tcp lock: 0000000053aa08fe/0xbc32a82856848952 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.497563:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304512:0@lo:101: 00000100:00100000:3.0:1782270239.497590:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.497619:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 000000005fef6302 going to sleep for 11 seconds 00000100:00100000:2.0:1782270239.497638:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304512 00000100:00100000:2.0:1782270239.497643:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304512 00000100:00100000:2.0:1782270239.497671:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 4 00000100:00100000:2.0:1782270239.497677:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000008c5feb42 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+6:373621:x1868845780304512:12345-0@lo:101: 00010000:00010000:2.0:1782270239.497685:0:373639:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1782270239.497693:0:373639:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 00000000ecb8eb63/0xbc32a82856848959 lrc: 2/0,0 mode: --/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0xbc32a82856848952 expref: -99 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.497712:0:373639:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000ecb8eb63/0xbc32a82856848959 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0xbc32a82856848952 expref: 7 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.497720:0:373639:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 00000000ecb8eb63/0xbc32a82856848959 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0xbc32a82856848952 expref: 7 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.497733:0:373639:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 00000000ecb8eb63, rc 0) 00000100:00100000:2.0:1782270239.497764:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000008c5feb42 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+7:373621:x1868845780304512:12345-0@lo:101: Request processed in 88us (174us total) trans 0 rc 0/0 00000100:00100000:2.0:1782270239.497770:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 4 00000100:00100000:3.0:1782270239.497811:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304512:0@lo:101: 00010000:00010000:3.0:1782270239.497822:0:373621:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.125@tcp lock: 0000000053aa08fe/0xbc32a82856848952 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a82856848959 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.497829:0:373621:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.125@tcp lock: 0000000053aa08fe/0xbc32a82856848952 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0xbc32a82856848959 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1782270239.497840:0:373621:0:(mgc_request.c:1880:mgc_process_log()) MGC192.168.202.125@tcp: configuration from log 'tst250fs-barrier' succeeded (0). 00010000:00010000:3.0:1782270239.497856:0:373621:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.125@tcp lock: 0000000053aa08fe/0xbc32a82856848952 lrc: 3/1,0 mode: CR/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a82856848959 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.497862:0:373621:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.125@tcp lock: 0000000053aa08fe/0xbc32a82856848952 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x5:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a82856848959 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1782270239.497867:0:373621:0:(mgc_request.c:194:do_config_log_add()) do adding config log tst250fs-MDT0000-0000000000000000 10000000:01000000:3.0:1782270239.497871:0:373621:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs-MDT0000 to resid 0x7366303532747374/0x0 (tst250fs) 10000000:01000000:3.0:1782270239.497875:0:373621:0:(mgc_request.c:194:do_config_log_add()) do adding config log tst250fs-mdtir-ffff89f3058b9000 10000000:01000000:3.0:1782270239.497877:0:373621:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs-mdtir to resid 0x7366303532747374/0x2 (tst250fs) 10000000:01000000:3.0:1782270239.497880:0:373621:0:(mgc_request.c:1803:mgc_process_log()) Process log tst250fs-MDT0000-0000000000000000 from 1 10000000:01000000:3.0:1782270239.497882:0:373621:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for tst250fs-MDT0000 (res 0x7366303532747374) 00010000:00010000:3.0:1782270239.497894:0:373621:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.125@tcp lock: 000000002312ebe0/0xbc32a82856848960 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.497901:0:373621:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.125@tcp lock: 000000002312ebe0/0xbc32a82856848960 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.497913:0:373621:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.125@tcp lock: 000000002312ebe0/0xbc32a82856848960 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.497924:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304640:0@lo:101: 00000100:00100000:3.0:1782270239.497950:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.497966:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 000000005fef6302 going to sleep for 11 seconds 00000100:00100000:1.0:1782270239.497983:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304640 00000100:00100000:1.0:1782270239.497993:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304640 00000100:00100000:1.0:1782270239.498022:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 5 00000100:00100000:1.0:1782270239.498027:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000eb0647a5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+7:373621:x1868845780304640:12345-0@lo:101: 00010000:00010000:1.0:1782270239.498034:0:373640:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:1.0:1782270239.498041:0:373640:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 00000000ddb4f13a/0xbc32a82856848967 lrc: 2/0,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: local remote: 0xbc32a82856848960 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.498053:0:373640:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000ddb4f13a/0xbc32a82856848967 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0xbc32a82856848960 expref: 8 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.498060:0:373640:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 00000000ddb4f13a/0xbc32a82856848967 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0xbc32a82856848960 expref: 8 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.498071:0:373640:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 00000000ddb4f13a, rc 0) 00000100:00100000:1.0:1782270239.498104:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000eb0647a5 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+8:373621:x1868845780304640:12345-0@lo:101: Request processed in 77us (154us total) trans 0 rc 0/0 00000100:00100000:1.0:1782270239.498111:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 5 00000100:00100000:2.0:1782270239.498158:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@0000000096eb1c3e pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304640:0@lo:101: 00010000:00010000:2.0:1782270239.498169:0:373621:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.125@tcp lock: 000000002312ebe0/0xbc32a82856848960 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a82856848967 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.498175:0:373621:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.125@tcp lock: 000000002312ebe0/0xbc32a82856848960 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x1000000000000 nid: local remote: 0xbc32a82856848967 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1782270239.498227:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304768:0@lo:501: 00000100:00100000:2.0:1782270239.498252:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.498278:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 0000000059451e57 going to sleep for 11 seconds 00000100:00100000:0.0:1782270239.498306:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304768 00000100:00100000:0.0:1782270239.498311:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304768 00000100:00100000:0.0:1782270239.498350:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 6 00000100:00100000:0.0:1782270239.498355:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000045c07ee9 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+8:373621:x1868845780304768:12345-0@lo:501: 00000100:00100000:0.0:1782270239.498478:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000045c07ee9 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373621:x1868845780304768:12345-0@lo:501: Request processed in 123us (226us total) trans 0 rc 0/0 00000100:00100000:0.0:1782270239.498486:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 6 00000100:00100000:2.0:1782270239.498509:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304768:0@lo:501: 00000100:00100000:2.0:1782270239.498536:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304896:0@lo:503: 00000100:00100000:2.0:1782270239.498570:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.498586:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 0000000059451e57 going to sleep for 11 seconds 00000100:00100000:3.0:1782270239.498607:0:373638:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780304896 00000100:00100000:3.0:1782270239.498612:0:373638:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780304896 00000100:00100000:3.0:1782270239.498644:0:373638:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 7 00000100:00100000:3.0:1782270239.498651:0:373638:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000000f6fe32b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373621:x1868845780304896:12345-0@lo:503: 00000100:00100000:3.0:1782270239.498715:0:373638:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000000f6fe32b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373621:x1868845780304896:12345-0@lo:503: Request processed in 65us (144us total) trans 0 rc 0/0 00000100:00100000:3.0:1782270239.498720:0:373638:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 7 00000100:00100000:2.0:1782270239.498736:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780304896:0@lo:503: 00000100:00100000:0.0:1782270239.499032:0:373667:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000007b62e88e pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373667:1868845780305024:0@lo:502: 00000100:00100000:0.0:1782270239.499061:0:373667:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1782270239.499083:0:373667:0:(client.c:2701:ptlrpc_set_wait()) set 00000000b650432f going to sleep for 11 seconds 00000100:00100000:1.0:1782270239.499100:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305024 00000100:00100000:1.0:1782270239.499105:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305024 00000100:00100000:1.0:1782270239.499145:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 8 00000100:00100000:1.0:1782270239.499150:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000fcbcc0b0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373667:x1868845780305024:12345-0@lo:502: 00000100:00100000:1.0:1782270239.499228:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000fcbcc0b0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373667:x1868845780305024:12345-0@lo:502: Request processed in 78us (166us total) trans 0 rc 0/0 00000100:00100000:1.0:1782270239.499235:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 8 00000100:00100000:0.0:1782270239.499253:0:373667:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000007b62e88e pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373667:1868845780305024:0@lo:502: 00000020:01000000:0.0:1782270239.499274:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1782270239.499282:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1782270239.499284:0:373667:0:(obd_config.c:1561:class_process_config()) marker 2 (0x1) tst250fs-MDT0000 lov setup 00000020:01000000:0.0:1782270239.499289:0:373667:0:(obd_config.c:1967:class_config_llog_handler()) For 2.x interoperability, rename obd type from lov to lod (tst250fs-MDT0000) 00000020:00000080:0.0:1782270239.499292:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf001 00000020:00000080:0.0:1782270239.499318:0:373667:0:(genops.c:413:class_newdev()) Allocate new device tst250fs-MDT0000-mdtlov (000000008665842f) 00000020:00000080:0.0:1782270239.499335:0:373667:0:(obd_config.c:720:class_attach_name()) OBD: dev 4 attached type lod with refcount 2 00000020:00000080:0.0:1782270239.499341:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf003 00080000:01000000:0.0:1782270239.499411:0:373667:0:(osd_handler.c:8929:osd_obd_connect()) connect #2 00000020:00000080:0.0:1782270239.499418:0:373667:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDT0000-osd_UUID, cookie 0xbc32a82856848975 00000020:00000080:0.0:1782270239.499630:0:373667:0:(obd_config.c:826:class_setup()) finished setup of obd tst250fs-MDT0000-mdtlov (uuid tst250fs-MDT0000-mdtlov_UUID) 00000020:01000000:0.0:1782270239.499634:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:0.0:1782270239.499637:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1782270239.499639:0:373667:0:(obd_config.c:1561:class_process_config()) marker 2 (0x2) tst250fs-MDT0000 lov setup 00000020:01000000:0.0:1782270239.499641:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:0.0:1782270239.499650:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:0.0:1782270239.499651:0:373667:0:(obd_config.c:1561:class_process_config()) marker 3 (0x1) tst250fs-MDT0000 add mdt 00000020:00000080:0.0:1782270239.499656:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf001 00000020:00000080:0.0:1782270239.499680:0:373667:0:(genops.c:413:class_newdev()) Allocate new device tst250fs-MDT0000 (000000006b3b11dd) 00000020:00000080:0.0:1782270239.499690:0:373667:0:(obd_config.c:720:class_attach_name()) OBD: dev 5 attached type mdt with refcount 2 00000020:00000080:0.0:1782270239.499694:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf007 00000020:00000080:0.0:1782270239.499696:0:373667:0:(obd_config.c:1514:class_process_config()) mountopt: profile tst250fs-MDT0000 osc tst250fs-MDT0000-mdtlov mdc (null) 00000020:01000000:0.0:1782270239.499699:0:373667:0:(obd_config.c:1148:class_add_profile()) Add profile tst250fs-MDT0000 00000020:00000080:0.0:1782270239.499704:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf003 00000020:01000004:0.0:1782270239.499747:0:373667:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000a7a21454 from tst250fs-MDT0000, refs=3 00000020:00000080:0.0:1782270239.499759:0:373667:0:(genops.c:413:class_newdev()) Allocate new device tst250fs-MDD0000 (00000000337f48ed) 00000020:00000080:0.0:1782270239.499766:0:373667:0:(obd_config.c:720:class_attach_name()) OBD: dev 6 attached type mdd with refcount 2 00000004:01000000:0.0:1782270239.499845:0:373667:0:(lod_dev.c:2291:lod_obd_connect()) connect #0 00000020:00000080:0.0:1782270239.499851:0:373667:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDT0000-mdtlov_UUID, cookie 0xbc32a8285684898a 00000020:00000080:0.0:1782270239.499942:0:373667:0:(obd_config.c:826:class_setup()) finished setup of obd tst250fs-MDD0000 (uuid tst250fs-MDD0000_UUID) 00000004:01000000:0.0:1782270239.499949:0:373667:0:(mdd_device.c:1596:mdd_obd_connect()) connect #0 00000020:00000080:0.0:1782270239.499953:0:373667:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDD0000_UUID, cookie 0xbc32a82856848991 00080000:01000000:0.0:1782270239.499957:0:373667:0:(osd_handler.c:8929:osd_obd_connect()) connect #3 00000020:00000080:0.0:1782270239.499960:0:373667:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDT0000-osd_UUID, cookie 0xbc32a82856848998 00080000:10000000:0.0:1782270239.500402:0:373667:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000001:0x3:0x0] (8/24) registered 40000000:02000000:0.0:1782270239.500535:0:373667:0:(fid_handler.c:560:seq_server_init()) ctl-tst250fs-MDT0000: No data found on store. Initialize space. 40000000:02000000:0.0:1782270239.504376:0:373667:0:(fid_handler.c:560:seq_server_init()) srv-tst250fs-MDT0000: No data found on store. Initialize space. 00010000:00010000:0.0:1782270239.537818:0:373667:0:(ldlm_pool.c:925:ldlm_pool_init()) Lock pool ldlm-pool-mdt-tst250fs-MDT0000_UUID-1 is initialized 00000001:02000400:0.0:1782270239.538109:0:373667:0:(tgt_lastrcvd.c:1878:tgt_server_data_init()) tst250fs-MDT0000: new disk, initializing 00000001:00000004:0.0:1782270239.540301:0:373667:0:(tgt_lastrcvd.c:727:tgt_server_data_update()) tst250fs-MDT0000_UUID: mount_count is 1, last_transno is 0 00000001:00080000:0.0:1782270239.540593:0:373667:0:(tgt_lastrcvd.c:240:tgt_reply_header_write()) tst250fs-MDT0000: write reply_data header. magic=0xbdabda01 header_size=32 reply_size=32 00000020:00000080:0.0:1782270239.542233:0:373667:0:(genops.c:413:class_newdev()) Allocate new device tst250fs-QMT0000 (000000000cbb7796) 00000020:00000080:0.0:1782270239.542247:0:373667:0:(obd_config.c:720:class_attach_name()) OBD: dev 7 attached type qmt with refcount 2 00080000:01000000:0.0:1782270239.542304:0:373667:0:(osd_handler.c:8929:osd_obd_connect()) connect #4 00000020:00000080:0.0:1782270239.542313:0:373667:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDT0000-osd_UUID, cookie 0xbc32a828568489a6 00000020:00000080:1.0:1782270239.544037:0:373667:0:(obd_config.c:826:class_setup()) finished setup of obd tst250fs-QMT0000 (uuid tst250fs-QMT0000_UUID) 00080000:10000000:1.0:1782270239.544892:0:373667:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000006:0x10000:0x0] (8/32) registered 00080000:10000000:1.0:1782270239.548062:0:373667:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000006:0x1010000:0x0] (8/32) registered 00080000:10000000:1.0:1782270239.549586:0:373667:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000006:0x2010000:0x0] (8/32) registered 00080000:10000000:1.0:1782270239.551391:0:373667:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000006:0x20000:0x0] (8/32) registered 00080000:10000000:1.0:1782270239.552837:0:373667:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000006:0x1020000:0x0] (8/32) registered 00080000:10000000:1.0:1782270239.553943:0:373667:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000006:0x2020000:0x0] (8/32) registered 00000020:00000080:1.0:1782270239.555378:0:373667:0:(genops.c:1406:class_connect()) connect: client tst250fs-QMT0000_UUID, cookie 0xbc32a828568489ad 00000020:00000080:1.0:1782270239.555725:0:373667:0:(obd_config.c:826:class_setup()) finished setup of obd tst250fs-MDT0000 (uuid tst250fs-MDT0000_UUID) 00000020:01000000:1.0:1782270239.555737:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1782270239.555743:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1782270239.555745:0:373667:0:(obd_config.c:1561:class_process_config()) marker 3 (0x2) tst250fs-MDT0000 add mdt 00000020:01000000:1.0:1782270239.555759:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:1.0:1782270239.555763:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1782270239.555765:0:373667:0:(obd_config.c:1561:class_process_config()) marker 8 (0x1) tst250fs sys.timeout 00000020:00000080:1.0:1782270239.555767:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf009 00000020:00000080:1.0:1782270239.555768:0:373667:0:(obd_config.c:1535:class_process_config()) changing lustre timeout from 20 to 20 00000020:01000000:1.0:1782270239.555771:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1782270239.555773:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1782270239.555774:0:373667:0:(obd_config.c:1561:class_process_config()) marker 8 (0x2) tst250fs sys.timeout 00000020:01000000:1.0:1782270239.555776:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x0 mark_flg=0x1 00000020:00000080:1.0:1782270239.555780:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1782270239.555781:0:373667:0:(obd_config.c:1561:class_process_config()) marker 10 (0x1) tst250fs-MDT0000 mdt.identity_upcall 00000020:00000080:1.0:1782270239.555796:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf00f 00000004:01000000:1.0:1782270239.555831:0:373667:0:(mdt_lproc.c:316:identity_upcall_store()) tst250fs-MDT0000: identity upcall set to /home/green/git/lustre-release/lustre/utils/l_getidentity 00000100:00100000:1.0:1782270239.555885:0:373667:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000ec754813 pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373667:1868845780305152:0@lo:502: 00000100:00100000:1.0:1782270239.555959:0:373667:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1782270239.556009:0:373667:0:(client.c:2701:ptlrpc_set_wait()) set 00000000a085845d going to sleep for 11 seconds 00000100:00100000:0.0:1782270239.556073:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305152 00000100:00100000:0.0:1782270239.556081:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305152 00000100:00100000:0.0:1782270239.556145:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 9 00000100:00100000:0.0:1782270239.556153:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000fa160f16 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373667:x1868845780305152:12345-0@lo:502: 00000100:00100000:0.0:1782270239.556250:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000fa160f16 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373667:x1868845780305152:12345-0@lo:502: Request processed in 98us (291us total) trans 0 rc 0/0 00000100:00100000:0.0:1782270239.556257:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 9 00000100:00100000:1.0:1782270239.556287:0:373667:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000ec754813 pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373667:1868845780305152:0@lo:502: 00000020:01000000:1.0:1782270239.556311:0:373667:0:(obd_config.c:1890:class_config_llog_handler()) Marker, inst_flg=0x2 mark_flg=0x2 00000020:00000080:1.0:1782270239.556314:0:373667:0:(obd_config.c:1470:class_process_config()) processing cmd: cf010 00000020:00000080:1.0:1782270239.556315:0:373667:0:(obd_config.c:1561:class_process_config()) marker 10 (0x2) tst250fs-MDT0000 mdt.identity_upcall 00000040:00080000:1.0:1782270239.556318:0:373667:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 16 count 16 00000020:01000000:2.0:1782270239.556412:0:373621:0:(obd_config.c:2145:class_config_parse_llog()) Processed log tst250fs-MDT0000 gen 1-15 (rc=0) 10000000:01000000:2.0:1782270239.556447:0:373621:0:(mgc_request.c:1880:mgc_process_log()) MGC192.168.202.125@tcp: configuration from log 'tst250fs-MDT0000' succeeded (0). 00010000:00010000:2.0:1782270239.556464:0:373621:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.125@tcp lock: 000000002312ebe0/0xbc32a82856848960 lrc: 3/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a82856848967 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.556472:0:373621:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.125@tcp lock: 000000002312ebe0/0xbc32a82856848960 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 3 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a82856848967 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:2.0:1782270239.556482:0:373621:0:(mgc_request.c:1803:mgc_process_log()) Process log tst250fs-mdtir-ffff89f3058b9000 from 1 10000000:01000000:2.0:1782270239.556484:0:373621:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for tst250fs-mdtir (res 0x7366303532747374) 00010000:00010000:2.0:1782270239.556503:0:373621:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.556508:0:373621:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.556514:0:373621:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1782270239.556526:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305280:0@lo:101: 00000100:00100000:2.0:1782270239.556555:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.556581:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 00000000af7b76f6 going to sleep for 11 seconds 00000100:00100000:1.0:1782270239.556601:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305280 00000100:00100000:1.0:1782270239.556607:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305280 00000100:00100000:1.0:1782270239.556647:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 10 00000100:00100000:1.0:1782270239.556653:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000006f7fb924 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+9:373621:x1868845780305280:12345-0@lo:101: 00010000:00010000:1.0:1782270239.556662:0:373640:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:1.0:1782270239.556674:0:373640:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 2/0,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0xbc32a828568489b4 expref: -99 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.556692:0:373640:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0xbc32a828568489b4 expref: 10 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.556700:0:373640:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0xbc32a828568489b4 expref: 10 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.556708:0:373640:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 0000000051c151e7, rc 0) 00000100:00100000:1.0:1782270239.556748:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000006f7fb924 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+10:373621:x1868845780305280:12345-0@lo:101: Request processed in 96us (194us total) trans 0 rc 0/0 00000100:00100000:1.0:1782270239.556755:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 10 00000100:00100000:2.0:1782270239.556779:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305280:0@lo:101: 00010000:00010000:2.0:1782270239.556811:0:373621:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.556820:0:373621:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1782270239.557275:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305408:0@lo:256: 00000100:00100000:2.0:1782270239.557299:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.557318:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 00000000af7b76f6 going to sleep for 11 seconds 00000100:00100000:0.0:1782270239.557340:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305408 00000100:00100000:0.0:1782270239.557344:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305408 00000100:00100000:0.0:1782270239.557378:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 11 00000100:00100000:0.0:1782270239.557385:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000038964db6 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+10:373621:x1868845780305408:12345-0@lo:256: 20000000:01000000:0.0:1782270239.557400:0:373639:0:(mgs_nids.c:914:mgs_get_ir_logs()) Reading IR log tst250fs-mdtir bufsize 1048576. 20000000:01000000:0.0:1782270239.557405:0:373639:0:(mgs_nids.c:318:mgs_nidtbl_read()) Read IR logs tst250fs return with 0, version 1 00000100:00100000:2.0:1782270239.557477:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305408:0@lo:256: 00000100:00100000:0.0:1782270239.557480:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000038964db6 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+10:373621:x1868845780305408:12345-0@lo:256: Request processed in 94us (178us total) trans 0 rc 0/0 00000100:00100000:0.0:1782270239.557490:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 11 10000000:01000000:2.0:1782270239.558012:0:373621:0:(mgc_request.c:1880:mgc_process_log()) MGC192.168.202.125@tcp: configuration from log 'tst250fs-mdtir' succeeded (0). 00010000:00010000:2.0:1782270239.558026:0:373621:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 3/1,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.558032:0:373621:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:2.0:1782270239.558037:0:373621:0:(mgc_request.c:1803:mgc_process_log()) Process log params-ffff89f3058b9000 from 1 10000000:01000000:2.0:1782270239.558038:0:373621:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for params (res 0x736d61726170) 00010000:00010000:2.0:1782270239.558051:0:373621:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.125@tcp lock: 0000000010ddc3fc/0xbc32a828568489c2 lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.558055:0:373621:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.125@tcp lock: 0000000010ddc3fc/0xbc32a828568489c2 lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.558059:0:373621:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.125@tcp lock: 0000000010ddc3fc/0xbc32a828568489c2 lrc: 3/1,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1782270239.558066:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305536:0@lo:101: 00000100:00100000:2.0:1782270239.558084:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.558097:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 00000000af7b76f6 going to sleep for 11 seconds 00000100:00100000:3.0:1782270239.558153:0:373638:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305536 00000100:00100000:3.0:1782270239.558158:0:373638:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305536 00000100:00100000:3.0:1782270239.558184:0:373638:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 12 00000100:00100000:3.0:1782270239.558190:0:373638:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000003ac68e55 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+10:373621:x1868845780305536:12345-0@lo:101: 00010000:00010000:3.0:1782270239.558197:0:373638:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:3.0:1782270239.558208:0:373638:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 00000000bc8e4be7/0xbc32a828568489c9 lrc: 2/0,0 mode: --/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0xbc32a828568489c2 expref: -99 pid: 373638 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.558223:0:373638:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000bc8e4be7/0xbc32a828568489c9 lrc: 3/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0xbc32a828568489c2 expref: 11 pid: 373638 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.558231:0:373638:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 00000000bc8e4be7/0xbc32a828568489c9 lrc: 3/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0xbc32a828568489c2 expref: 11 pid: 373638 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.558247:0:373638:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 00000000bc8e4be7, rc 0) 00000100:00100000:3.0:1782270239.558295:0:373638:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000003ac68e55 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+11:373621:x1868845780305536:12345-0@lo:101: Request processed in 104us (209us total) trans 0 rc 0/0 00000100:00100000:3.0:1782270239.558301:0:373638:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 12 00000100:00100000:2.0:1782270239.559041:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305536:0@lo:101: 00010000:00010000:2.0:1782270239.559051:0:373621:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.125@tcp lock: 0000000010ddc3fc/0xbc32a828568489c2 lrc: 4/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489c9 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.559056:0:373621:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.125@tcp lock: 0000000010ddc3fc/0xbc32a828568489c2 lrc: 4/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0xbc32a828568489c9 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:2.0:1782270239.559107:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305664:0@lo:501: 00000100:00100000:2.0:1782270239.559151:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.559186:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 00000000af7b76f6 going to sleep for 11 seconds 00000100:00100000:0.0:1782270239.559235:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305664 00000100:00100000:0.0:1782270239.559238:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305664 00000100:00100000:0.0:1782270239.559264:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 13 00000100:00100000:0.0:1782270239.559271:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000006dfe04af pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+11:373621:x1868845780305664:12345-0@lo:501: 00000100:00100000:0.0:1782270239.559410:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000006dfe04af pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+11:373621:x1868845780305664:12345-0@lo:501: Request processed in 136us (255us total) trans 0 rc 0/0 00000100:00100000:0.0:1782270239.559417:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 13 00000100:00100000:2.0:1782270239.559437:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305664:0@lo:501: 00000100:00100000:2.0:1782270239.559460:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305792:0@lo:503: 00000100:00100000:2.0:1782270239.559493:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.559509:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 00000000af7b76f6 going to sleep for 11 seconds 00000100:00100000:1.0:1782270239.559533:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305792 00000100:00100000:1.0:1782270239.559538:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305792 00000100:00100000:1.0:1782270239.559570:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 14 00000100:00100000:1.0:1782270239.559576:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000f203fab0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+11:373621:x1868845780305792:12345-0@lo:503: 00000040:00080000:1.0:1782270239.559608:0:373640:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000100:00100000:1.0:1782270239.559646:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000f203fab0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+11:373621:x1868845780305792:12345-0@lo:503: Request processed in 71us (152us total) trans 0 rc 0/0 00000100:00100000:1.0:1782270239.559654:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 14 00000100:00100000:2.0:1782270239.559682:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305792:0@lo:503: 00000040:00080000:2.0:1782270239.560481:0:373671:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x2:0x0] index 64768 count 1 00000020:01000000:3.0:1782270239.560832:0:373621:0:(obd_config.c:2145:class_config_parse_llog()) Processed log params gen 1-0 (rc=0) 10000000:01000000:3.0:1782270239.560857:0:373621:0:(mgc_request.c:1880:mgc_process_log()) MGC192.168.202.125@tcp: configuration from log 'params' succeeded (0). 00010000:00010000:3.0:1782270239.560877:0:373621:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.125@tcp lock: 0000000010ddc3fc/0xbc32a828568489c2 lrc: 3/1,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489c9 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.560886:0:373621:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.125@tcp lock: 0000000010ddc3fc/0xbc32a828568489c2 lrc: 2/0,0 mode: CR/CR res: [0x736d61726170:0x3:0x0].0x0 rrc: 2 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489c9 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1782270239.560931:0:373621:0:(mgc_request.c:1945:mgc_process_config()) parse_log tst250fs-client from 0 10000000:01000000:3.0:1782270239.560938:0:373621:0:(mgc_request.c:329:config_log_add()) add config log tst250fs-client-ffff89f3058b9000 10000000:01000000:3.0:1782270239.560944:0:373621:0:(mgc_request.c:194:do_config_log_add()) do adding config log tst250fs-client-ffff89f3058b9000 10000000:01000000:3.0:1782270239.560948:0:373621:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs-client to resid 0x7366303532747374/0x0 (tst250fs) 10000000:01000000:3.0:1782270239.560954:0:373621:0:(mgc_request.c:1803:mgc_process_log()) Process log tst250fs-client-ffff89f3058b9000 from 1 10000000:01000000:3.0:1782270239.560957:0:373621:0:(mgc_request.c:996:mgc_enqueue()) Enqueue for tst250fs-client (res 0x7366303532747374) 00010000:00010000:3.0:1782270239.560981:0:373621:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: MGC192.168.202.125@tcp lock: 000000003d1a5640/0xbc32a828568489d0 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x10000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.560989:0:373621:0:(ldlm_request.c:1107:ldlm_cli_enqueue()) ### client-side enqueue START, flags 0x1000000000000 ns: MGC192.168.202.125@tcp lock: 000000003d1a5640/0xbc32a828568489d0 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x0 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.560996:0:373621:0:(ldlm_request.c:1194:ldlm_cli_enqueue()) ### sending request ns: MGC192.168.202.125@tcp lock: 000000003d1a5640/0xbc32a828568489d0 lrc: 3/1,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x1000000000000 nid: local remote: 0x0 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.561010:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000ac2d75d1 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305920:0@lo:101: 00000100:00100000:3.0:1782270239.561051:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.561086:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 00000000c333dd9d going to sleep for 11 seconds 00000100:00100000:2.0:1782270239.561192:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780305920 00000100:00100000:2.0:1782270239.561198:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780305920 00000100:00100000:2.0:1782270239.561233:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 15 00000100:00100000:2.0:1782270239.561240:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000537a21dd pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+11:373621:x1868845780305920:12345-0@lo:101: 00010000:00010000:2.0:1782270239.561250:0:373639:0:(ldlm_lockd.c:1265:ldlm_handle_enqueue()) ### server-side enqueue handler START 00010000:00010000:2.0:1782270239.561260:0:373639:0:(ldlm_lockd.c:1343:ldlm_handle_enqueue()) ### server-side enqueue handler, new lock created ns: MGS lock: 00000000a79e0e40/0xbc32a828568489d7 lrc: 2/0,0 mode: --/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x40000000000000 nid: local remote: 0xbc32a828568489d0 expref: -99 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.561278:0:373639:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000a79e0e40/0xbc32a828568489d7 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x50000000000000 nid: 0@lo remote: 0xbc32a828568489d0 expref: 12 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.561286:0:373639:0:(ldlm_lockd.c:1513:ldlm_handle_enqueue()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: MGS lock: 00000000a79e0e40/0xbc32a828568489d7 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0xbc32a828568489d0 expref: 12 pid: 373639 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:2.0:1782270239.561293:0:373639:0:(ldlm_lockd.c:1592:ldlm_handle_enqueue()) ### server-side enqueue handler END (lock 00000000a79e0e40, rc 0) 00000100:00100000:2.0:1782270239.561326:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000537a21dd pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373621:x1868845780305920:12345-0@lo:101: Request processed in 88us (276us total) trans 0 rc 0/0 00000100:00100000:2.0:1782270239.561333:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 15 00000100:00100000:3.0:1782270239.561365:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000ac2d75d1 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780305920:0@lo:101: 00010000:00010000:3.0:1782270239.561378:0:373621:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGC192.168.202.125@tcp lock: 000000003d1a5640/0xbc32a828568489d0 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489d7 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.561386:0:373621:0:(ldlm_request.c:841:ldlm_cli_enqueue_fini()) ### client-side enqueue END ns: MGC192.168.202.125@tcp lock: 000000003d1a5640/0xbc32a828568489d0 lrc: 4/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x1000000000000 nid: local remote: 0xbc32a828568489d7 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.561432:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000ac2d75d1 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780306048:0@lo:501: 00000100:00100000:3.0:1782270239.561456:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.561483:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 00000000c333dd9d going to sleep for 11 seconds 00000100:00100000:1.0:1782270239.561968:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306048 00000100:00100000:1.0:1782270239.561974:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306048 00000100:00100000:1.0:1782270239.562550:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 16 00000100:00100000:1.0:1782270239.562558:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000f36c9d7b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373621:x1868845780306048:12345-0@lo:501: 00000100:00100000:1.0:1782270239.562797:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000f36c9d7b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373621:x1868845780306048:12345-0@lo:501: Request processed in 228us (1328us total) trans 0 rc 0/0 00000100:00100000:2.0:1782270239.562797:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000ac2d75d1 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780306048:0@lo:501: 00000100:00100000:1.0:1782270239.562819:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 16 00000100:00100000:2.0:1782270239.562839:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780306176:0@lo:503: 00000100:00100000:2.0:1782270239.562886:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:2.0:1782270239.562917:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 0000000059815413 going to sleep for 11 seconds 00000100:00100000:0.0:1782270239.563008:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306176 00000100:00100000:0.0:1782270239.563011:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306176 00000100:00100000:0.0:1782270239.563033:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 17 00000100:00100000:0.0:1782270239.563037:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000004627b6db pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373621:x1868845780306176:12345-0@lo:503: 00000100:00100000:0.0:1782270239.563099:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000004627b6db pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373621:x1868845780306176:12345-0@lo:503: Request processed in 62us (214us total) trans 0 rc 0/0 00000100:00100000:0.0:1782270239.563110:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 17 00000100:00100000:2.0:1782270239.563207:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000004e57b3c4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780306176:0@lo:503: 00000100:00100000:1.0:1782270239.563439:0:373672:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000ec754813 pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373672:1868845780306304:0@lo:502: 00000100:00100000:1.0:1782270239.563475:0:373672:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1782270239.563506:0:373672:0:(client.c:2701:ptlrpc_set_wait()) set 00000000cf7ff075 going to sleep for 11 seconds 00000100:00100000:3.0:1782270239.563555:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306304 00000100:00100000:3.0:1782270239.563560:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306304 00000100:00100000:3.0:1782270239.563588:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 18 00000100:00100000:3.0:1782270239.563595:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000bb31295f pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373672:x1868845780306304:12345-0@lo:502: 00000100:00100000:3.0:1782270239.563705:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000bb31295f pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373672:x1868845780306304:12345-0@lo:502: Request processed in 111us (230us total) trans 0 rc 0/0 00000100:00100000:3.0:1782270239.563712:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 18 00000100:00100000:1.0:1782270239.563774:0:373672:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000ec754813 pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373672:1868845780306304:0@lo:502: 00000020:01000004:1.0:1782270239.563836:0:373672:0:(obd_mount.c:221:lustre_start_simple()) Starting OBD tst250fs-MDT0000-lwp-MDT0000 (typ=lwp) 00000020:00000080:1.0:1782270239.563860:0:373672:0:(genops.c:413:class_newdev()) Allocate new device tst250fs-MDT0000-lwp-MDT0000 (00000000c4b3b0dd) 00000020:00000080:1.0:1782270239.563878:0:373672:0:(obd_config.c:720:class_attach_name()) OBD: dev 8 attached type lwp with refcount 2 00000020:01000004:1.0:1782270239.564071:0:373672:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000a7a21454 from tst250fs-MDT0000, refs=4 00000020:01000004:1.0:1782270239.564076:0:373672:0:(tgt_mount.c:187:server_put_mount()) put mount 00000000a7a21454 from tst250fs-MDT0000, refs=4 00000020:01000004:1.0:1782270239.564078:0:373672:0:(obd_mount.c:701:lustre_put_lsi()) put 00000000a7a21454 4 00010000:00080000:1.0:1782270239.564104:0:373672:0:(ldlm_lib.c:102:import_set_conn()) imp 0000000068c663a9@tst250fs-MDT0000-lwp-MDT0000: add connection 192.168.202.125@tcp at head 00010000:00010000:1.0:1782270239.565984:0:373672:0:(ldlm_pool.c:925:ldlm_pool_init()) Lock pool ldlm-pool-tst250fs-MDT0000-lwp-MDT0000-1 is initialized 00000020:00000080:1.0:1782270239.566098:0:373672:0:(obd_config.c:826:class_setup()) finished setup of obd tst250fs-MDT0000-lwp-MDT0000 (uuid tst250fs-MDT0000-lwp-MDT0000_UUID) 00000010:01000000:0.0:1782270239.566209:0:373672:0:(lwp_dev.c:497:lwp_obd_connect()) connect #0 00000020:00000080:0.0:1782270239.566221:0:373672:0:(genops.c:1406:class_connect()) connect: client tst250fs-MDT0000-lwp-MDT0000, cookie 0xbc32a828568489e5 00000100:00080000:0.0:1782270239.566230:0:373672:0:(import.c:512:import_select_connection()) tst250fs-MDT0000-lwp-MDT0000: connect to NID 0@lo last attempt 0 00000100:00080000:0.0:1782270239.566234:0:373672:0:(import.c:626:import_select_connection()) tst250fs-MDT0000-lwp-MDT0000: import 0000000068c663a9 using connection 192.168.202.125@tcp/0@lo 00000100:00100000:0.0:1782270239.566262:0:373672:0:(import.c:828:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5) req@000000007b62e88e x1868845780306432/t0(0) o38->tst250fs-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:0.0:1782270239.566284:0:373672:0:(pinger.c:375:ptlrpc_pinger_add_import()) adding pingable import tst250fs-MDT0000-lwp-MDT0000_UUID->tst250fs-MDT0000_UUID 00000100:00100000:3.0:1782270239.566433:0:371865:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@000000007b62e88e pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:tst250fs-MDT0000-lwp-MDT0000_UUID:371865:1868845780306432:0@lo:38: 00000100:00100000:0.0:1782270239.566508:0:373672:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000e30a01e8 pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373672:1868845780306560:0@lo:502: 00000100:00100000:3.0:1782270239.566509:0:371865:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:1.0:1782270239.566544:0:373645:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306432 00000100:00100000:1.0:1782270239.566551:0:373645:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306432 00000100:00100000:0.0:1782270239.566563:0:373672:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:0.0:1782270239.566582:0:373672:0:(client.c:2701:ptlrpc_set_wait()) set 00000000121ee47f going to sleep for 11 seconds 00000100:00100000:1.0:1782270239.566597:0:373645:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1782270239.566605:0:373645:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@0000000053c47e9b pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:0+-99:371865:x1868845780306432:12345-0@lo:38: 00000100:00100000:3.0:1782270239.566612:0:373639:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306560 00000100:00100000:3.0:1782270239.566617:0:373639:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306560 00000100:00100000:3.0:1782270239.566652:0:373639:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 19 00000100:00100000:3.0:1782270239.566659:0:373639:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000c928e8f6 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373672:x1868845780306560:12345-0@lo:502: 00000100:00100000:1.0:1782270239.566663:0:373645:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@0000000053c47e9b pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:0+-99:371865:x1868845780306432:12345-0@lo:38: Request processed in 56us (157us total) trans 0 rc -11/-11 00000100:00100000:1.0:1782270239.566673:0:373645:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:1.0:1782270239.566713:0:371865:0:(client.c:3111:ptlrpc_free_committed()) tst250fs-MDT0000-lwp-MDT0000: committing for last_committed 0 gen 2 00000100:00080000:1.0:1782270239.566721:0:371865:0:(import.c:65:import_set_state_nolock()) 0000000068c663a9 tst250fs-MDT0000_UUID: changing import state from CONNECTING to DISCONN 00000100:00080000:1.0:1782270239.566726:0:371865:0:(import.c:1513:ptlrpc_connect_interpret()) recovery of tst250fs-MDT0000_UUID on 0@lo failed (-11) 00000100:00100000:1.0:1782270239.566730:0:371865:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@000000007b62e88e pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:tst250fs-MDT0000-lwp-MDT0000_UUID:371865:1868845780306432:0@lo:38: 00000100:00100000:3.0:1782270239.566793:0:373639:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000c928e8f6 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373672:x1868845780306560:12345-0@lo:502: Request processed in 118us (214us total) trans 0 rc 0/0 00000100:00100000:3.0:1782270239.566808:0:373639:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 19 00000100:00100000:0.0:1782270239.566933:0:373672:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000e30a01e8 pname:cluuid:pid:xid:nid:opc:job llog_process_th:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373672:1868845780306560:0@lo:502: 00000040:00080000:0.0:1782270239.566952:0:373672:0:(llog.c:857:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 21 count 21 00000020:01000000:3.0:1782270239.567060:0:373621:0:(obd_config.c:2145:class_config_parse_llog()) Processed log tst250fs-client gen 1-20 (rc=0) 10000000:01000000:3.0:1782270239.567084:0:373621:0:(mgc_request.c:1880:mgc_process_log()) MGC192.168.202.125@tcp: configuration from log 'tst250fs-client' succeeded (0). 00010000:00010000:3.0:1782270239.567103:0:373621:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: MGC192.168.202.125@tcp lock: 000000003d1a5640/0xbc32a828568489d0 lrc: 3/1,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489d7 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.567112:0:373621:0:(ldlm_lock.c:919:ldlm_lock_decref_internal()) ### do not add lock into lru list ns: MGC192.168.202.125@tcp lock: 000000003d1a5640/0xbc32a828568489d0 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x0:0x0].0x0 rrc: 4 type: PLN flags: 0x11000000000000 nid: local remote: 0xbc32a828568489d7 expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000020:01000004:3.0:1782270239.567182:0:373621:0:(tgt_mount.c:1175:server_mti_print()) mti - server_notify_target 00000020:01000004:3.0:1782270239.567185:0:373621:0:(tgt_mount.c:1176:server_mti_print()) server: tst250fs-MDT0000 00000020:01000004:3.0:1782270239.567186:0:373621:0:(tgt_mount.c:1177:server_mti_print()) fs: tst250fs 00000020:01000004:3.0:1782270239.567187:0:373621:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1782270239.567188:0:373621:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1782270239.567189:0:373621:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1782270239.567191:0:373621:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1782270239.567192:0:373621:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1782270239.567193:0:373621:0:(tgt_mount.c:1192:server_mti_print()) LDD_F_VIRIGIN 00000020:01000004:3.0:1782270239.567194:0:373621:0:(tgt_mount.c:1194:server_mti_print()) LDD_F_UPDATE 00000020:01000004:3.0:1782270239.567196:0:373621:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1782270239.567197:0:373621:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 10000000:01000000:3.0:1782270239.567200:0:373621:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target tst250fs-MDT0000 0x40020065 00000020:01000004:3.0:1782270239.567202:0:373621:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req 00000020:01000004:3.0:1782270239.567203:0:373621:0:(tgt_mount.c:1176:server_mti_print()) server: tst250fs-MDT0000 00000020:01000004:3.0:1782270239.567204:0:373621:0:(tgt_mount.c:1177:server_mti_print()) fs: tst250fs 00000020:01000004:3.0:1782270239.567205:0:373621:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:3.0:1782270239.567206:0:373621:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:3.0:1782270239.567207:0:373621:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:3.0:1782270239.567208:0:373621:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:3.0:1782270239.567209:0:373621:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:3.0:1782270239.567210:0:373621:0:(tgt_mount.c:1192:server_mti_print()) LDD_F_VIRIGIN 00000020:01000004:3.0:1782270239.567210:0:373621:0:(tgt_mount.c:1194:server_mti_print()) LDD_F_UPDATE 00000020:01000004:3.0:1782270239.567211:0:373621:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:3.0:1782270239.567212:0:373621:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 10000000:01000000:3.0:1782270239.567223:0:373621:0:(mgc_request_server.c:281:mgc_target_register()) register tst250fs-MDT0000 00000100:00100000:3.0:1782270239.567231:0:373621:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000686c62e4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780306688:0@lo:253: 00000100:00100000:3.0:1782270239.567263:0:373621:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.567285:0:373621:0:(client.c:2701:ptlrpc_set_wait()) set 000000002acdbe42 going to sleep for 11 seconds 00000100:00100000:3.0:1782270239.567302:0:373640:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306688 00000100:00100000:3.0:1782270239.567305:0:373640:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306688 00000100:00100000:3.0:1782270239.567326:0:373640:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 20 00000100:00100000:3.0:1782270239.567333:0:373640:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000007ec4190a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373621:x1868845780306688:12345-0@lo:253: 20000000:01000000:3.0:1782270239.567353:0:373640:0:(mgs_handler.c:453:mgs_target_reg()) fs: tst250fs index: 0 is ready to reconnect. 20000000:01000000:3.0:1782270239.567365:0:373640:0:(mgs_nids.c:463:mgs_tnl_update()) nidtbl: write 1 NIDs to NET #0 20000000:01000000:3.0:1782270239.572269:0:373640:0:(mgs_nids.c:815:mgs_ir_update()) Try to revoke recover lock of tst250fs 20000000:01000000:3.0:1782270239.572289:0:373640:0:(mgs_handler.c:637:mgs_target_reg()) replying with tst250fs-MDT0000, index=0, rc=0 20000000:01000000:1.0:1782270239.572314:0:373661:0:(mgs_nids.c:712:mgs_ir_notify()) mgs_tst250fs_notify woken up, phase is 1 10000000:01000000:1.0:1782270239.572328:0:373661:0:(mgc_request.c:68:mgc_name2resid()) log tst250fs to resid 0x7366303532747374/0x2 (tst250fs) 00010000:00010000:1.0:1782270239.572347:0:373661:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(EX) ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 3/0,1 mode: --/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.572365:0:373661:0:(ldlm_lock.c:687:ldlm_add_bl_work_item()) ### lock incompatible; sending blocking AST. ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40000000000000 nid: 0@lo remote: 0xbc32a828568489b4 expref: 12 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.572374:0:373661:0:(ldlm_resource.c:1750:ldlm_resource_add_lock()) ### About to add this lock ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 4/0,1 mode: --/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.572412:0:373661:0:(ldlm_lockd.c:963:ldlm_server_blocking_ast()) ### server preparing blocking AST ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50000000000020 nid: 0@lo remote: 0xbc32a828568489b4 expref: 12 pid: 373640 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.572427:0:373661:0:(ldlm_lockd.c:495:ldlm_add_waiting_lock()) ### adding to wait list(timeout: 150, AT: on) ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 4/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x70000400000020 nid: 0@lo remote: 0xbc32a828568489b4 expref: 12 pid: 373640 timeout: 13192 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:1.0:1782270239.572451:0:373661:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000ec754813 pname:cluuid:pid:xid:nid:opc:job mgs_tst250fs_no:MGS:373661:1868845780306816:0@lo:104: 00000100:00100000:1.0:1782270239.572531:0:373661:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.572561:0:373640:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@000000007ec4190a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:373621:x1868845780306688:12345-0@lo:253: Request processed in 5227us (5296us total) trans 0 rc 0/0 00000100:00100000:3.0:1782270239.572574:0:373640:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 20 00000100:00100000:1.0:1782270239.572597:0:373661:0:(client.c:2701:ptlrpc_set_wait()) set 00000000cf7ff075 going to sleep for 11 seconds 00000100:00100000:2.0:1782270239.572602:0:373621:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000686c62e4 pname:cluuid:pid:xid:nid:opc:job mount.lustre:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:373621:1868845780306688:0@lo:253: 10000000:01000000:2.0:1782270239.572618:0:373621:0:(mgc_request_server.c:302:mgc_target_register()) register tst250fs-MDT0000 got index = 0 00000020:01000004:2.0:1782270239.572621:0:373621:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: rep 00000020:01000004:2.0:1782270239.572623:0:373621:0:(tgt_mount.c:1176:server_mti_print()) server: tst250fs-MDT0000 00000020:01000004:2.0:1782270239.572624:0:373621:0:(tgt_mount.c:1177:server_mti_print()) fs: tst250fs 00000020:01000004:2.0:1782270239.572626:0:373621:0:(tgt_mount.c:1178:server_mti_print()) uuid: 00000020:01000004:2.0:1782270239.572627:0:373621:0:(tgt_mount.c:1179:server_mti_print()) ver: 0 00000020:01000004:2.0:1782270239.572629:0:373621:0:(tgt_mount.c:1180:server_mti_print()) flags: 00000020:01000004:2.0:1782270239.572630:0:373621:0:(tgt_mount.c:1182:server_mti_print()) LDD_F_SV_TYPE_MDT 00000020:01000004:2.0:1782270239.572631:0:373621:0:(tgt_mount.c:1186:server_mti_print()) LDD_F_SV_TYPE_MGS 00000020:01000004:2.0:1782270239.572633:0:373621:0:(tgt_mount.c:1192:server_mti_print()) LDD_F_VIRIGIN 00000020:01000004:2.0:1782270239.572634:0:373621:0:(tgt_mount.c:1194:server_mti_print()) LDD_F_UPDATE 00000020:01000004:2.0:1782270239.572634:0:373621:0:(tgt_mount.c:1214:server_mti_print()) LDD_F_LARGE_NID 00000020:01000004:2.0:1782270239.572635:0:373621:0:(tgt_mount.c:1220:server_mti_print()) LDD_F_OPC_READY 00000020:02000000:2.0:1782270239.572649:0:373621:0:(tgt_mount.c:2689:server_calc_timeout()) tst250fs-MDT0000: Imperative Recovery not enabled, recovery window 60-180 00000100:00100000:0.0:1782270239.572668:0:373627:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306816 00000100:00100000:0.0:1782270239.572675:0:373627:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306816 00000100:00100000:0.0:1782270239.572716:0:373627:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:0.0:1782270239.572726:0:373627:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000ebc3a7e3 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cb00_000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+3:373661:x1868845780306816:12345-0@lo:104: 00010000:00010000:0.0:1782270239.572738:0:373627:0:(ldlm_lockd.c:2506:ldlm_callback_handler()) ### blocking ast ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400000000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:0.0:1782270239.572841:0:373627:0:(ldlm_lockd.c:2189:__ldlm_bl_to_thread()) added 1/1 locks to priority blp list, 1 blwis in pool 00000100:00100000:0.0:1782270239.572846:0:373627:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000ebc3a7e3 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cb00_000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+3:373661:x1868845780306816:12345-0@lo:104: Request processed in 123us (317us total) trans 0 rc 0/0 00000100:00100000:0.0:1782270239.572853:0:373627:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00010000:00010000:3.0:1782270239.572871:0:373632:0:(ldlm_lockd.c:2801:ldlm_bl_get_work()) Got 1 locks of 0 total in blp. (0 blwis in pool) 00010000:00010000:3.0:1782270239.572878:0:373632:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400000000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.572887:0:373632:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock 00000000376c05c9 already unused, calling callback (000000003d97d00e) 10000000:00010000:3.0:1782270239.572890:0:373632:0:(mgc_request.c:922:mgc_blocking_ast()) ### MGC blocking CB ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 2/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1400400000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.572899:0:373632:0:(ldlm_request.c:1391:ldlm_cli_cancel_local()) ### client-side cancel ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1408400000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:1.0:1782270239.572900:0:373661:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000ec754813 pname:cluuid:pid:xid:nid:opc:job mgs_tst250fs_no:MGS:373661:1868845780306816:0@lo:104: 10000000:00010000:3.0:1782270239.572912:0:373632:0:(mgc_request.c:928:mgc_blocking_ast()) ### MGC cancel CB ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1409400000000 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.572918:0:373661:0:(ldlm_request.c:298:ldlm_completion_ast()) ### client-side enqueue returned a blocked locksleeping ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 3/0,1 mode: --/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 10000000:01000000:3.0:1782270239.572919:0:373632:0:(mgc_request.c:932:mgc_blocking_ast()) Lock res [0x7366303532747374:0x2:0x0].0x0 (tst250fs) 00010000:00010000:3.0:1782270239.572954:0:373632:0:(ldlm_request.c:1439:__ldlm_pack_lock()) ### packing ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 2/0,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.572964:0:373632:0:(ldlm_request.c:1498:ldlm_cancel_pack()) 1 locks packed 00010000:00010000:3.0:1782270239.572993:0:373632:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 1/0,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.572998:0:373632:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGC192.168.202.125@tcp lock: 00000000376c05c9/0xbc32a828568489b4 lrc: 0/0,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x5c09400000020 nid: local remote: 0xbc32a828568489bb expref: -99 pid: 373621 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573013:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:3.0:1782270239.573015:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00010000:00010000:3.0:1782270239.573017:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000100:00100000:0.0:1782270239.573057:0:371867:0:(client.c:1905:ptlrpc_send_new_req()) Sending RPC req@00000000b0f0f655 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:371867:1868845780306944:0@lo:103: 00000100:00100000:0.0:1782270239.573084:0:371867:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo) 00000100:00100000:3.0:1782270239.573148:0:373629:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1868845780306944 00000100:00100000:3.0:1782270239.573153:0:373629:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1868845780306944 00010000:00010000:3.0:1782270239.573171:0:373629:0:(ldlm_lockd.c:2683:ldlm_cancel_hpreq_check()) ### hpreq cancel/convert lock ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 4/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x60000400000020 nid: 0@lo remote: 0xbc32a828568489b4 expref: 12 pid: 373640 timeout: 13192 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.573197:0:373629:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0 00000100:00100000:3.0:1782270239.573202:0:373629:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000e30a01e8 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cn00_000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+12:371867:x1868845780306944:12345-0@lo:103: 00010000:00010000:3.0:1782270239.573211:0:373629:0:(ldlm_lockd.c:1747:ldlm_request_cancel()) ### server-side cancel handler START: 1 locks, starting at 0 00010000:00010000:3.0:1782270239.573215:0:373629:0:(ldlm_lockd.c:1796:ldlm_request_cancel()) ### server cancels blocked lock after 0s ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 4/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x60000400000020 nid: 0@lo remote: 0xbc32a828568489b4 expref: 12 pid: 373640 timeout: 13192 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573222:0:373629:0:(ldlm_lockd.c:568:ldlm_del_waiting_lock()) ### removed ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 3/0,0 mode: CR/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x50000400000020 nid: 0@lo remote: 0xbc32a828568489b4 expref: 12 pid: 373640 timeout: 13192 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573231:0:373629:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: 0000000051c151e7/0xbc32a828568489bb lrc: 0/0,0 mode: --/CR res: [0x7366303532747374:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x44801400000020 nid: 0@lo remote: 0xbc32a828568489b4 expref: 12 pid: 373640 timeout: 13192 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573241:0:373629:0:(ldlm_lock.c:715:ldlm_add_cp_work_item()) ### lock granted; sending completion AST. ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 3/0,1 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40290000000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573253:0:373629:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 4/0,1 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40290000000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 20000000:01000000:3.0:1782270239.573262:0:373629:0:(mgs_nids.c:688:mgs_ir_notify_complete()) Revoke recover lock of tst250fs completed after 0.000934832s 00010000:00010000:3.0:1782270239.573264:0:373629:0:(ldlm_lock.c:954:ldlm_lock_decref_and_cancel()) ### ldlm_lock_decref(EX) ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 5/0,1 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573269:0:373629:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(EX) ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 5/0,1 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573275:0:373629:0:(ldlm_lock.c:887:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 4/0,0 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573280:0:373629:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 5/0,0 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573285:0:373629:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock 0000000054cb7631 already unused, calling callback (0000000069812618) 00010000:00010000:3.0:1782270239.573288:0:373629:0:(ldlm_request.c:378:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 5/0,0 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573294:0:373629:0:(ldlm_request.c:1416:ldlm_cli_cancel_local()) ### server-side local cancel ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 6/0,0 mode: EX/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573309:0:373629:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 4/0,0 mode: --/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:3.0:1782270239.573318:0:373629:0:(ldlm_lockd.c:1808:ldlm_request_cancel()) ### server-side cancel handler END 00010000:00010000:1.0:1782270239.573329:0:373661:0:(ldlm_request.c:190:ldlm_completion_tail()) ### client-side enqueue: destroyed ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 1/0,0 mode: --/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.573337:0:373661:0:(ldlm_request.c:557:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 1/0,0 mode: --/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00010000:00010000:1.0:1782270239.573343:0:373661:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: 0000000054cb7631/0xbc32a828568489ec lrc: 0/0,0 mode: --/EX res: [0x7366303532747374:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 373661 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 00000100:00100000:3.0:1782270239.573352:0:373629:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000e30a01e8 pname:cluuid+ref:pid:xid:nid:opc:job ldlm_cn00_000:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e+11:371867:x1868845780306944:12345-0@lo:103: Request processed in 150us (267us total) trans 0 rc 0/0 00000100:00100000:3.0:1782270239.573370:0:373629:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0 00000100:00100000:0.0:1782270239.573377:0:371867:0:(client.c:2400:ptlrpc_check_set()) Completed RPC req@00000000b0f0f655 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:1bf7dd3d-5ee7-4e19-99af-a84d44812a4e:371867:1868845780306944:0@lo:103: 00080000:10000000:2.0:1782270239.576245:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0x9:0x0] (8/32) registered 00080000:10000000:2.0:1782270239.576390:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000005:0x1:0x0] (8/8) registered 00080000:10000000:2.0:1782270239.576589:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0xa:0x0] (8/32) registered 00080000:10000000:2.0:1782270239.576747:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000005:0x2:0x0] (8/8) registered 00080000:10000000:2.0:1782270239.576925:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0xb:0x0] (8/32) registered 00080000:10000000:2.0:1782270239.577035:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000005:0x3:0x0] (8/8) registered 00080000:10000000:3.0:1782270239.578041:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0xc:0x0] (8/32) registered 00080000:10000000:3.0:1782270239.578291:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000005:0x20001:0x0] (8/8) registered 00080000:10000000:3.0:1782270239.578453:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0xd:0x0] (8/32) registered 00080000:10000000:3.0:1782270239.578602:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000005:0x20002:0x0] (8/8) registered 00080000:10000000:3.0:1782270239.578782:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0xe:0x0] (8/32) registered 00080000:10000000:3.0:1782270239.578932:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000005:0x20003:0x0] (8/8) registered 40000000:02000000:2.0:1782270239.580802:0:373621:0:(fid_handler.c:119:__seq_server_alloc_super()) ctl-tst250fs-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt 00000040:01000000:2.0:1782270239.589507:0:373621:0:(llog_obd.c:197:llog_setup()) obd tst250fs-MDT0000-osd ctxt 16 is initialized 00000020:00080000:3.0:1782270239.589511:0:373677:0:(update_trans.c:1530:distribute_txn_commit_thread()) tst250fs-MDT0000: start commit thread committed batchid 0 00000020:00080000:3.0:1782270239.589516:0:373677:0:(update_trans.c:1581:distribute_txn_commit_thread()) tst250fs-MDT0000: batchid: 0 committed batchid 0 00000040:01000000:2.0:1782270239.589738:0:373678:0:(llog_osd.c:2237:llog_osd_get_cat_list()) cat list: disk size=0, read=32 00000040:01000000:3.0:1782270239.590888:0:373621:0:(llog_obd.c:197:llog_setup()) obd tst250fs-MDD0000 ctxt 12 is initialized 00000040:00080000:3.0:1782270239.591033:0:373621:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000004:00000080:3.0:1782270239.591527:0:373621:0:(mdd_device.c:553:mdd_changelog_llog_init()) changelog starting index=0 00000040:01000000:3.0:1782270239.591534:0:373621:0:(llog_obd.c:197:llog_setup()) obd tst250fs-MDD0000 ctxt 14 is initialized 00000040:00080000:3.0:1782270239.591623:0:373621:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00000040:00080000:3.0:1782270239.592798:0:373621:0:(llog.c:857:llog_process_thread()) stop processing catalog [0xa:0x5:0x0] index 64768 count 1 00000040:00080000:3.0:1782270239.593359:0:373621:0:(llog.c:857:llog_process_thread()) stop processing catalog [0xa:0x6:0x0] index 64768 count 1 00000040:01000000:3.0:1782270239.593395:0:373621:0:(llog_obd.c:197:llog_setup()) obd tst250fs-MDD0000 ctxt 15 is initialized 00000040:00080000:3.0:1782270239.593556:0:373621:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00080000:10000000:3.0:1782270239.593735:0:373621:0:(osd_handler.c:5579:osd_index_try()) tst250fs-MDT0000: index object [0x200000003:0x10:0x0] (8/32) registered 00100000:10000000:3.0:1782270239.594538:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_00: rc = 0 00100000:10000000:3.0:1782270239.594756:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_01: rc = 0 00100000:10000000:3.0:1782270239.594883:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_02: rc = 0 00100000:10000000:3.0:1782270239.594980:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_03: rc = 0 00100000:10000000:3.0:1782270239.595140:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_04: rc = 0 00100000:10000000:3.0:1782270239.595245:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_05: rc = 0 00100000:10000000:3.0:1782270239.595355:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_06: rc = 0 00100000:10000000:3.0:1782270239.595505:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_07: rc = 0 00100000:10000000:3.0:1782270239.595646:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_08: rc = 0 00100000:10000000:3.0:1782270239.595770:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_09: rc = 0 00100000:10000000:3.0:1782270239.595921:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_10: rc = 0 00100000:10000000:3.0:1782270239.596066:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_11: rc = 0 00100000:10000000:3.0:1782270239.596221:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_12: rc = 0 00100000:10000000:3.0:1782270239.596364:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_13: rc = 0 00100000:10000000:3.0:1782270239.596493:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_14: rc = 0 00100000:10000000:3.0:1782270239.596717:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_namespace_15: rc = 0 00100000:10000000:3.0:1782270239.597114:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_00: rc = 0 00000040:00080000:2.0:1782270239.597223:0:373678:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log 00100000:10000000:3.0:1782270239.597299:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_01: rc = 0 00100000:10000000:3.0:1782270239.597440:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_02: rc = 0 00100000:10000000:3.0:1782270239.598648:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_03: rc = 0 00100000:10000000:3.0:1782270239.598870:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_04: rc = 0 00100000:10000000:3.0:1782270239.599029:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_05: rc = 0 00100000:10000000:3.0:1782270239.599234:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_06: rc = 0 00100000:10000000:3.0:1782270239.599366:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_07: rc = 0 00100000:10000000:3.0:1782270239.599505:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_08: rc = 0 00100000:10000000:3.0:1782270239.599638:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_09: rc = 0 00100000:10000000:3.0:1782270239.599778:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_10: rc = 0 00100000:10000000:3.0:1782270239.599932:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_11: rc = 0 00100000:10000000:3.0:1782270239.600083:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_12: rc = 0 00100000:10000000:3.0:1782270239.600231:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_13: rc = 0 00100000:10000000:3.0:1782270239.600333:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_14: rc = 0 00100000:10000000:3.0:1782270239.600455:0:373621:0:(lfsck_lib.c:2686:lfsck_load_one_trace_file()) tst250fs-MDT0000-osd: unlink lfsck sub trace file lfsck_layout_15: rc = 0 00000001:00000004:3.0:1782270239.600643:0:373621:0:(tgt_lastrcvd.c:727:tgt_server_data_update()) tst250fs-MDT0000_UUID: mount_count is 1, last_transno is 4294967296 00000040:00080000:0.0:1782270239.604058:0:373678:0:(llog.c:857:llog_process_thread()) stop processing catalog [0x200000400:0x1:0x0] index 261376 count 1 00000004:00080000:0.0:1782270239.604169:0:373678:0:(lod_dev.c:521:lod_sub_recovery_thread()) tst250fs-MDT0000-osd retrieved update log, duration 0, retries 0 00000004:00080000:0.0:1782270239.604174:0:373678:0:(lod_dev.c:545:lod_sub_recovery_thread()) tst250fs-MDT0000 got update logs from all MDTs. 00000001:00080000:3.0:1782270239.604642:0:373621:0:(tgt_lastrcvd.c:222:tgt_reply_header_read()) tst250fs-MDT0000: read reply_data header. magic=0xbdabda01 header_size=32 reply_size=32 00000004:00000080:3.0:1782270239.604666:0:373621:0:(mdd_device.c:2302:mdd_iocontrol()) tst250fs-MDD0000: cmd=c00866e6 len=0 karg=ffffa81b00c97988 00100000:10000000:3.0:1782270239.604681:0:373621:0:(lfsck_lib.c:3085:lfsck_start()) tst250fs-MDT0000-osd: start master thread 00000020:01000004:2.0:1782270239.605050:0:373621:0:(tgt_mount.c:298:server_mgc_clear_fs()) Unassign mgc disk 10000000:01000000:2.0:1782270239.605065:0:373621:0:(mgc_request_server.c:166:mgc_fs_clear()) MGC192.168.202.125@tcp: cl_mgc_mutex unlock 00000020:01000004:2.0:1782270239.605080:0:373621:0:(tgt_mount.c:2458:server_fill_super_common()) Server sb, dev=46 00000080:00000004:2.0:1782270239.605096:0:373621:0:(super25.c:187:lustre_fill_super()) /dev/mapper/mds1_flakey: Mount complete 00000020:00000004:2.0:1782270239.605916:0:373621:0:(tgt_mount.c:2344:server_getattr()) tst250fs-MDT0000: root_inode from vfsmnt ino=2, dev=0 00000020:00000004:2.0:1782270239.606134:0:373621:0:(tgt_mount.c:2359:is_cmd_supported()) ioctl cmd=41009432 00010000:00010000:2.0:1782270240.431266:0:373633:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00000001:02000400:1.0:1782270241.371945:0:373922:0:(debug.c:654:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg225-server.virtnet: executing set_default_debug -1 all 00000400:00000001:1.0:1782270241.392268:0:373924:0:(debug.c:306:cfs_str2mask()) Process entered 00010000:00000001:2.0:1782270241.456240:0:367058:0:(ldlm_pool.c:319:ldlm_srv_pool_recalc()) Process entered 00010000:00000001:2.0:1782270241.456247:0:367058:0:(ldlm_pool.c:351:ldlm_srv_pool_recalc()) Process leaving (rc=0 : 0 : 0) 00010000:00000001:2.0:1782270241.456253:0:367058:0:(ldlm_pool.c:459:ldlm_cli_pool_recalc()) Process entered 00010000:00000001:2.0:1782270241.456254:0:367058:0:(ldlm_pool.c:463:ldlm_cli_pool_recalc()) Process leaving (rc=0 : 0 : 0) 00000020:00000001:3.0:1782270241.456301:0:373632:0:(genops.c:1916:obd_stale_export_get()) Process entered 00000020:00000001:3.0:1782270241.456312:0:373632:0:(genops.c:1930:obd_stale_export_get()) Process leaving (rc=0 : 0 : 0) 00010000:00010000:3.0:1782270241.456318:0:373632:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) 00080000:00000010:0.0:1782270241.593930:0:373933:0:(osd_handler.c:2599:osd_statfs()) kmalloced '(ksfs)': 120 at 0000000020d7ed35. 00080000:00000010:0.0:1782270241.593945:0:373933:0:(osd_handler.c:2640:osd_statfs()) kfreed 'ksfs': 120 at 0000000020d7ed35. 00000020:00000001:0.0:1782270241.593952:0:373933:0:(tgt_mount.c:2302:server_show_options()) Process leaving (rc=0 : 0 : 0) 00080000:00000010:2.0:1782270241.743653:0:373974:0:(osd_handler.c:2599:osd_statfs()) kmalloced '(ksfs)': 120 at 000000001c2f8bde. 00080000:00000010:2.0:1782270241.743669:0:373974:0:(osd_handler.c:2640:osd_statfs()) kfreed 'ksfs': 120 at 000000001c2f8bde. 00000020:00000001:2.0:1782270241.743677:0:373974:0:(tgt_mount.c:2302:server_show_options()) Process leaving (rc=0 : 0 : 0) 00000020:00000004:2.0:1782270241.743706:0:373974:0:(tgt_mount.c:2344:server_getattr()) tst250fs-MDT0000: root_inode from vfsmnt ino=2, dev=0 00000020:00000004:2.0:1782270241.743881:0:373974:0:(tgt_mount.c:2359:is_cmd_supported()) ioctl cmd=81009431 00080000:00000010:3.0:1782270241.942505:0:373984:0:(osd_handler.c:2599:osd_statfs()) kmalloced '(ksfs)': 120 at 00000000bb14a39a. 00080000:00000010:3.0:1782270241.942520:0:373984:0:(osd_handler.c:2640:osd_statfs()) kfreed 'ksfs': 120 at 00000000bb14a39a. 00000020:00000001:3.0:1782270241.942527:0:373984:0:(tgt_mount.c:2302:server_show_options()) Process leaving (rc=0 : 0 : 0) 00010000:00000001:2.0:1782270242.479262:0:367058:0:(ldlm_pool.c:319:ldlm_srv_pool_recalc()) Process entered 00010000:00000001:2.0:1782270242.479273:0:367058:0:(ldlm_pool.c:351:ldlm_srv_pool_recalc()) Process leaving (rc=0 : 0 : 0) 00010000:00000001:2.0:1782270242.479283:0:367058:0:(ldlm_pool.c:459:ldlm_cli_pool_recalc()) Process entered 00010000:00000001:2.0:1782270242.479285:0:367058:0:(ldlm_pool.c:463:ldlm_cli_pool_recalc()) Process leaving (rc=0 : 0 : 0) 00000020:00000001:2.0:1782270242.479311:0:373633:0:(genops.c:1916:obd_stale_export_get()) Process entered 00000020:00000001:2.0:1782270242.479315:0:373633:0:(genops.c:1930:obd_stale_export_get()) Process leaving (rc=0 : 0 : 0) 00010000:00010000:2.0:1782270242.479318:0:373633:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue) Debug log: 916 lines, 916 kept, 0 dropped, 0 bad.