00000001:02000400:2.0F:1787760134.045073:0:3106:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg247-server.virtnet: executing set_hostid
00000001:02000400:3.0F:1787760156.276280:0:3330:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg247-server.virtnet: executing load_modules_local
00000001:01000000:3.0:1787760159.075045:0:3374:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm adler32 speed = 523 MB/s
00000001:01000000:3.0:1787760159.327182:0:3374:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32 speed = 1126 MB/s
00000001:01000000:2.0:1787760159.578225:0:3374:0:(lnet-crypto.c:359:cfs_crypto_performance_test()) Crypto hash algorithm crc32c speed = 3223 MB/s
00000020:02000000:3.0:1787760161.029153:0:3422:0:(class_obd.c:771:obdclass_init()) Lustre: Build Version: 2.17.57_115_gc42a164
00000400:02000000:2.0:1787760163.232857:0:3437:0:(api-ni.c:2823:lnet_startup_lndni()) Added LNI 192.168.202.147@tcp [8/256/0/180]
00008000:02000000:2.0:1787760170.050498:0:3588:0:(echo_client.c:2574:obdecho_init()) Echo OBD driver; http://www.lustre.org/
00000001:02000400:0.0F:1787760229.194595:0:5190:0:(debug.c:653:libcfs_debug_mark_buffer()) DEBUG MARKER: oleg247-server.virtnet: executing load_modules_local
02000000:01000000:3.0:1787761245.843777:0:6073: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:1.0F:1787761249.402296:0:6575:0:(obd_mount.c:923:lmd_print())   mount data:
00000020:01000004:1.0:1787761249.402303:0:6575:0:(obd_mount.c:926:lmd_print()) device:  /dev/mapper/mds1_flakey
00000020:01000004:1.0:1787761249.402304:0:6575:0:(obd_mount.c:929:lmd_print()) options: user_xattr,errors=remount-ro
00000080:01200004:1.0:1787761249.402440:0:6575:0:(super25.c:131:lustre_fill_super()) VFS Op: sb 00000000babe96cb
00000080:02000400:1.0:1787761249.402449:0:6575:0:(super25.c:149:lustre_fill_super()) lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt'
00000020:01000004:1.0:1787761249.405369:0:6575:0:(tgt_mount.c:2500:osd_start()) Attempting to start lustre-MDT0000, type=osd-ldiskfs, lsifl=200065, mountfl=0
00000020:01000004:1.0:1787761249.405378:0:6575:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD lustre-MDT0000-osd (typ=osd-ldiskfs)
00000020:00000080:1.0:1787761249.405405:0:6575:0:(genops.c:413:class_newdev()) Allocate new device lustre-MDT0000-osd (000000007848c085)
00000020:00000080:1.0:1787761249.405431:0:6575:0:(obd_config.c:720:class_attach_name()) OBD: dev 0 attached type osd-ldiskfs with refcount 2
00100000:10000000:3.0:1787761249.421205:0:6575:0:(scrub.c:230:scrub_file_store()) lustre-MDT0000: store scrub file: rc = 0
00100000:10000000:3.0:1787761249.421245:0:6575:0:(scrub.c:230:scrub_file_store()) lustre-MDT0000: store scrub file: rc = 0
00080000:01000000:3.0:1787761249.432083:0:6575:0:(osd_lproc.c:911:osd_procfs_init()) lustre-MDT0000: register osd-ldiskfs tunable parameters
00000020:00000080:3.0:1787761249.432245:0:6575:0:(obd_config.c:826:class_setup()) finished setup of obd lustre-MDT0000-osd (uuid lustre-MDT0000-osd_UUID)
00080000:01000000:3.0:1787761249.432251:0:6575:0:(osd_handler.c:8895:osd_obd_connect()) connect #0
00000020:00000080:3.0:1787761249.432260:0:6575:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x47a99669367b4835
00000020:01000004:3.0:1787761249.432266:0:6575:0:(tgt_mount.c:2585:server_fill_super()) Found service lustre-MDT0000 on device /dev/mapper/mds1_flakey
00000020:01000000:3.0:1787761249.432270:0:6575:0:(tgt_mount.c:219:server_start_mgs()) Start MGS service MGS
00000020:01000004:3.0:1787761249.432273:0:6575:0:(tgt_mount.c:101:server_register_mount()) register mount 00000000babe96cb from MGS
00000020:01000004:3.0:1787761249.432277:0:6575:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGS (typ=mgs)
00000020:00000080:3.0:1787761249.432292:0:6575:0:(genops.c:413:class_newdev()) Allocate new device MGS (000000004e7fb30d)
00000020:00000080:3.0:1787761249.432301:0:6575:0:(obd_config.c:720:class_attach_name()) OBD: dev 1 attached type mgs with refcount 2
00000020:01000004:3.0:1787761249.432393:0:6575:0:(tgt_mount.c:153:server_get_mount()) get mount 00000000babe96cb from MGS, refs=2
00080000:01000000:3.0:1787761249.432397:0:6575:0:(osd_handler.c:8895:osd_obd_connect()) connect #1
00000020:00000080:3.0:1787761249.432400:0:6575:0:(genops.c:1385:class_connect()) connect: client lustre-MDT0000-osd_UUID, cookie 0x47a99669367b4843
00000100:00100000:3.0:1787761249.432503:0:6575: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:1787761249.432613:0:6575:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 0 min 2 max 56
00000100:00100000:3.0:1787761249.432618:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_000'
00000100:00100000:1.0:1787761249.433404:0:6575:0:(service.c:3462:ptlrpc_start_thread()) ldlm_cbd[0] started 1 min 2 max 56
00000100:00100000:1.0:1787761249.433416:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cb00_001'
00000100:00100000:1.0:1787761249.434017:0:6575:0:(service.c:155:ptlrpc_grow_req_bufs()) ldlm_canceld: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0
00000100:00100000:1.0:1787761249.434195:0:6575:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 0 min 3 max 56
00000100:00100000:1.0:1787761249.434201:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_000'
00000100:00100000:3.0:1787761249.434782:0:6575:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 1 min 3 max 56
00000100:00100000:3.0:1787761249.434807:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_001'
00000100:00100000:1.0:1787761249.435373:0:6575:0:(service.c:3462:ptlrpc_start_thread()) ldlm_canceld[0] started 2 min 3 max 56
00000100:00100000:1.0:1787761249.435380:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'ldlm_cn00_002'
00010000:00010000:3.0:1787761249.435750:0:6586:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:3.0:1787761249.435755:0:6586:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:3.0:1787761249.435757:0:6586:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:3.0:1787761249.435943:0:6587:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:3.0:1787761249.435947:0:6587:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:3.0:1787761249.435949:0:6587:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1787761249.436282:0:6575:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGS-0 is initialized
00010000:00010000:3.0:1787761249.437994:0:6586:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000001:01000000:1.0:1787761249.685967:0:6575:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip512 speed = 6291 MB/s
00000001:01000000:1.0:1787761249.935850:0:6575:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10ip4K speed = 7463 MB/s
00000001:01000000:1.0:1787761250.186211:0:6575:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc512 speed = 1611 MB/s
00000001:01000000:1.0:1787761250.436330:0:6575:0:(integrity.c:236:obd_t10_performance_test()) MGS: T10 checksum algorithm t10crc4K speed = 1847 MB/s
00080000:10000000:1.0:1787761250.439305:0:6575:0:(osd_handler.c:5551:osd_index_try()) lustre-MDT0000: index object [0x200000003:0x2:0x0] (8/32) registered
00000040:01000000:1.0:1787761250.444403:0:6575:0:(llog_obd.c:197:llog_setup()) obd MGS ctxt 0 is initialized
10000000:01000000:3.0:1787761250.444849:0:6589:0:(mgc_request.c:68:mgc_name2resid()) log params to resid 0x736d61726170/0x2 (params)
20000000:01000000:1.0:1787761250.444861:0:6575:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2
20000000:01000000:1.0:1787761250.444897:0:6575:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
00000040:00080000:1.0:1787761250.445008:0:6575:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
20000000:01000000:1.0:1787761250.445031:0:6575:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
00000100:00100000:1.0:1787761250.445472:0:6575:0:(service.c:155:ptlrpc_grow_req_bufs()) mgs: allocate 64 new 8192-byte reqbufs (0/64 left), rc = 0
00000100:00100000:1.0:1787761250.445669:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 0 min 3 max 32
00000100:00100000:1.0:1787761250.445675:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0000'
00000100:00100000:2.0:1787761250.446186:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 1 min 3 max 32
00000100:00100000:2.0:1787761250.446194:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0001'
00000100:00100000:3.0:1787761250.446463:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mgs[-1] started 2 min 3 max 32
00000100:00100000:3.0:1787761250.446474:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'll_mgs_0002'
00000100:00080000:2.0:1787761250.446899:0:6594:0:(pinger.c:466:ping_evictor_main()) Starting Ping Evictor
00000020:00000080:3.0:1787761250.447002:0:6575:0:(obd_config.c:826:class_setup()) finished setup of obd MGS (uuid MGS)
00000020:01000004:3.0:1787761250.447024:0:6575:0:(obd_mount.c:411:lustre_start_mgc()) Start MGC 'MGC192.168.202.147@tcp'
00000020:01000004:3.0:1787761250.447026:0:6575:0:(obd_mount.c:420:lustre_start_mgc()) mgs NIDs (null).
00000020:01000004:3.0:1787761250.447078:0:6575:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MGC192.168.202.147@tcp (typ=mgc)
00000020:00000080:3.0:1787761250.447095:0:6575:0:(genops.c:413:class_newdev()) Allocate new device MGC192.168.202.147@tcp (000000002a0a9230)
00000020:00000080:3.0:1787761250.447119:0:6575:0:(obd_config.c:720:class_attach_name()) OBD: dev 2 attached type mgc with refcount 2
00010000:00080000:3.0:1787761250.447248:0:6575:0:(ldlm_lib.c:102:import_set_conn()) imp 00000000f62ba437@MGC192.168.202.147@tcp: add connection 192.168.202.147@tcp at head
00010000:00010000:3.0:1787761250.447587:0:6575:0:(ldlm_pool.c:923:ldlm_pool_init()) Lock pool ldlm-pool-MGC192.168.202.147@tcp-0 is initialized
00000040:01000000:3.0:1787761250.447595:0:6575:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.202.147@tcp ctxt 1 is initialized
10000000:01000000:1.0:1787761250.448052:0:6595:0:(mgc_request.c:631:mgc_requeue_thread()) Starting requeue thread
00000020:00000080:3.0:1787761250.448247:0:6575:0:(obd_config.c:826:class_setup()) finished setup of obd MGC192.168.202.147@tcp (uuid 456ed951-49e5-4861-9fd4-1eba768c7e55)
00000020:00000080:3.0:1787761250.448270:0:6575:0:(genops.c:1385:class_connect()) connect: client 456ed951-49e5-4861-9fd4-1eba768c7e55, cookie 0x47a99669367b4851
00000100:00080000:3.0:1787761250.448284:0:6575:0:(import.c:510:import_select_connection()) MGC192.168.202.147@tcp: connect to NID 0@lo last attempt 0
00000100:00080000:3.0:1787761250.448291:0:6575:0:(import.c:624:import_select_connection()) MGC192.168.202.147@tcp: import 00000000f62ba437 using connection 192.168.202.147@tcp/0@lo
00000100:00100000:3.0:1787761250.448351:0:6575:0:(import.c:826:ptlrpc_connect_import_locked()) @@@ (re)connect request (timeout 5)  req@0000000080d163bd x1874602400678016/t0(0) o250->MGC192.168.202.147@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:3.0:1787761250.448371:0:6575:0:(pinger.c:373:ptlrpc_pinger_add_import()) adding pingable import 456ed951-49e5-4861-9fd4-1eba768c7e55->MGS
00000020:01000004:3.0:1787761250.448394:0:6575:0:(tgt_mount.c:1809:server_start_targets()) starting target lustre-MDT0000
00000020:01000004:3.0:1787761250.448399:0:6575:0:(obd_mount.c:230:lustre_start_simple()) Starting OBD MDS (typ=mds)
00000020:00000080:3.0:1787761250.448408:0:6575:0:(genops.c:413:class_newdev()) Allocate new device MDS (000000009c6de79f)
00000020:00000080:3.0:1787761250.448423:0:6575:0:(obd_config.c:720:class_attach_name()) OBD: dev 3 attached type mds with refcount 2
00000100:00100000:0.0:1787761250.448551:0:3453:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@0000000080d163bd pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:456ed951-49e5-4861-9fd4-1eba768c7e55:3453:1874602400678016:0@lo:250:
00000100:00100000:0.0:1787761250.448617:0:3453:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1787761250.448665:0:6590:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874602400678016
00000100:00100000:1.0:1787761250.448672:0:6590:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874602400678016
00000100:00100000:1.0:1787761250.448704:0:6590:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 0
00000100:00100000:1.0:1787761250.448717:0:6590:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000bad1117e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:0+-99:3453:x1874602400678016:12345-0@lo:250:
00010000:00080000:1.0:1787761250.448741:0:6590:0:(ldlm_lib.c:1482:target_handle_connect()) MGS: connection from 456ed951-49e5-4861-9fd4-1eba768c7e55@0@lo t0 exp 0000000000000000 cur 1162 last 0
00000020:00000080:1.0:1787761250.448773:0:6590:0:(genops.c:1385:class_connect()) connect: client 456ed951-49e5-4861-9fd4-1eba768c7e55, cookie 0x47a99669367b485f
00000100:00080000:1.0:1787761250.448969:0:6590:0:(import.c:65:import_set_state_nolock()) 000000004d1faa8c : changing import state from RECOVER to FULL
00000100:00100000:1.0:1787761250.449036:0:6590:0:(service.c:2610:ptlrpc_server_handle_request()) Handled RPC req@00000000bad1117e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0000:456ed951-49e5-4861-9fd4-1eba768c7e55+5:3453:x1874602400678016:12345-0@lo:250: Request processed in 318us (418us total) trans 0 rc 0/0
00000100:00100000:1.0:1787761250.449043:0:6590:0:(nrs_fifo.c:211:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 0
00000100:00100000:0.0:1787761250.449077:0:3453:0:(client.c:3125:ptlrpc_free_committed()) MGC192.168.202.147@tcp: committing for last_committed 0 gen 1
00000100:00080000:0.0:1787761250.449086:0:3453:0:(import.c:1132:ptlrpc_connect_interpret()) MGC192.168.202.147@tcp: connect to target with instance 0
00000100:00080000:0.0:1787761250.449093:0:3453:0:(import.c:956:ptlrpc_connect_set_flags()) MGC192.168.202.147@tcp: Resetting ns_connect_flags to server flags: 0xa000011001002060
10000000:01000000:0.0:1787761250.449096:0:3453:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808005
00000100:00080000:0.0:1787761250.449098:0:3453:0:(import.c:65:import_set_state_nolock()) 00000000f62ba437 MGS: changing import state from CONNECTING to FULL
10000000:01000000:0.0:1787761250.449101:0:3453:0:(mgc_request.c:1168:mgc_import_event()) import event 0x808004
00000100:00080000:0.0:1787761250.449109:0:3453:0:(pinger.c:186:ptlrpc_pinger_ir_up()) IR up
00000100:00100000:0.0:1787761250.449114:0:3453:0:(client.c:2414:ptlrpc_check_set()) Completed RPC req@0000000080d163bd pname:cluuid:pid:xid:nid:opc:job ptlrpcd_rcv:456ed951-49e5-4861-9fd4-1eba768c7e55:3453:1874602400678016:0@lo:250:
00000100:00100000:2.0:1787761250.455391:0:6575:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt: allocate 64 new 262144-byte reqbufs (0/64 left), rc = 0
00000100:00100000:2.0:1787761250.455513:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 0 min 3 max 116
00000100:00100000:2.0:1787761250.455516:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_000'
00000100:00100000:2.0:1787761250.456133:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 1 min 3 max 116
00000100:00100000:2.0:1787761250.456139:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_001'
00000100:00100000:2.0:1787761250.456384:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt[0] started 2 min 3 max 116
00000100:00100000:2.0:1787761250.456397:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt00_002'
00000100:00100000:2.0:1787761250.457093:0:6575: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:1787761250.457197:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 0 min 2 max 80
00000100:00100000:2.0:1787761250.457200:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_000'
00000100:00100000:2.0:1787761250.457496:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_readpage[0] started 1 min 2 max 80
00000100:00100000:2.0:1787761250.457501:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_rdpg00_001'
00010000:00010000:3.0:1787761250.479940:0:6587:0:(ldlm_lockd.c:2804:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:2.0:1787761250.481976:0:6575: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:1787761250.482134:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 0 min 2 max 116
00000100:00100000:2.0:1787761250.482140:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_000'
00000100:00100000:2.0:1787761250.482877:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_out[0] started 1 min 2 max 116
00000100:00100000:2.0:1787761250.482885:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_out00_001'
00000100:00100000:2.0:1787761250.483375:0:6575: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:1787761250.483494:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 0 min 2 max 256
00000100:00100000:2.0:1787761250.483499:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0000'
00000100:00100000:0.0:1787761250.483788:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqs[-1] started 1 min 2 max 256
00000100:00100000:0.0:1787761250.483796:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqs_0001'
00000100:00100000:2.0:1787761250.484271:0:6575: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:1787761250.484347:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 0 min 2 max 256
00000100:00100000:2.0:1787761250.484357:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0000'
00000100:00100000:2.0:1787761250.484658:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_seqm[-1] started 1 min 2 max 256
00000100:00100000:2.0:1787761250.484663:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_seqm_0001'
00000100:00100000:2.0:1787761250.485102:0:6575: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:1787761250.485195:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 0 min 2 max 256
00000100:00100000:2.0:1787761250.485198:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0000'
00000100:00100000:2.0:1787761250.485577:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_fld[-1] started 1 min 2 max 256
00000100:00100000:2.0:1787761250.485582:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_fld_0001'
00000100:00100000:2.0:1787761250.496037:0:6575:0:(service.c:155:ptlrpc_grow_req_bufs()) mdt_io: allocate 64 new 524288-byte reqbufs (0/64 left), rc = 0
00000100:00100000:2.0:1787761250.496193:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 0 min 3 max 116
00000100:00100000:2.0:1787761250.496198:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_000'
00000100:00100000:2.0:1787761250.497356:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 1 min 3 max 116
00000100:00100000:2.0:1787761250.497361:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_001'
00000100:00100000:2.0:1787761250.498297:0:6575:0:(service.c:3462:ptlrpc_start_thread()) mdt_io[0] started 2 min 3 max 116
00000100:00100000:2.0:1787761250.498303:0:6575:0:(service.c:3521:ptlrpc_start_thread()) starting thread 'mdt_io00_002'
00000020:00000080:2.0:1787761250.499284:0:6575:0:(obd_config.c:826:class_setup()) finished setup of obd MDS (uuid MDS_uuid)
00000020:01000004:2.0:1787761250.499309:0:6575:0:(tgt_mount.c:280:server_mgc_set_fs()) Set mgc disk for /dev/mapper/mds1_flakey
10000000:01000000:2.0:1787761250.499314:0:6575:0:(mgc_request_server.c:89:mgc_fs_setup()) MGC192.168.202.147@tcp: cl_mgc_mutex lustre-MDT0000-osd for locked: rc = 0
00000040:01000000:2.0:1787761250.499400:0:6575:0:(llog_obd.c:197:llog_setup()) obd MGC192.168.202.147@tcp ctxt 0 is initialized
00000020:01000004:2.0:1787761250.499431:0:6575:0:(tgt_mount.c:1418:server_register_target()) Registration lustre-MDT0000, fs=lustre, 192.168.202.147@tcp, index=0000, flags=0x20065
00000020:01000004:2.0:1787761250.499436:0:6575:0:(tgt_mount.c:1175:server_mti_print()) mti - server_register_target
00000020:01000004:2.0:1787761250.499438:0:6575:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000
00000020:01000004:2.0:1787761250.499440:0:6575:0:(tgt_mount.c:1177:server_mti_print()) fs:     lustre
00000020:01000004:2.0:1787761250.499441:0:6575:0:(tgt_mount.c:1178:server_mti_print()) uuid:   
00000020:01000004:2.0:1787761250.499442:0:6575:0:(tgt_mount.c:1179:server_mti_print()) ver:    0
00000020:01000004:2.0:1787761250.499444:0:6575:0:(tgt_mount.c:1180:server_mti_print()) flags:
00000020:01000004:2.0:1787761250.499446:0:6575:0:(tgt_mount.c:1182:server_mti_print()) 	 LDD_F_SV_TYPE_MDT
00000020:01000004:2.0:1787761250.499447:0:6575:0:(tgt_mount.c:1186:server_mti_print()) 	 LDD_F_SV_TYPE_MGS
00000020:01000004:2.0:1787761250.499449:0:6575:0:(tgt_mount.c:1192:server_mti_print()) 	 LDD_F_VIRIGIN
00000020:01000004:2.0:1787761250.499450:0:6575:0:(tgt_mount.c:1194:server_mti_print()) 	 LDD_F_UPDATE
00000020:01000004:2.0:1787761250.499452:0:6575:0:(tgt_mount.c:1214:server_mti_print()) 	 LDD_F_LARGE_NID
00000020:01000004:2.0:1787761250.499454:0:6575:0:(tgt_mount.c:1216:server_mti_print()) 	 LDD_F_OPC_REG
10000000:01000000:2.0:1787761250.499456:0:6575:0:(mgc_request_server.c:451:mgc_set_info_async_server()) register_target lustre-MDT0000 0x10020065
00000020:01000004:2.0:1787761250.499459:0:6575:0:(tgt_mount.c:1175:server_mti_print()) mti - mgc_target_register: req
00000020:01000004:2.0:1787761250.499461:0:6575:0:(tgt_mount.c:1176:server_mti_print()) server: lustre-MDT0000
00000020:01000004:2.0:1787761250.499462:0:6575:0:(tgt_mount.c:1177:server_mti_print()) fs:     lustre
00000020:01000004:2.0:1787761250.499463:0:6575:0:(tgt_mount.c:1178:server_mti_print()) uuid:   
00000020:01000004:2.0:1787761250.499464:0:6575:0:(tgt_mount.c:1179:server_mti_print()) ver:    0
00000020:01000004:2.0:1787761250.499465:0:6575:0:(tgt_mount.c:1180:server_mti_print()) flags:
00000020:01000004:2.0:1787761250.499466:0:6575:0:(tgt_mount.c:1182:server_mti_print()) 	 LDD_F_SV_TYPE_MDT
00000020:01000004:2.0:1787761250.499467:0:6575:0:(tgt_mount.c:1186:server_mti_print()) 	 LDD_F_SV_TYPE_MGS
00000020:01000004:2.0:1787761250.499468:0:6575:0:(tgt_mount.c:1192:server_mti_print()) 	 LDD_F_VIRIGIN
00000020:01000004:2.0:1787761250.499469:0:6575:0:(tgt_mount.c:1194:server_mti_print()) 	 LDD_F_UPDATE
00000020:01000004:2.0:1787761250.499470:0:6575:0:(tgt_mount.c:1214:server_mti_print()) 	 LDD_F_LARGE_NID
00000020:01000004:2.0:1787761250.499495:0:6575:0:(tgt_mount.c:1216:server_mti_print()) 	 LDD_F_OPC_REG
10000000:01000000:2.0:1787761250.499523:0:6575:0:(mgc_request_server.c:281:mgc_target_register()) register lustre-MDT0000
00000100:00100000:2.0:1787761250.499557:0:6575:0:(client.c:1919:ptlrpc_send_new_req()) Sending RPC req@00000000efc55a0c pname:cluuid:pid:xid:nid:opc:job mount.lustre:456ed951-49e5-4861-9fd4-1eba768c7e55:6575:1874602400678144:0@lo:253:
00000100:00100000:2.0:1787761250.499649:0:6575:0:(events.c:340:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:2.0:1787761250.499703:0:6575:0:(client.c:2715:ptlrpc_set_wait()) set 00000000ad55504d going to sleep for 11 seconds
00000100:00100000:3.0:1787761250.499746:0:6593:0:(service.c:2301:ptlrpc_server_handle_req_in()) unwrap req x1874602400678144
00000100:00100000:3.0:1787761250.499757:0:6593:0:(service.c:2366:ptlrpc_server_handle_req_in()) got req x1874602400678144
00000100:00100000:3.0:1787761250.499805:0:6593:0:(nrs_fifo.c:152:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 1
00000100:00100000:3.0:1787761250.499840:0:6593:0:(service.c:2552:ptlrpc_server_handle_request()) Handling RPC req@00000000ff99008f pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:456ed951-49e5-4861-9fd4-1eba768c7e55+5:6575:x1874602400678144:12345-0@lo:253:
20000000:01000000:3.0:1787761250.499895:0:6593:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
20000000:01000000:3.0:1787761250.499898:0:6593:0:(mgs_handler.c:479:mgs_target_reg()) fs: lustre index: 0 is registered to MGS.
10000000:01000000:3.0:1787761250.500172:0:6613:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x2 (lustre)
20000000:01000000:2.0:1787761250.500212:0:6593:0:(mgs_nids.c:666:mgs_nidtbl_init_fs()) IR: current version is 2
00000040:00080000:2.0:1787761250.500518:0:6593:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
00000040:00080000:2.0:1787761250.501452:0:6614:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 64768 count 1
20000000:01000000:3.0:1787761250.501600:0:6593:0:(mgs_llog.c:684:mgs_find_or_make_fsdb_nolock()) Created new db: rc = 0
20000000:01000000:3.0:1787761250.501605:0:6593:0:(mgs_handler.c:599:mgs_target_reg()) updating lustre-MDT0000, index=0
20000000:01000000:3.0:1787761250.501609:0:6593:0:(mgs_llog.c:869:mgs_set_index()) Set index for lustre-MDT0000 to 0
20000000:01000000:3.0:1787761250.501612:0:6593:0:(mgs_llog.c:3612:mgs_write_log_mdt()) writing new mdt lustre-MDT0000
20000000:01000000:3.0:1787761250.501620:0:6593:0:(mgs_llog.c:3172:mgs_write_log_lov()) Writing lov(lustre-MDT0000-mdtlov) log for lustre-MDT0000
00000040:00080000:3.0:1787761250.501790:0:6593:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
00000040:00080000:3.0:1787761250.501983:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].1, 224 off8416
20000000:01000000:3.0:1787761250.501995:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000-mdtlov 0xcf001 lov lustre-MDT0000-mdtlov_UUID (null) (null)
00000040:00080000:3.0:1787761250.502009:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].2, 136 off8552
00000040:00080000:3.0:1787761250.502018:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].3, 176 off8728
00000040:00080000:3.0:1787761250.502027:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].4, 224 off8952
00000040:00080000:3.0:1787761250.502078:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].5, 224 off9176
20000000:01000000:3.0:1787761250.502084:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000 0xcf001 mdt lustre-MDT0000_UUID (null) (null)
00000040:00080000:3.0:1787761250.502092:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].6, 120 off9296
20000000:01000000:3.0:1787761250.502095:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg (null) 0xcf007 lustre-MDT0000 lustre-MDT0000-mdtlov (null) (null)
00000040:00080000:3.0:1787761250.502102:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].7, 112 off9408
20000000:01000000:3.0:1787761250.502105:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000 0xcf003 lustre-MDT0000_UUID 0 lustre-MDT0000-mdtlov f
00000040:00080000:3.0:1787761250.502112:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].8, 160 off9568
00000040:00080000:3.0:1787761250.502121:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].9, 224 off9792
00000040:00080000:3.0:1787761250.502138:0:6593:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
20000000:01000000:3.0:1787761250.502141:0:6593:0:(mgs_llog.c:3172:mgs_write_log_lov()) Writing lov(lustre-clilov) log for lustre-client
00000040:00080000:3.0:1787761250.502145:0:6593:0:(llog_osd.c:211:llog_osd_read_header()) not reading header from 0-byte log
00000040:00080000:3.0:1787761250.502218:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].1, 224 off8416
20000000:01000000:3.0:1787761250.502225:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-clilov 0xcf001 lov lustre-clilov_UUID (null) (null)
00000040:00080000:3.0:1787761250.502235:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].2, 120 off8536
00000040:00080000:3.0:1787761250.502244:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].3, 168 off8704
00000040:00080000:3.0:1787761250.502252:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].4, 224 off8928
20000000:01000000:3.0:1787761250.502258:0:6593:0:(mgs_llog.c:3129:mgs_write_log_lmv()) Writing lmv(lustre-clilmv) log for lustre-client
00000040:00080000:3.0:1787761250.502273:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].5, 224 off9152
20000000:01000000:3.0:1787761250.502278:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-clilmv 0xcf001 lmv lustre-clilmv_UUID (null) (null)
00000040:00080000:3.0:1787761250.502285:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].6, 120 off9272
00000040:00080000:3.0:1787761250.502304:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].7, 168 off9440
00000040:00080000:3.0:1787761250.502319:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].8, 224 off9664
20000000:01000000:3.0:1787761250.502325:0:6593:0:(mgs_llog.c:3094:mgs_write_log_mount_opt()) Writing mount options log for lustre-client
00000040:00080000:3.0:1787761250.502338:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].9, 224 off9888
20000000:01000000:3.0:1787761250.502343:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg (null) 0xcf007 lustre-client lustre-clilov lustre-clilmv (null)
00000040:00080000:3.0:1787761250.502350:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].10, 120 off10008
00000040:00080000:3.0:1787761250.502359:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].11, 224 off10232
00000040:00080000:3.0:1787761250.502407:0:6593:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 12 count 12
20000000:01000000:3.0:1787761250.502420:0:6593: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:3.0:1787761250.502425:0:6593:0:(mgs_llog.c:1109:mgs_modify()) modify lustre-client/lustre-MDT0000/add mdc fl=4
00000040:00080000:3.0:1787761250.502740:0:6615:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 12 count 12
00000040:00080000:2.0:1787761250.502888:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].12, 224 off10456
20000000:01000000:2.0:1787761250.502904:0:6593:0:(mgs_llog.c:3355:mgs_write_log_mdc_to_lmv()) add nid 192.168.202.147@tcp for mdt
20000000:01000000:2.0:1787761250.502905:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg (null) 0xcf005 192.168.202.147@tcp (null) (null) (null)
00000040:00080000:2.0:1787761250.502915:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].13, 88 off10544
20000000:01000000:2.0:1787761250.502934:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000-mdc 0xcf001 mdc lustre-clilmv_UUID (null) (null)
00000040:00080000:2.0:1787761250.502946:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].14, 128 off10672
20000000:01000000:2.0:1787761250.502951:0:6593:0:(mgs_llog.c:1539:record_base_raw()) lcfg lustre-MDT0000-mdc 0xcf003 lustre-MDT0000_UUID 192.168.202.147@tcp (null) (null)
00000040:00080000:2.0:1787761250.502958:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].15, 144 off10816
20000000:01000000:2.0:1787761250.502963:0:6593: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:1787761250.502970:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].16, 160 off10976
00000040:00080000:2.0:1787761250.502979:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].17, 224 off11200
20000000:01000000:2.0:1787761250.503000:0:6593: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:1787761250.503002:0:6593:0:(mgs_llog.c:4748:mgs_write_log_param()) next param 'sys.timeout=20'
20000000:01000000:2.0:1787761250.503005:0:6593:0:(mgs_llog.c:4181:mgs_write_log_sys()) global 'sys.timeout=20' val=20
20000000:01000000:2.0:1787761250.503050:0:6593:0:(mgs_llog.c:2550:mgs_write_log_direct_all()) Changing log lustre-client
20000000:01000000:2.0:1787761250.503052:0:6593:0:(mgs_llog.c:1109:mgs_modify()) modify lustre-client/lustre/sys.timeout fl=4
00000040:00080000:2.0:1787761250.503231:0:6616:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x3:0x0] index 18 count 18
00000040:00080000:3.0:1787761250.503318:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].18, 224 off11424
00000040:00080000:3.0:1787761250.503332:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].19, 80 off11504
00000040:00080000:3.0:1787761250.503340:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x3:0x0].20, 224 off11728
20000000:01000000:3.0:1787761250.503348:0:6593:0:(mgs_llog.c:2550:mgs_write_log_direct_all()) Changing log lustre-MDT0000
20000000:01000000:3.0:1787761250.503349:0:6593:0:(mgs_llog.c:1109:mgs_modify()) modify lustre-MDT0000/lustre/sys.timeout fl=4
00000040:00080000:3.0:1787761250.503526:0:6617:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 10 count 10
00000040:00080000:2.0:1787761250.503633:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].10, 224 off10016
00000040:00080000:2.0:1787761250.503656:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].11, 80 off10096
00000040:00080000:2.0:1787761250.503671:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].12, 224 off10320
00000020:00000080:2.0:1787761250.503683:0:6593:0:(obd_config.c:1472:class_process_config()) processing cmd: cf009
00000020:00000080:2.0:1787761250.503685:0:6593:0:(obd_config.c:1537:class_process_config()) changing lustre timeout from 100 to 20
20000000:01000000:2.0:1787761250.503690:0:6593: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:1787761250.503700:0:6593: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:1787761250.503705:0:6593: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:1787761250.503709:0:6593: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:2.0:1787761250.503971:0:6618:0:(llog.c:862:llog_process_thread()) stop processing plain [0xa:0x4:0x0] index 13 count 13
20000000:02000000:3.0:1787761250.504039:0:6593: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:3.0:1787761250.507226:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].13, 224 off10544
00000040:00080000:3.0:1787761250.507241:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].14, 160 off10704
00000040:00080000:3.0:1787761250.507250:0:6593:0:(llog_osd.c:725:llog_osd_write_rec()) added record [0xa:0x4:0x0].15, 224 off10928
10000000:01000000:3.0:1787761250.507261:0:6593:0:(mgc_request.c:68:mgc_name2resid()) log lustre to resid 0x65727473756c/0x0 (lustre)
00010000:00010000:3.0:1787761250.507279:0:6593:0:(ldlm_lock.c:775:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(EX) ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 lrc: 3/0,1 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507294:0:6593:0:(ldlm_lock.c:1072:ldlm_granted_list_add_lock()) ### About to add lock: ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 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: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507303:0:6593:0:(ldlm_lock.c:954:ldlm_lock_decref_and_cancel()) ### ldlm_lock_decref(EX) ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 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: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507308:0:6593:0:(ldlm_lock.c:829:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(EX) ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 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: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507321:0:6593:0:(ldlm_lock.c:887:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 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: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507326:0:6593:0:(ldlm_lockd.c:1907:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 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: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507330:0:6593:0:(ldlm_lockd.c:1921:ldlm_handle_bl_callback()) Lock 00000000585c15ee already unused, calling callback (00000000460a2771)
00010000:00010000:3.0:1787761250.507333:0:6593:0:(ldlm_request.c:378:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 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: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507339:0:6593:0:(ldlm_request.c:1416:ldlm_cli_cancel_local()) ### server-side local cancel ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 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: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507351:0:6593:0:(ldlm_lockd.c:1933:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 lrc: 3/0,0 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507358:0:6593:0:(ldlm_request.c:557:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 lrc: 1/0,0 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
00010000:00010000:3.0:1787761250.507362:0:6593:0:(ldlm_lock.c:193:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: MGS lock: 00000000585c15ee/0x47a99669367b4866 lrc: 0/0,0 mode: --/EX res: [0x65727473756c:0x0:0x0].0x0 rrc: 2 type: PLN flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 6593 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0
20000000:01000000:3.0:1787761250.507373:0:6593: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.