00000001:02000400:3.0F:1789760673.157708:0:3105:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg318-server.virtnet: executing set_hostid
00000001:02000400:3.0:1789760689.667189:0:3327:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local
00000001:01000000:3.0:1789760691.553334:0:3386:0:(lnet-crypto.c:360:cfs_crypto_performance_test()) Crypto hash algorithm adler32 speed = 459 MB/s
00000001:01000000:2.0F:1789760691.803337:0:3386:0:(lnet-crypto.c:360:cfs_crypto_performance_test()) Crypto hash algorithm crc32 speed = 867 MB/s
00000001:01000000:2.0:1789760692.053139:0:3386:0:(lnet-crypto.c:360:cfs_crypto_performance_test()) Crypto hash algorithm crc32c speed = 2971 MB/s
00000020:02000000:1.0F:1789760692.782333:0:3418:0:(class_obd.c:771:obdclass_init()) Lustre: Build Version: 2.17.57_103_g082f77f
00000400:02000000:3.0:1789760693.345524:0:3433:0:(api-ni.c:2823:lnet_startup_lndni()) Added LNI 192.168.203.118@tcp [8/256/0/180]
00008000:02000000:3.0:1789760697.309439:0:3583:0:(echo_client.c:2574:obdecho_init()) Echo OBD driver; http://www.lustre.org/
00000001:02000400:1.0:1789760741.425576:0:5187:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local
02000000:01000000:2.0:1789760820.932366:0:5933:0:(lproc_gss.c:195:rsi_upcall_store()) rsicache: rsi upcall set to /home/green/git/lustre-release/lustre/utils/gss/l_getauth
00000020:01000004:0.0F:1789760823.966797:0:6432:0:(obd_mount.c:923:lmd_print())   mount data:
00000020:01000004:0.0:1789760823.966836:0:6432:0:(obd_mount.c:926:lmd_print()) device:  /dev/mapper/mds1_flakey
00000020:01000004:0.0:1789760823.966837:0:6432:0:(obd_mount.c:929:lmd_print()) options: user_xattr,errors=remount-ro
00000080:01200004:0.0:1789760823.966940:0:6432:0:(super25.c:131:lustre_fill_super()) VFS Op: sb 00000000db1ea9bd
00000080:02000400:0.0:1789760823.966949:0:6432:0:(super25.c:149:lustre_fill_super()) lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt'
00000020:01000004:0.0:1789760823.968894:0:6432:0:(tgt_mount.c:2503:osd_start()) Attempting to start lustre-MDT0000, type=osd-ldiskfs, lsifl=200065, mountfl=0
00000020:01000004:0.0:1789760823.968900:0:6432:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD lustre-MDT0000-osd (typ=osd-ldiskfs)
00000020:00000080:0.0:1789760823.968919:0:6432:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-osd (00000000dba53ef1)
00000020:00000080:0.0:1789760823.968933:0:6432:0:(obd_config.c:720:class_attach_name()) OBD: dev 0 attached type osd-ldiskfs with refcount 2
00100000:10000000:2.0:1789760823.984848:0:6432:0:(scrub.c:230:scrub_file_store()) lustre-MDT0000: store scrub file: rc = 0
00100000:10000000:2.0:1789760823.984886:0:6432:0:(scrub.c:230:scrub_file_store()) lustre-MDT0000: store scrub file: rc = 0
00080000:01000000:2.0:1789760823.995006:0:6432:0:(osd_lproc.c:911:osd_procfs_init()) lustre-MDT0000: register osd-ldiskfs tunable parameters
00000020:00000080:2.0:1789760823.995206:0:6432:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-osd (uuid lustre-MDT0000-osd_UUID)
00080000:01000000:2.0:1789760823.995212:0:6432:0:(osd_handler.c:8925:osd_obd_connect()) connect #0
00000020:00000080:2.0:1789760823.995222:0:6432:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x265a75c5aff9cd02
00000020:01000004:2.0:1789760823.995227:0:6432:0:(tgt_mount.c:2588:server_fill_super()) Found service lustre-MDT0000 on device /dev/mapper/mds1_flakey
00000020:01000000:2.0:1789760823.995231:0:6432:0:(tgt_mount.c:219:server_start_mgs()) Start MGS service MGS
00000020:01000004:2.0:1789760823.995234:0:6432:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000db1ea9bd from MGS
00000020:01000004:2.0:1789760823.995238:0:6432:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGS (typ=mgs)
00000020:00000080:2.0:1789760823.995251:0:6432:0:(genops.c:413:class_newdev()) Allocate new device MGS (00000000849bb9ee)
00000020:00000080:2.0:1789760823.995258:0:6432:0:(obd_config.c:720:class_attach_name()) OBD: dev 1 attached type mgs with refcount 2
00000020:01000004:2.0:1789760823.995325:0:6432:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000db1ea9bd from MGS, refs=2
00080000:01000000:2.0:1789760823.995329:0:6432:0:(osd_handler.c:8925:osd_obd_connect()) connect #1
00000020:00000080:2.0:1789760823.995333:0:6432:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x265a75c5aff9cd10
00000100:00100000:2.0:1789760823.995419:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_cbd: allocate 1 new 8192-byte reqbufs (0/1 left), rc = 0
00000100:00100000:2.0:1789760823.995509:0:6432:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 0 min 2 max 56
00000100:00100000:2.0:1789760823.995513:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_000'
00000100:00100000:2.0:1789760823.995756:0:6432:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 1 min 2 max 56
00000100:00100000:2.0:1789760823.995761:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_001'
00000100:00100000:2.0:1789760823.996325:0:6432: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:1789760823.996432:0:6432:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 0 min 3 max 56
00000100:00100000:2.0:1789760823.996436:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_000'
00000100:00100000:2.0:1789760823.997326:0:6432:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 1 min 3 max 56
00000100:00100000:2.0:1789760823.997331:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_001'
00000100:00100000:2.0:1789760823.997541:0:6432:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 2 min 3 max 56
00000100:00100000:2.0:1789760823.997545:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_002'
00010000:00010000:2.0:1789760823.997934:0:6443:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:2.0:1789760823.997937:0:6443:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:2.0:1789760823.997938:0:6443:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1789760823.998122:0:6444:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1789760823.998125:0:6444:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1789760823.998127:0:6444:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:2.0:1789760823.998386:0:6432:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGS-0 is initialized
00010000:00010000:3.0:1789760823.999982:0:6443:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000001:01000000:2.0:1789760824.247855:0:6432:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip512 speed = 6847 MB/s
00000001:01000000:2.0:1789760824.497829:0:6432:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip4K speed = 7587 MB/s
00000001:01000000:2.0:1789760824.748176:0:6432:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc512 speed = 1643 MB/s
00000001:01000000:2.0:1789760824.998098:0:6432:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc4K speed = 1927 MB/s
00080000:10000000:2.0:1789760825.000692:0:6432:0:(osd_handler.c:5581:osd_index_try()) lustre-MDT0000: index object [0x200000003:0x2:0x0] (8/32) registered
00000040:01000000:2.0:1789760825.005369:0:6432:0:(llog_obd.c:197:llog_setup()) obd MGS ctxt 0 is initialized
10000000:01000000:2.0:1789760825.005776:0:6446:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x2 (params)
20000000:01000000:3.0:1789760825.005796:0:6432:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2
20000000:01000000:3.0:1789760825.005865:0:6432:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
00000040:00080000:3.0:1789760825.006016:0:6432:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
20000000:01000000:3.0:1789760825.006063:0:6432:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
00000100:00100000:3.0:1789760825.006472:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) mgs: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0
00000100:00100000:3.0:1789760825.006675:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 0 min 3 max 32
00000100:00100000:3.0:1789760825.006680:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0000'
00000100:00100000:2.0:1789760825.007071:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 1 min 3 max 32
00000100:00100000:2.0:1789760825.007078:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0001'
00000100:00100000:3.0:1789760825.007274:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 2 min 3 max 32
00000100:00100000:3.0:1789760825.007280:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0002'
00000100:00080000:2.0:1789760825.007621:0:6451:0:(pinger.c:466:ping_evictor_main()) Starting Ping Evictor
00000020:00000080:3.0:1789760825.007632:0:6432:0:(obd_config.c:826:class_setup()) finished setup of obd MGS (uuid MGS)
00000020:01000004:3.0:1789760825.007649:0:6432:0:(obd_mount.c:411:lustre_start_mgc()) Start MGC 'MGC192.168.203.118@tcp'
00000020:01000004:3.0:1789760825.007650:0:6432:0:(obd_mount.c:420:lustre_start_mgc()) mgs NIDs (null).
00000020:01000004:3.0:1789760825.007696:0:6432:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGC192.168.203.118@tcp (typ=mgc)
00000020:00000080:3.0:1789760825.007712:0:6432:0:(genops.c:413:class_newdev()) Allocate new device MGC192.168.203.118@tcp (00000000fc5182e3)
00000020:00000080:3.0:1789760825.007724:0:6432:0:(obd_config.c:720:class_attach_name()) OBD: dev 2 attached type mgc with refcount 2
00010000:00080000:3.0:1789760825.007864:0:6432:0:(ldlm_lib.c:102:import_set_conn()) imp 00000000e45bf230@MGC192.168.203.118@tcp: add connection 192.168.203.118@tcp at head
00010000:00010000:3.0:1789760825.008044:0:6432:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGC192.168.203.118@tcp-0 is initialized
00000040:01000000:3.0:1789760825.008049:0:6432:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.203.118@tcp ctxt 1 is initialized
10000000:01000000:3.0:1789760825.008295:0:6452:0:(mgc_request.c:631:mgc_requeue_thread()) Starting requeue thread
00000020:00000080:2.0:1789760825.008336:0:6432:0:(obd_config.c:826:class_setup()) finished setup of obd MGC192.168.203.118@tcp (uuid eb648b1c-d606-486d-a591-51b67b446b11)
00000020:00000080:2.0:1789760825.008354:0:6432:0:(genops.c:1385:class_connect()) connect: client eb648b1c-d606-486d-a591-51b67b446b11, cookie 0x265a75c5aff9cd1e
00000100:00080000:2.0:1789760825.008365:0:6432:0:(import.c:510:import_select_connection()) MGC192.168.203.118@tcp: connect to NID 0@lo last attempt 0
00000100:00080000:2.0:1789760825.008371:0:6432:0:(import.c:624:import_select_connection()) MGC192.168.203.118@tcp: import 00000000e45bf230 using connection 192.168.203.118@tcp/0@lo
00000100:00100000:2.0:1789760825.008423:0:6432:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5)  req@00000000d4fcda5f x1876700108423296/t0(0) o250->MGC192.168.203.118@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:00100000:0.0:1789760825.008514:0:3448:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000d4fcda5f pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:eb648b1c-d606-486d-a591-51b67b446b11:3448:1876700108423296:0@lo:250:
00000100:00100000:0.0:1789760825.008612:0:3448:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00080000:2.0:1789760825.008676:0:6432:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import eb648b1c-d606-486d-a591-51b67b446b11->MGS
00000100:00100000:0.0:1789760825.008702:0:6447:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1876700108423296
00000020:01000004:2.0:1789760825.008707:0:6432:0:(tgt_mount.c:1812:server_start_targets()) starting target lustre-MDT0000
00000100:00100000:0.0:1789760825.008708:0:6447:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1876700108423296
00000020:01000004:2.0:1789760825.008711:0:6432:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MDS (typ=mds)
00000020:00000080:2.0:1789760825.008722:0:6432:0:(genops.c:413:class_newdev()) Allocate new device MDS (00000000bcc07a03)
00000020:00000080:2.0:1789760825.008734:0:6432:0:(obd_config.c:720:class_attach_name()) OBD: dev 3 attached type mds with refcount 2
00000100:00100000:0.0:1789760825.008742:0:6447:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0
00000100:00100000:0.0:1789760825.008748:0:6447:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000213adb29 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:0+-99:3448:x1876700108423296:12345-0@lo:250:
00010000:00080000:0.0:1789760825.008768:0:6447:0:(ldlm_lib.c:1444:target_handle_connect()) MGS: connection from eb648b1c-d606-486d-a591-51b67b446b11@0@lo t0 exp 0000000000000000 cur 236 last 0
00000020:00000080:0.0:1789760825.008830:0:6447:0:(genops.c:1385:class_connect()) connect: client eb648b1c-d606-486d-a591-51b67b446b11, cookie 0x265a75c5aff9cd2c
00000100:00080000:0.0:1789760825.009075:0:6447:0:(import.c:65:import_set_state_nolock()) 00000000e653e402 : changing import state from RECOVER to FULL
00000100:00100000:0.0:1789760825.009149:0:6447:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000213adb29 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:eb648b1c-d606-486d-a591-51b67b446b11+5:3448:x1876700108423296:12345-0@lo:250: Request processed in 400us (539us total) trans 0 rc 0/0
00000100:00100000:0.0:1789760825.009158:0:6447:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0
00000100:00100000:0.0:1789760825.009225:0:3448:0:(client.c:3125:ptlrpc_free_committed()) MGC192.168.203.118@tcp: committing for last_committed 0 gen 1
00000100:00080000:0.0:1789760825.009232:0:3448:0:(import.c:1132:ptlrpc_connect_interpret()) MGC192.168.203.118@tcp: connect to target with instance 0
00000100:00080000:0.0:1789760825.009240:0:3448:0:(import.c:956:ptlrpc_connect_set_flags()) MGC192.168.203.118@tcp: Resetting ns_connect_flags to server flags: 0xa000011001002060
10000000:01000000:0.0:1789760825.009245:0:3448:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808005
00000100:00080000:0.0:1789760825.009249:0:3448:0:(import.c:65:import_set_state_nolock()) 00000000e45bf230 MGS: changing import state from CONNECTING to FULL
10000000:01000000:0.0:1789760825.009252:0:3448:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808004
00000100:00080000:0.0:1789760825.009262:0:3448:0:(pinger.c:186:ptlrpc_pinger_ir_up()) IR up
00000100:00100000:0.0:1789760825.009269:0:3448:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@00000000d4fcda5f pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:eb648b1c-d606-486d-a591-51b67b446b11:3448:1876700108423296:0@lo:250:
00000100:00100000:2.0:1789760825.015047:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt: allocate 64 new 262144-byte reqbufs (0/64 left), rc = 0
00000100:00100000:2.0:1789760825.015278:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 0 min 3 max 116
00000100:00100000:2.0:1789760825.015283:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_000'
00000100:00100000:3.0:1789760825.015739:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 1 min 3 max 116
00000100:00100000:3.0:1789760825.015746:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_001'
00000100:00100000:2.0:1789760825.016053:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 2 min 3 max 116
00000100:00100000:2.0:1789760825.016060:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_002'
00000100:00100000:3.0:1789760825.016585:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_readpage: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0
00000100:00100000:3.0:1789760825.016683:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 0 min 2 max 80
00000100:00100000:3.0:1789760825.016686:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_000'
00000100:00100000:3.0:1789760825.017085:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 1 min 2 max 80
00000100:00100000:3.0:1789760825.017092:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_001'
00010000:00010000:1.0:1789760825.030906:0:6444:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:3.0:1789760825.039705:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_out: allocate 64 new 1048576-byte reqbufs (0/64 left), rc = 0
00000100:00100000:3.0:1789760825.039992:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 0 min 2 max 116
00000100:00100000:3.0:1789760825.040007:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_000'
00000100:00100000:3.0:1789760825.040678:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 1 min 2 max 116
00000100:00100000:3.0:1789760825.040684:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_001'
00000100:00100000:3.0:1789760825.041120:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqs: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0
00000100:00100000:3.0:1789760825.041233:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 0 min 2 max 256
00000100:00100000:3.0:1789760825.041241:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0000'
00000100:00100000:3.0:1789760825.041491:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 1 min 2 max 256
00000100:00100000:3.0:1789760825.041512:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0001'
00000100:00100000:3.0:1789760825.042063:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_seqm: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0
00000100:00100000:3.0:1789760825.042153:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 0 min 2 max 256
00000100:00100000:3.0:1789760825.042156:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0000'
00000100:00100000:3.0:1789760825.042433:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 1 min 2 max 256
00000100:00100000:3.0:1789760825.042440:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0001'
00000100:00100000:3.0:1789760825.042971:0:6432:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_fld: allocate 64 new 4096-byte reqbufs (0/64 left), rc = 0
00000100:00100000:3.0:1789760825.043140:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 0 min 2 max 256
00000100:00100000:3.0:1789760825.043146:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0000'
00000100:00100000:3.0:1789760825.043418:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 1 min 2 max 256
00000100:00100000:3.0:1789760825.043425:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0001'
00000100:00100000:3.0:1789760825.056931:0:6432: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:1789760825.057130:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 0 min 3 max 116
00000100:00100000:3.0:1789760825.057135:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_000'
00000100:00100000:3.0:1789760825.058246:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 1 min 3 max 116
00000100:00100000:3.0:1789760825.058253:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_001'
00000100:00100000:3.0:1789760825.058864:0:6432:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 2 min 3 max 116
00000100:00100000:3.0:1789760825.058872:0:6432:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_002'
00000020:00000080:3.0:1789760825.059448:0:6432:0:(obd_config.c:826:class_setup()) finished setup of obd MDS (uuid MDS_uuid)
00000020:01000004:3.0:1789760825.059493:0:6432:0:(tgt_mount.c:280:server_mgc_set_fs()) Set mgc disk for /dev/mapper/mds1_flakey
10000000:01000000:3.0:1789760825.059500:0:6432:0:(mgc_request_server.c:89:mgc_fs_setup()) MGC192.168.203.118@tcp: cl_mgc_mutex lustre-MDT0000-osd for locked: rc = 0
00000040:01000000:3.0:1789760825.059593:0:6432:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.203.118@tcp ctxt 0 is initialized
00000020:01000004:3.0:1789760825.059632:0:6432:0:(tgt_mount.c:1418:server_register_target()) Registration lustre-MDT0000, fs=lustre, 192.168.203.118@tcp, index=0000, flags=0x20065
00000020:01000004:3.0:1789760825.059636:0:6432:0:(tgt_mount.c:1175:server_mti_print()) mti - server_register_target
00000020:01000004:3.0:1789760825.059638:0:6432:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000
00000020:01000004:3.0:1789760825.059639:0:6432:0:(tgt_mount.c:1177:server_mti_print()) fs:     lustre
00000020:01000004:3.0:1789760825.059641:0:6432:0:(tgt_mount.c:1178:server_mti_print()) uuid:   
00000020:01000004:3.0:1789760825.059646:0:6432:0:(tgt_mount.c:1179:server_mti_print()) ver:    0
00000020:01000004:3.0:1789760825.059647:0:6432:0:(tgt_mount.c:1180:server_mti_print()) flags:
00000020:01000004:3.0:1789760825.059649:0:6432:0:(tgt_mount.c:1182:server_mti_print()) 	 LDD_F_SV_TYPE_MDT
00000020:01000004:3.0:1789760825.059650:0:6432:0:(tgt_mount.c:1186:server_mti_print()) 	 LDD_F_SV_TYPE_MGS
00000020:01000004:3.0:1789760825.059651:0:6432:0:(tgt_mount.c:1192:server_mti_print()) 	 LDD_F_VIRIGIN
00000020:01000004:3.0:1789760825.059653:0:6432:0:(tgt_mount.c:1194:server_mti_print()) 	 LDD_F_UPDATE
00000020:01000004:3.0:1789760825.059654:0:6432:0:(tgt_mount.c:1214:server_mti_print()) 	 LDD_F_LARGE_NID
00000020:01000004:3.0:1789760825.059656:0:6432:0:(tgt_mount.c:1216:server_mti_print()) 	 LDD_F_OPC_REG
10000000:01000000:3.0:1789760825.059658:0:6432:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target lustre-MDT0000 0x10020065
00000020:01000004:3.0:1789760825.059660:0:6432:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req
00000020:01000004:3.0:1789760825.059662:0:6432:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000
00000020:01000004:3.0:1789760825.059663:0:6432:0:(tgt_mount.c:1177:server_mti_print()) fs:     lustre
00000020:01000004:3.0:1789760825.059664:0:6432:0:(tgt_mount.c:1178:server_mti_print()) uuid:   
00000020:01000004:3.0:1789760825.059665:0:6432:0:(tgt_mount.c:1179:server_mti_print()) ver:    0
00000020:01000004:3.0:1789760825.059666:0:6432:0:(tgt_mount.c:1180:server_mti_print()) flags:
00000020:01000004:3.0:1789760825.059667:0:6432:0:(tgt_mount.c:1182:server_mti_print()) 	 LDD_F_SV_TYPE_MDT
00000020:01000004:3.0:1789760825.059668:0:6432:0:(tgt_mount.c:1186:server_mti_print()) 	 LDD_F_SV_TYPE_MGS
00000020:01000004:3.0:1789760825.059669:0:6432:0:(tgt_mount.c:1192:server_mti_print()) 	 LDD_F_VIRIGIN
00000020:01000004:3.0:1789760825.059669:0:6432:0:(tgt_mount.c:1194:server_mti_print()) 	 LDD_F_UPDATE
00000020:01000004:3.0:1789760825.059670:0:6432:0:(tgt_mount.c:1214:server_mti_print()) 	 LDD_F_LARGE_NID
00000020:01000004:3.0:1789760825.059671:0:6432:0:(tgt_mount.c:1216:server_mti_print()) 	 LDD_F_OPC_REG
10000000:01000000:3.0:1789760825.059703:0:6432:0:(mgc_request_server.c:281:mgc_target_register()) register lustre-MDT0000
00000100:00100000:3.0:1789760825.059736:0:6432:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000043b6f64f pname:cluuid:pid:xid:nid:opc:job mount.lustre:eb648b1c-d606-486d-a591-51b67b446b11:6432:1876700108423424:0@lo:253:
00000100:00100000:3.0:1789760825.059799:0:6432:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:2.0:1789760825.059870:0:6450:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1876700108423424
00000100:00100000:2.0:1789760825.059879:0:6450:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1876700108423424
00000100:00100000:3.0:1789760825.059908:0:6432:0:(client.c:2715:ptlrpc_set_wait()) set 00000000cbd4b5ba going to sleep for 11 seconds
00000100:00100000:2.0:1789760825.059925:0:6450:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 1
00000100:00100000:2.0:1789760825.059936:0:6450:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@000000001995fe85 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:eb648b1c-d606-486d-a591-51b67b446b11+5:6432:x1876700108423424:12345-0@lo:253:
20000000:01000000:2.0:1789760825.059985:0:6450:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
20000000:01000000:2.0:1789760825.059991:0:6450:0:(mgs_handler.c:479:mgs_target_reg()) fs: lustre index: 0 is registered to MGS.
10000000:01000000:0.0:1789760825.060247:0:6471:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x2 (lustre)
20000000:01000000:2.0:1789760825.060272:0:6450:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2
00000040:00080000:2.0:1789760825.060475:0:6450:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
00000040:00080000:0.0:1789760825.061160:0:6472:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 64768 count 1
20000000:01000000:2.0:1789760825.061258:0:6450:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
20000000:01000000:2.0:1789760825.061260:0:6450:0:(mgs_handler.c:599:mgs_target_reg()) updating lustre-MDT0000, index=0
20000000:01000000:2.0:1789760825.061264:0:6450:0:(mgs_llog.c:869:mgs_set_index()) Set index for lustre-MDT0000 to 0
20000000:01000000:2.0:1789760825.061266:0:6450:0:(mgs_llog.c:3612:mgs_write_log_mdt()) writing new mdt lustre-MDT0000
20000000:01000000:2.0:1789760825.061273:0:6450:0:(mgs_llog.c:3172:mgs_write_log_lov()) Writing lov(lustre-MDT0000-mdtlov) log for lustre-MDT0000
00000040:00080000:2.0:1789760825.061338:0:6450:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
00000040:00080000:2.0:1789760825.061431:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].1, 224 off8416
20000000:01000000:2.0:1789760825.061441:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000-mdtlov 0xcf001 lov lustre-MDT0000-mdtlov_UUID (null) (null)
00000040:00080000:2.0:1789760825.061452:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].2, 136 off8552
00000040:00080000:2.0:1789760825.061462:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].3, 176 off8728
00000040:00080000:2.0:1789760825.061470:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].4, 224 off8952
00000040:00080000:2.0:1789760825.061499:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].5, 224 off9176
20000000:01000000:2.0:1789760825.061504:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000 0xcf001 mdt lustre-MDT0000_UUID (null) (null)
00000040:00080000:2.0:1789760825.061522:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].6, 120 off9296
20000000:01000000:2.0:1789760825.061526:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg (null) 0xcf007 lustre-MDT0000 lustre-MDT0000-mdtlov (null) (null)
00000040:00080000:2.0:1789760825.061533:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].7, 112 off9408
20000000:01000000:2.0:1789760825.061536:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000 0xcf003 lustre-MDT0000_UUID 0 lustre-MDT0000-mdtlov f
00000040:00080000:2.0:1789760825.061543:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].8, 160 off9568
00000040:00080000:2.0:1789760825.061551:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].9, 224 off9792
00000040:00080000:2.0:1789760825.061568:0:6450:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
20000000:01000000:2.0:1789760825.061571:0:6450:0:(mgs_llog.c:3172:mgs_write_log_lov()) Writing lov(lustre-clilov) log for lustre-client
00000040:00080000:2.0:1789760825.061575:0:6450:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
00000040:00080000:2.0:1789760825.061632:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].1, 224 off8416
20000000:01000000:2.0:1789760825.061639:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-clilov 0xcf001 lov lustre-clilov_UUID (null) (null)
00000040:00080000:2.0:1789760825.061648:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].2, 120 off8536
00000040:00080000:2.0:1789760825.061656:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].3, 168 off8704
00000040:00080000:2.0:1789760825.061664:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].4, 224 off8928
20000000:01000000:2.0:1789760825.061670:0:6450:0:(mgs_llog.c:3129:mgs_write_log_lmv()) Writing lmv(lustre-clilmv) log for lustre-client
00000040:00080000:2.0:1789760825.061685:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].5, 224 off9152
20000000:01000000:2.0:1789760825.061689:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-clilmv 0xcf001 lmv lustre-clilmv_UUID (null) (null)
00000040:00080000:2.0:1789760825.061702:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].6, 120 off9272
00000040:00080000:2.0:1789760825.061711:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].7, 168 off9440
00000040:00080000:2.0:1789760825.061719:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].8, 224 off9664
20000000:01000000:2.0:1789760825.061725:0:6450:0:(mgs_llog.c:3094:mgs_write_log_mount_opt()) Writing mount options log for lustre-client
00000040:00080000:2.0:1789760825.061738:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].9, 224 off9888
20000000:01000000:2.0:1789760825.061742:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg (null) 0xcf007 lustre-client lustre-clilov lustre-clilmv (null)
00000040:00080000:2.0:1789760825.061749:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].10, 120 off10008
00000040:00080000:2.0:1789760825.061758:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].11, 224 off10232
00000040:00080000:2.0:1789760825.061796:0:6450:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 12 count 12
20000000:01000000:2.0:1789760825.061838:0:6450:0:(mgs_llog.c:3309:mgs_write_log_mdc_to_lmv()) adding mdc for lustre-MDT0000 to log lustre-client:lmv(lustre-clilmv)
20000000:01000000:2.0:1789760825.061843:0:6450:0:(mgs_llog.c:1109:mgs_modify()) modify lustre-client/lustre-MDT0000/add mdc fl=4
00000040:00080000:0.0:1789760825.062000:0:6473:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 12 count 12
00000040:00080000:2.0:1789760825.062087:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].12, 224 off10456
20000000:01000000:2.0:1789760825.062099:0:6450:0:(mgs_llog.c:3355:mgs_write_log_mdc_to_lmv()) add nid 192.168.203.118@tcp for mdt
20000000:01000000:2.0:1789760825.062100:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg (null) 0xcf005 192.168.203.118@tcp (null) (null) (null)
00000040:00080000:2.0:1789760825.062124:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].13, 88 off10544
20000000:01000000:2.0:1789760825.062131:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000-mdc 0xcf001 mdc lustre-clilmv_UUID (null) (null)
00000040:00080000:2.0:1789760825.062145:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].14, 128 off10672
20000000:01000000:2.0:1789760825.062150:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000-mdc 0xcf003 lustre-MDT0000_UUID 192.168.203.118@tcp (null) (null)
00000040:00080000:2.0:1789760825.062164:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].15, 144 off10816
20000000:01000000:2.0:1789760825.062171:0:6450:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-clilmv 0xcf014 lustre-MDT0000_UUID 0 1 lustre-MDT0000-mdc_UUID
00000040:00080000:2.0:1789760825.062181:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].16, 160 off10976
00000040:00080000:2.0:1789760825.062189:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].17, 224 off11200
20000000:01000000:2.0:1789760825.062213:0:6450:0:(mgs_llog.c:5252:mgs_write_log_target()) remaining string: ' mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity ', param: 'sys.timeout=20'
20000000:01000000:2.0:1789760825.062216:0:6450:0:(mgs_llog.c:4748:mgs_write_log_param()) next param 'sys.timeout=20'
20000000:01000000:2.0:1789760825.062220:0:6450:0:(mgs_llog.c:4181:mgs_write_log_sys()) global 'sys.timeout=20' val=20
20000000:01000000:2.0:1789760825.062271:0:6450:0:(mgs_llog.c:2550:mgs_write_log_direct_all()) Changing log lustre-MDT0000
20000000:01000000:2.0:1789760825.062274:0:6450:0:(mgs_llog.c:1109:mgs_modify()) modify lustre-MDT0000/lustre/sys.timeout fl=4
00000040:00080000:0.0:1789760825.062477:0:6474:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 10 count 10
00000040:00080000:2.0:1789760825.062547:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].10, 224 off10016
00000040:00080000:2.0:1789760825.062562:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].11, 80 off10096
00000040:00080000:2.0:1789760825.062588:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].12, 224 off10320
20000000:01000000:2.0:1789760825.062595:0:6450:0:(mgs_llog.c:2550:mgs_write_log_direct_all()) Changing log lustre-client
20000000:01000000:2.0:1789760825.062600:0:6450:0:(mgs_llog.c:1109:mgs_modify()) modify lustre-client/lustre/sys.timeout fl=4
00000040:00080000:0.0:1789760825.062763:0:6475:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 18 count 18
00000040:00080000:2.0:1789760825.062836:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].18, 224 off11424
00000040:00080000:2.0:1789760825.062848:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].19, 80 off11504
00000040:00080000:2.0:1789760825.062856:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].20, 224 off11728
00000020:00000080:2.0:1789760825.062864:0:6450:0:(obd_config.c:1472:class_process_config()) processing cmd: cf009
00000020:00000080:2.0:1789760825.062865:0:6450:0:(obd_config.c:1537:class_process_config()) changing lustre timeout from 100 to 20
20000000:01000000:2.0:1789760825.062868:0:6450:0:(mgs_llog.c:5252:mgs_write_log_target()) remaining string: ' ', param: 'mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity'
20000000:01000000:2.0:1789760825.062869:0:6450:0:(mgs_llog.c:4748:mgs_write_log_param()) next param 'mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity'
20000000:01000000:2.0:1789760825.062872:0:6450:0:(mgs_llog.c:5072:mgs_write_log_param()) mdt param identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity
20000000:01000000:2.0:1789760825.062875:0:6450:0:(mgs_llog.c:1379:mgs_modify_param()) modify lustre-MDT0000/lustre-MDT0000/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity del=0
00000040:00080000:0.0:1789760825.063045:0:6476:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 13 count 13
20000000:02000000:2.0:1789760825.063081:0:6450:0:(mgs_llog.c:4120:mgs_wlp_lcfg()) Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000
00000040:00080000:2.0:1789760825.066272:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].13, 224 off10544
00000040:00080000:2.0:1789760825.066285:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].14, 160 off10704
00000040:00080000:2.0:1789760825.066293:0:6450:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].15, 224 off10928
10000000:01000000:2.0:1789760825.066301:0:6450:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x0 (lustre)
00010000:00010000:2.0:1789760825.066315:0:6450:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(EX) ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 3/0,1 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066327:0:6450:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 3/0,1 mode: EX/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066335:0:6450:0:(ldlm_lock.c:954:ldlm_lock_decref_and_cancel()) ### ldlm_lock_decref(EX) ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 4/0,1 mode: EX/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066339:0:6450:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(EX) ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 4/0,1 mode: EX/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066343:0:6450:0:(ldlm_lock.c:887:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 3/0,0 mode: EX/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066347:0:6450:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 4/0,0 mode: EX/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066357:0:6450:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock 000000002aba2031 already unused, calling callback (00000000ec092446)
00010000:00010000:2.0:1789760825.066360:0:6450:0:(ldlm_request.c:378:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 4/0,0 mode: EX/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066365:0:6450:0:(ldlm_request.c:1416:ldlm_cli_cancel_local()) ### server-side local cancel ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 5/0,0 mode: EX/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066373:0:6450:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 3/0,0 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066378:0:6450:0:(ldlm_request.c:557:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 1/0,0 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:2.0:1789760825.066382:0:6450:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: 000000002aba2031/0x265a75c5aff9cd33 lrc: 0/0,0 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 6450 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
20000000:01000000:2.0:1789760825.066392:0:6450:0:(mgs_handler.c:637:mgs_target_reg()) replying with lustre-MDT0000, index=0, rc=0
Debug log: 289 lines, 289 kept, 0 dropped, 0 bad.