[D 16:57:53.698832] *************************************************** [D 16:57:53.698866] src/apps/kernel/linux/pvfs2-client-core starting at 2008-02-13 16:57 [D 16:57:53.698895] *************************************************** [D 16:57:53.698936] [SM Frame PUSH]: (0x100c9440) frame: 0x100c9500 [D 16:57:53.698960] [SM Locating]: (0x100c9440) op-id: 301 [D 16:57:53.698983] client_op_state_get_machine 301 [D 16:57:53.699006] [SM Locating]: (0x100c9440) located: client_perf_count_timer_sm:do_work [D 16:57:53.699029] PINT_client_state_machine_post smcb 0x100c9440, op: UNKNOWN [D 16:57:53.699052] [SM Entering]: (0x100c9440) client_perf_count_timer_sm:do_work (status: 0) [P 16:57:53.699162] Start times (hr:min:sec): 16:57:53.698 0 0 0 0 0 [P 16:57:53.699190] Intervals (hr:min:sec) : 00:00:00.001 0 0 0 0 0 [P 16:57:53.699214] ------------------------------------------------------------------------------------------------------------- [P 16:57:53.699238] ACACHE_NUM_ENTRIES : 0 0 0 0 0 0 [P 16:57:53.699262] ACACHE_SOFT_LIMIT : 5120 0 0 0 0 0 [P 16:57:53.699286] ACACHE_HARD_LIMIT : 10240 0 0 0 0 0 [P 16:57:53.699310] ACACHE_HITS : 0 0 0 0 0 0 [P 16:57:53.699334] ACACHE_MISSES : 0 0 0 0 0 0 [P 16:57:53.699357] ACACHE_UPDATES : 0 0 0 0 0 0 [P 16:57:53.699384] ACACHE_PURGES : 0 0 0 0 0 0 [P 16:57:53.699408] ACACHE_REPLACEMENTS : 0 0 0 0 0 0 [P 16:57:53.699432] ACACHE_DELETIONS : 0 0 0 0 0 0 [P 16:57:53.699456] ACACHE_ENABLED : 1 0 0 0 0 0 [D 16:57:53.699483] [SM Exiting]: (0x100c9440) client_perf_count_timer_sm:do_work (error code: 0), (action: DEFERRED) [D 16:57:53.699508] Posted UNKNOWN (-1) (waiting for test)(-1073741839) [D 16:57:53.699533] [SM Frame PUSH]: (0x100c9f20) frame: 0x100c9fe0 [D 16:57:53.699557] [SM Locating]: (0x100c9f20) op-id: 301 [D 16:57:53.699580] client_op_state_get_machine 301 [D 16:57:53.699602] [SM Locating]: (0x100c9f20) located: client_perf_count_timer_sm:do_work [D 16:57:53.699625] PINT_client_state_machine_post smcb 0x100c9f20, op: UNKNOWN [D 16:57:53.699649] [SM Entering]: (0x100c9f20) client_perf_count_timer_sm:do_work (status: 0) [P 16:57:53.699748] Start times (hr:min:sec): 16:57:53.698 0 0 0 0 0 [P 16:57:53.699772] Intervals (hr:min:sec) : 00:00:00.001 0 0 0 0 0 [P 16:57:53.699796] ------------------------------------------------------------------------------------------------------------- [P 16:57:53.699821] NCACHE_NUM_ENTRIES : 0 0 0 0 0 0 [P 16:57:53.699845] NCACHE_SOFT_LIMIT : 5120 0 0 0 0 0 [P 16:57:53.699868] NCACHE_HARD_LIMIT : 10240 0 0 0 0 0 [P 16:57:53.699892] NCACHE_HITS : 0 0 0 0 0 0 [P 16:57:53.699915] NCACHE_MISSES : 0 0 0 0 0 0 [P 16:57:53.699939] NCACHE_UPDATES : 0 0 0 0 0 0 [P 16:57:53.699967] NCACHE_PURGES : 0 0 0 0 0 0 [P 16:57:53.699991] NCACHE_REPLACEMENTS : 0 0 0 0 0 0 [P 16:57:53.700015] NCACHE_DELETIONS : 0 0 0 0 0 0 [P 16:57:53.700037] NCACHE_ENABLED : 1 0 0 0 0 0 [D 16:57:53.700063] [SM Exiting]: (0x100c9f20) client_perf_count_timer_sm:do_work (error code: 0), (action: DEFERRED) [D 16:57:53.700088] Posted UNKNOWN (-1) (waiting for test)(-1073741839) [D 16:57:53.700386] [INFO]: Mapping pointer 0x4000024c000 for I/O. [D 16:57:53.707257] [INFO]: Mapping pointer 0x4000164e000 for I/O. [D 16:57:53.707347] process_vfs_requests called [D 16:57:53.707382] PINT_sys_dev_unexp [D 16:57:53.707406] [SM Frame PUSH]: (0x100cc3b0) frame: 0x100cc470 [D 16:57:53.707430] [SM Locating]: (0x100cc3b0) op-id: 400 [D 16:57:53.707453] client_op_state_get_machine 400 [D 16:57:53.707476] [SM Locating]: (0x100cc3b0) located: sysdev_unexp_sm:post [D 16:57:53.707501] PINT_client_state_machine_post smcb 0x100cc3b0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.707525] [SM Entering]: (0x100cc3b0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.707554] [SM Exiting]: (0x100cc3b0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.707579] Posted PVFS_DEV_UNEXPECTED (8) (waiting for test)(-1073741839) [D 16:57:53.707610] PINT_sys_dev_unexp [D 16:57:53.707633] [SM Frame PUSH]: (0x100ce2a0) frame: 0x100ce360 [D 16:57:53.707656] [SM Locating]: (0x100ce2a0) op-id: 400 [D 16:57:53.707682] client_op_state_get_machine 400 [D 16:57:53.707705] [SM Locating]: (0x100ce2a0) located: sysdev_unexp_sm:post [D 16:57:53.707729] PINT_client_state_machine_post smcb 0x100ce2a0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.707752] [SM Entering]: (0x100ce2a0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.707777] [SM Exiting]: (0x100ce2a0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.707802] Posted PVFS_DEV_UNEXPECTED (10) (waiting for test)(-1073741839) [D 16:57:53.707832] PINT_sys_dev_unexp [D 16:57:53.707856] [SM Frame PUSH]: (0x100d0190) frame: 0x100d0250 [D 16:57:53.707880] [SM Locating]: (0x100d0190) op-id: 400 [D 16:57:53.707902] client_op_state_get_machine 400 [D 16:57:53.707925] [SM Locating]: (0x100d0190) located: sysdev_unexp_sm:post [D 16:57:53.707948] PINT_client_state_machine_post smcb 0x100d0190, op: PVFS_DEV_UNEXPECTED [D 16:57:53.707972] [SM Entering]: (0x100d0190) sysdev_unexp_sm:post (status: 0) [D 16:57:53.707997] [SM Exiting]: (0x100d0190) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.708023] Posted PVFS_DEV_UNEXPECTED (12) (waiting for test)(-1073741839) [D 16:57:53.708052] PINT_sys_dev_unexp [D 16:57:53.708076] [SM Frame PUSH]: (0x100d2080) frame: 0x100d2140 [D 16:57:53.708099] [SM Locating]: (0x100d2080) op-id: 400 [D 16:57:53.708123] client_op_state_get_machine 400 [D 16:57:53.708146] [SM Locating]: (0x100d2080) located: sysdev_unexp_sm:post [D 16:57:53.708168] PINT_client_state_machine_post smcb 0x100d2080, op: PVFS_DEV_UNEXPECTED [D 16:57:53.708192] [SM Entering]: (0x100d2080) sysdev_unexp_sm:post (status: 0) [D 16:57:53.708217] [SM Exiting]: (0x100d2080) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.708242] Posted PVFS_DEV_UNEXPECTED (14) (waiting for test)(-1073741839) [D 16:57:53.708270] PINT_sys_dev_unexp [D 16:57:53.708295] [SM Frame PUSH]: (0x100d3f70) frame: 0x100d4030 [D 16:57:53.708319] [SM Locating]: (0x100d3f70) op-id: 400 [D 16:57:53.708343] client_op_state_get_machine 400 [D 16:57:53.708366] [SM Locating]: (0x100d3f70) located: sysdev_unexp_sm:post [D 16:57:53.708389] PINT_client_state_machine_post smcb 0x100d3f70, op: PVFS_DEV_UNEXPECTED [D 16:57:53.708413] [SM Entering]: (0x100d3f70) sysdev_unexp_sm:post (status: 0) [D 16:57:53.708438] [SM Exiting]: (0x100d3f70) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.708466] Posted PVFS_DEV_UNEXPECTED (16) (waiting for test)(-1073741839) [D 16:57:53.708494] PINT_sys_dev_unexp [D 16:57:53.708520] [SM Frame PUSH]: (0x100d5e60) frame: 0x100d5f20 [D 16:57:53.708544] [SM Locating]: (0x100d5e60) op-id: 400 [D 16:57:53.708568] client_op_state_get_machine 400 [D 16:57:53.708590] [SM Locating]: (0x100d5e60) located: sysdev_unexp_sm:post [D 16:57:53.708614] PINT_client_state_machine_post smcb 0x100d5e60, op: PVFS_DEV_UNEXPECTED [D 16:57:53.708638] [SM Entering]: (0x100d5e60) sysdev_unexp_sm:post (status: 0) [D 16:57:53.708662] [SM Exiting]: (0x100d5e60) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.708687] Posted PVFS_DEV_UNEXPECTED (18) (waiting for test)(-1073741839) [D 16:57:53.708715] PINT_sys_dev_unexp [D 16:57:53.708744] [SM Frame PUSH]: (0x100d7d50) frame: 0x100d7e10 [D 16:57:53.708767] [SM Locating]: (0x100d7d50) op-id: 400 [D 16:57:53.708790] client_op_state_get_machine 400 [D 16:57:53.708813] [SM Locating]: (0x100d7d50) located: sysdev_unexp_sm:post [D 16:57:53.708837] PINT_client_state_machine_post smcb 0x100d7d50, op: PVFS_DEV_UNEXPECTED [D 16:57:53.708860] [SM Entering]: (0x100d7d50) sysdev_unexp_sm:post (status: 0) [D 16:57:53.708886] [SM Exiting]: (0x100d7d50) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.708910] Posted PVFS_DEV_UNEXPECTED (20) (waiting for test)(-1073741839) [D 16:57:53.708941] PINT_sys_dev_unexp [D 16:57:53.708969] [SM Frame PUSH]: (0x100d9c40) frame: 0x100d9d00 [D 16:57:53.708992] [SM Locating]: (0x100d9c40) op-id: 400 [D 16:57:53.709015] client_op_state_get_machine 400 [D 16:57:53.709038] [SM Locating]: (0x100d9c40) located: sysdev_unexp_sm:post [D 16:57:53.709062] PINT_client_state_machine_post smcb 0x100d9c40, op: PVFS_DEV_UNEXPECTED [D 16:57:53.709086] [SM Entering]: (0x100d9c40) sysdev_unexp_sm:post (status: 0) [D 16:57:53.709111] [SM Exiting]: (0x100d9c40) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.709136] Posted PVFS_DEV_UNEXPECTED (22) (waiting for test)(-1073741839) [D 16:57:53.709163] PINT_sys_dev_unexp [D 16:57:53.709190] [SM Frame PUSH]: (0x100dbb30) frame: 0x100dbbf0 [D 16:57:53.709214] [SM Locating]: (0x100dbb30) op-id: 400 [D 16:57:53.709238] client_op_state_get_machine 400 [D 16:57:53.709260] [SM Locating]: (0x100dbb30) located: sysdev_unexp_sm:post [D 16:57:53.709283] PINT_client_state_machine_post smcb 0x100dbb30, op: PVFS_DEV_UNEXPECTED [D 16:57:53.709307] [SM Entering]: (0x100dbb30) sysdev_unexp_sm:post (status: 0) [D 16:57:53.709332] [SM Exiting]: (0x100dbb30) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.709357] Posted PVFS_DEV_UNEXPECTED (24) (waiting for test)(-1073741839) [D 16:57:53.709386] PINT_sys_dev_unexp [D 16:57:53.709417] [SM Frame PUSH]: (0x100dda20) frame: 0x100ddae0 [D 16:57:53.709444] [SM Locating]: (0x100dda20) op-id: 400 [D 16:57:53.709469] client_op_state_get_machine 400 [D 16:57:53.709495] [SM Locating]: (0x100dda20) located: sysdev_unexp_sm:post [D 16:57:53.709519] PINT_client_state_machine_post smcb 0x100dda20, op: PVFS_DEV_UNEXPECTED [D 16:57:53.709543] [SM Entering]: (0x100dda20) sysdev_unexp_sm:post (status: 0) [D 16:57:53.709568] [SM Exiting]: (0x100dda20) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.709592] Posted PVFS_DEV_UNEXPECTED (26) (waiting for test)(-1073741839) [D 16:57:53.709620] PINT_sys_dev_unexp [D 16:57:53.709647] [SM Frame PUSH]: (0x100df910) frame: 0x100df9d0 [D 16:57:53.709671] [SM Locating]: (0x100df910) op-id: 400 [D 16:57:53.709694] client_op_state_get_machine 400 [D 16:57:53.709717] [SM Locating]: (0x100df910) located: sysdev_unexp_sm:post [D 16:57:53.709740] PINT_client_state_machine_post smcb 0x100df910, op: PVFS_DEV_UNEXPECTED [D 16:57:53.709764] [SM Entering]: (0x100df910) sysdev_unexp_sm:post (status: 0) [D 16:57:53.709789] [SM Exiting]: (0x100df910) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.709814] Posted PVFS_DEV_UNEXPECTED (28) (waiting for test)(-1073741839) [D 16:57:53.709843] PINT_sys_dev_unexp [D 16:57:53.709870] [SM Frame PUSH]: (0x100e1800) frame: 0x100e18c0 [D 16:57:53.709895] [SM Locating]: (0x100e1800) op-id: 400 [D 16:57:53.709918] client_op_state_get_machine 400 [D 16:57:53.709940] [SM Locating]: (0x100e1800) located: sysdev_unexp_sm:post [D 16:57:53.709963] PINT_client_state_machine_post smcb 0x100e1800, op: PVFS_DEV_UNEXPECTED [D 16:57:53.709987] [SM Entering]: (0x100e1800) sysdev_unexp_sm:post (status: 0) [D 16:57:53.710012] [SM Exiting]: (0x100e1800) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.710037] Posted PVFS_DEV_UNEXPECTED (30) (waiting for test)(-1073741839) [D 16:57:53.710063] PINT_sys_dev_unexp [D 16:57:53.710087] [SM Frame PUSH]: (0x100e36f0) frame: 0x100e37b0 [D 16:57:53.710111] [SM Locating]: (0x100e36f0) op-id: 400 [D 16:57:53.710134] client_op_state_get_machine 400 [D 16:57:53.710157] [SM Locating]: (0x100e36f0) located: sysdev_unexp_sm:post [D 16:57:53.710181] PINT_client_state_machine_post smcb 0x100e36f0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.710204] [SM Entering]: (0x100e36f0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.710232] [SM Exiting]: (0x100e36f0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.710257] Posted PVFS_DEV_UNEXPECTED (32) (waiting for test)(-1073741839) [D 16:57:53.710285] PINT_sys_dev_unexp [D 16:57:53.710309] [SM Frame PUSH]: (0x100e55e0) frame: 0x100e56a0 [D 16:57:53.710331] [SM Locating]: (0x100e55e0) op-id: 400 [D 16:57:53.710355] client_op_state_get_machine 400 [D 16:57:53.710378] [SM Locating]: (0x100e55e0) located: sysdev_unexp_sm:post [D 16:57:53.710401] PINT_client_state_machine_post smcb 0x100e55e0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.710425] [SM Entering]: (0x100e55e0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.710453] [SM Exiting]: (0x100e55e0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.710478] Posted PVFS_DEV_UNEXPECTED (34) (waiting for test)(-1073741839) [D 16:57:53.710508] PINT_sys_dev_unexp [D 16:57:53.710532] [SM Frame PUSH]: (0x100e74d0) frame: 0x100e7590 [D 16:57:53.710556] [SM Locating]: (0x100e74d0) op-id: 400 [D 16:57:53.710578] client_op_state_get_machine 400 [D 16:57:53.710601] [SM Locating]: (0x100e74d0) located: sysdev_unexp_sm:post [D 16:57:53.710624] PINT_client_state_machine_post smcb 0x100e74d0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.710648] [SM Entering]: (0x100e74d0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.710673] [SM Exiting]: (0x100e74d0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.710698] Posted PVFS_DEV_UNEXPECTED (36) (waiting for test)(-1073741839) [D 16:57:53.710727] PINT_sys_dev_unexp [D 16:57:53.710751] [SM Frame PUSH]: (0x100e93c0) frame: 0x100e9480 [D 16:57:53.710775] [SM Locating]: (0x100e93c0) op-id: 400 [D 16:57:53.710798] client_op_state_get_machine 400 [D 16:57:53.710820] [SM Locating]: (0x100e93c0) located: sysdev_unexp_sm:post [D 16:57:53.710844] PINT_client_state_machine_post smcb 0x100e93c0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.710866] [SM Entering]: (0x100e93c0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.710891] [SM Exiting]: (0x100e93c0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.710916] Posted PVFS_DEV_UNEXPECTED (38) (waiting for test)(-1073741839) [D 16:57:53.710946] PINT_sys_dev_unexp [D 16:57:53.710969] [SM Frame PUSH]: (0x100eb2b0) frame: 0x100eb370 [D 16:57:53.710992] [SM Locating]: (0x100eb2b0) op-id: 400 [D 16:57:53.711015] client_op_state_get_machine 400 [D 16:57:53.711038] [SM Locating]: (0x100eb2b0) located: sysdev_unexp_sm:post [D 16:57:53.711062] PINT_client_state_machine_post smcb 0x100eb2b0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.711085] [SM Entering]: (0x100eb2b0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.711111] [SM Exiting]: (0x100eb2b0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.711135] Posted PVFS_DEV_UNEXPECTED (40) (waiting for test)(-1073741839) [D 16:57:53.711165] PINT_sys_dev_unexp [D 16:57:53.711189] [SM Frame PUSH]: (0x100ed1a0) frame: 0x100ed260 [D 16:57:53.711212] [SM Locating]: (0x100ed1a0) op-id: 400 [D 16:57:53.711237] client_op_state_get_machine 400 [D 16:57:53.711260] [SM Locating]: (0x100ed1a0) located: sysdev_unexp_sm:post [D 16:57:53.711284] PINT_client_state_machine_post smcb 0x100ed1a0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.711307] [SM Entering]: (0x100ed1a0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.711333] [SM Exiting]: (0x100ed1a0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.711358] Posted PVFS_DEV_UNEXPECTED (42) (waiting for test)(-1073741839) [D 16:57:53.711393] PINT_sys_dev_unexp [D 16:57:53.711417] [SM Frame PUSH]: (0x100ef090) frame: 0x100ef150 [D 16:57:53.711440] [SM Locating]: (0x100ef090) op-id: 400 [D 16:57:53.711462] client_op_state_get_machine 400 [D 16:57:53.711486] [SM Locating]: (0x100ef090) located: sysdev_unexp_sm:post [D 16:57:53.711509] PINT_client_state_machine_post smcb 0x100ef090, op: PVFS_DEV_UNEXPECTED [D 16:57:53.711533] [SM Entering]: (0x100ef090) sysdev_unexp_sm:post (status: 0) [D 16:57:53.711558] [SM Exiting]: (0x100ef090) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.711583] Posted PVFS_DEV_UNEXPECTED (44) (waiting for test)(-1073741839) [D 16:57:53.711610] PINT_sys_dev_unexp [D 16:57:53.711637] [SM Frame PUSH]: (0x100f0f80) frame: 0x100f1040 [D 16:57:53.711661] [SM Locating]: (0x100f0f80) op-id: 400 [D 16:57:53.711684] client_op_state_get_machine 400 [D 16:57:53.711707] [SM Locating]: (0x100f0f80) located: sysdev_unexp_sm:post [D 16:57:53.711730] PINT_client_state_machine_post smcb 0x100f0f80, op: PVFS_DEV_UNEXPECTED [D 16:57:53.711753] [SM Entering]: (0x100f0f80) sysdev_unexp_sm:post (status: 0) [D 16:57:53.711779] [SM Exiting]: (0x100f0f80) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.711804] Posted PVFS_DEV_UNEXPECTED (46) (waiting for test)(-1073741839) [D 16:57:53.711831] PINT_sys_dev_unexp [D 16:57:53.711858] [SM Frame PUSH]: (0x100f2e70) frame: 0x100f2f30 [D 16:57:53.711882] [SM Locating]: (0x100f2e70) op-id: 400 [D 16:57:53.711905] client_op_state_get_machine 400 [D 16:57:53.711928] [SM Locating]: (0x100f2e70) located: sysdev_unexp_sm:post [D 16:57:53.711951] PINT_client_state_machine_post smcb 0x100f2e70, op: PVFS_DEV_UNEXPECTED [D 16:57:53.711975] [SM Entering]: (0x100f2e70) sysdev_unexp_sm:post (status: 0) [D 16:57:53.711999] [SM Exiting]: (0x100f2e70) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.712024] Posted PVFS_DEV_UNEXPECTED (48) (waiting for test)(-1073741839) [D 16:57:53.712052] PINT_sys_dev_unexp [D 16:57:53.712081] [SM Frame PUSH]: (0x100f4d60) frame: 0x100f4e20 [D 16:57:53.712105] [SM Locating]: (0x100f4d60) op-id: 400 [D 16:57:53.712128] client_op_state_get_machine 400 [D 16:57:53.712151] [SM Locating]: (0x100f4d60) located: sysdev_unexp_sm:post [D 16:57:53.712174] PINT_client_state_machine_post smcb 0x100f4d60, op: PVFS_DEV_UNEXPECTED [D 16:57:53.712198] [SM Entering]: (0x100f4d60) sysdev_unexp_sm:post (status: 0) [D 16:57:53.712223] [SM Exiting]: (0x100f4d60) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.712247] Posted PVFS_DEV_UNEXPECTED (50) (waiting for test)(-1073741839) [D 16:57:53.712277] PINT_sys_dev_unexp [D 16:57:53.712304] [SM Frame PUSH]: (0x100f6c50) frame: 0x100f6d10 [D 16:57:53.712327] [SM Locating]: (0x100f6c50) op-id: 400 [D 16:57:53.712351] client_op_state_get_machine 400 [D 16:57:53.712374] [SM Locating]: (0x100f6c50) located: sysdev_unexp_sm:post [D 16:57:53.712397] PINT_client_state_machine_post smcb 0x100f6c50, op: PVFS_DEV_UNEXPECTED [D 16:57:53.712421] [SM Entering]: (0x100f6c50) sysdev_unexp_sm:post (status: 0) [D 16:57:53.712446] [SM Exiting]: (0x100f6c50) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.712471] Posted PVFS_DEV_UNEXPECTED (52) (waiting for test)(-1073741839) [D 16:57:53.712498] PINT_sys_dev_unexp [D 16:57:53.712527] [SM Frame PUSH]: (0x100f8b40) frame: 0x100f8c00 [D 16:57:53.712551] [SM Locating]: (0x100f8b40) op-id: 400 [D 16:57:53.712574] client_op_state_get_machine 400 [D 16:57:53.712596] [SM Locating]: (0x100f8b40) located: sysdev_unexp_sm:post [D 16:57:53.712619] PINT_client_state_machine_post smcb 0x100f8b40, op: PVFS_DEV_UNEXPECTED [D 16:57:53.712645] [SM Entering]: (0x100f8b40) sysdev_unexp_sm:post (status: 0) [D 16:57:53.712671] [SM Exiting]: (0x100f8b40) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.712696] Posted PVFS_DEV_UNEXPECTED (54) (waiting for test)(-1073741839) [D 16:57:53.712722] PINT_sys_dev_unexp [D 16:57:53.712749] [SM Frame PUSH]: (0x100faa30) frame: 0x100faaf0 [D 16:57:53.712773] [SM Locating]: (0x100faa30) op-id: 400 [D 16:57:53.712797] client_op_state_get_machine 400 [D 16:57:53.712820] [SM Locating]: (0x100faa30) located: sysdev_unexp_sm:post [D 16:57:53.712842] PINT_client_state_machine_post smcb 0x100faa30, op: PVFS_DEV_UNEXPECTED [D 16:57:53.712866] [SM Entering]: (0x100faa30) sysdev_unexp_sm:post (status: 0) [D 16:57:53.712891] [SM Exiting]: (0x100faa30) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.712916] Posted PVFS_DEV_UNEXPECTED (56) (waiting for test)(-1073741839) [D 16:57:53.712944] PINT_sys_dev_unexp [D 16:57:53.712970] [SM Frame PUSH]: (0x100fc920) frame: 0x100fc9e0 [D 16:57:53.712994] [SM Locating]: (0x100fc920) op-id: 400 [D 16:57:53.713017] client_op_state_get_machine 400 [D 16:57:53.713041] [SM Locating]: (0x100fc920) located: sysdev_unexp_sm:post [D 16:57:53.713064] PINT_client_state_machine_post smcb 0x100fc920, op: PVFS_DEV_UNEXPECTED [D 16:57:53.713087] [SM Entering]: (0x100fc920) sysdev_unexp_sm:post (status: 0) [D 16:57:53.713112] [SM Exiting]: (0x100fc920) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.713137] Posted PVFS_DEV_UNEXPECTED (58) (waiting for test)(-1073741839) [D 16:57:53.713165] PINT_sys_dev_unexp [D 16:57:53.713191] [SM Frame PUSH]: (0x100fe810) frame: 0x100fe8d0 [D 16:57:53.713215] [SM Locating]: (0x100fe810) op-id: 400 [D 16:57:53.713238] client_op_state_get_machine 400 [D 16:57:53.713261] [SM Locating]: (0x100fe810) located: sysdev_unexp_sm:post [D 16:57:53.713285] PINT_client_state_machine_post smcb 0x100fe810, op: PVFS_DEV_UNEXPECTED [D 16:57:53.713309] [SM Entering]: (0x100fe810) sysdev_unexp_sm:post (status: 0) [D 16:57:53.713334] [SM Exiting]: (0x100fe810) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.713358] Posted PVFS_DEV_UNEXPECTED (60) (waiting for test)(-1073741839) [D 16:57:53.713389] PINT_sys_dev_unexp [D 16:57:53.713416] [SM Frame PUSH]: (0x10100700) frame: 0x101007c0 [D 16:57:53.713441] [SM Locating]: (0x10100700) op-id: 400 [D 16:57:53.713467] client_op_state_get_machine 400 [D 16:57:53.713493] [SM Locating]: (0x10100700) located: sysdev_unexp_sm:post [D 16:57:53.713517] PINT_client_state_machine_post smcb 0x10100700, op: PVFS_DEV_UNEXPECTED [D 16:57:53.713540] [SM Entering]: (0x10100700) sysdev_unexp_sm:post (status: 0) [D 16:57:53.713568] [SM Exiting]: (0x10100700) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.713594] Posted PVFS_DEV_UNEXPECTED (62) (waiting for test)(-1073741839) [D 16:57:53.713622] PINT_sys_dev_unexp [D 16:57:53.713644] [SM Frame PUSH]: (0x101025f0) frame: 0x101026b0 [D 16:57:53.713668] [SM Locating]: (0x101025f0) op-id: 400 [D 16:57:53.713691] client_op_state_get_machine 400 [D 16:57:53.713714] [SM Locating]: (0x101025f0) located: sysdev_unexp_sm:post [D 16:57:53.713738] PINT_client_state_machine_post smcb 0x101025f0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.713761] [SM Entering]: (0x101025f0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.713791] [SM Exiting]: (0x101025f0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.713817] Posted PVFS_DEV_UNEXPECTED (64) (waiting for test)(-1073741839) [D 16:57:53.713844] PINT_sys_dev_unexp [D 16:57:53.713868] [SM Frame PUSH]: (0x101044e0) frame: 0x101045a0 [D 16:57:53.713891] [SM Locating]: (0x101044e0) op-id: 400 [D 16:57:53.713914] client_op_state_get_machine 400 [D 16:57:53.713937] [SM Locating]: (0x101044e0) located: sysdev_unexp_sm:post [D 16:57:53.713960] PINT_client_state_machine_post smcb 0x101044e0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.713984] [SM Entering]: (0x101044e0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.714012] [SM Exiting]: (0x101044e0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.714037] Posted PVFS_DEV_UNEXPECTED (66) (waiting for test)(-1073741839) [D 16:57:53.714066] PINT_sys_dev_unexp [D 16:57:53.714090] [SM Frame PUSH]: (0x101063d0) frame: 0x10106490 [D 16:57:53.714114] [SM Locating]: (0x101063d0) op-id: 400 [D 16:57:53.714137] client_op_state_get_machine 400 [D 16:57:53.714159] [SM Locating]: (0x101063d0) located: sysdev_unexp_sm:post [D 16:57:53.714183] PINT_client_state_machine_post smcb 0x101063d0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.714207] [SM Entering]: (0x101063d0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.714232] [SM Exiting]: (0x101063d0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.714257] Posted PVFS_DEV_UNEXPECTED (68) (waiting for test)(-1073741839) [D 16:57:53.714285] PINT_sys_dev_unexp [D 16:57:53.714309] [SM Frame PUSH]: (0x101082c0) frame: 0x10108380 [D 16:57:53.714333] [SM Locating]: (0x101082c0) op-id: 400 [D 16:57:53.714356] client_op_state_get_machine 400 [D 16:57:53.714379] [SM Locating]: (0x101082c0) located: sysdev_unexp_sm:post [D 16:57:53.714403] PINT_client_state_machine_post smcb 0x101082c0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.714426] [SM Entering]: (0x101082c0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.714450] [SM Exiting]: (0x101082c0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.714475] Posted PVFS_DEV_UNEXPECTED (70) (waiting for test)(-1073741839) [D 16:57:53.714505] PINT_sys_dev_unexp [D 16:57:53.714529] [SM Frame PUSH]: (0x1010a1b0) frame: 0x1010a270 [D 16:57:53.714552] [SM Locating]: (0x1010a1b0) op-id: 400 [D 16:57:53.714575] client_op_state_get_machine 400 [D 16:57:53.714598] [SM Locating]: (0x1010a1b0) located: sysdev_unexp_sm:post [D 16:57:53.714622] PINT_client_state_machine_post smcb 0x1010a1b0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.714645] [SM Entering]: (0x1010a1b0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.714671] [SM Exiting]: (0x1010a1b0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.714695] Posted PVFS_DEV_UNEXPECTED (72) (waiting for test)(-1073741839) [D 16:57:53.714724] PINT_sys_dev_unexp [D 16:57:53.714748] [SM Frame PUSH]: (0x1010c0a0) frame: 0x1010c160 [D 16:57:53.714772] [SM Locating]: (0x1010c0a0) op-id: 400 [D 16:57:53.714795] client_op_state_get_machine 400 [D 16:57:53.714818] [SM Locating]: (0x1010c0a0) located: sysdev_unexp_sm:post [D 16:57:53.714841] PINT_client_state_machine_post smcb 0x1010c0a0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.714864] [SM Entering]: (0x1010c0a0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.714890] [SM Exiting]: (0x1010c0a0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.714915] Posted PVFS_DEV_UNEXPECTED (74) (waiting for test)(-1073741839) [D 16:57:53.714942] PINT_sys_dev_unexp [D 16:57:53.714969] [SM Frame PUSH]: (0x1010df90) frame: 0x1010e050 [D 16:57:53.714993] [SM Locating]: (0x1010df90) op-id: 400 [D 16:57:53.715016] client_op_state_get_machine 400 [D 16:57:53.715039] [SM Locating]: (0x1010df90) located: sysdev_unexp_sm:post [D 16:57:53.715063] PINT_client_state_machine_post smcb 0x1010df90, op: PVFS_DEV_UNEXPECTED [D 16:57:53.715085] [SM Entering]: (0x1010df90) sysdev_unexp_sm:post (status: 0) [D 16:57:53.715110] [SM Exiting]: (0x1010df90) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.715135] Posted PVFS_DEV_UNEXPECTED (76) (waiting for test)(-1073741839) [D 16:57:53.715163] PINT_sys_dev_unexp [D 16:57:53.715189] [SM Frame PUSH]: (0x1010fe80) frame: 0x1010ff40 [D 16:57:53.715213] [SM Locating]: (0x1010fe80) op-id: 400 [D 16:57:53.715237] client_op_state_get_machine 400 [D 16:57:53.715259] [SM Locating]: (0x1010fe80) located: sysdev_unexp_sm:post [D 16:57:53.715283] PINT_client_state_machine_post smcb 0x1010fe80, op: PVFS_DEV_UNEXPECTED [D 16:57:53.715307] [SM Entering]: (0x1010fe80) sysdev_unexp_sm:post (status: 0) [D 16:57:53.715332] [SM Exiting]: (0x1010fe80) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.715356] Posted PVFS_DEV_UNEXPECTED (78) (waiting for test)(-1073741839) [D 16:57:53.715392] PINT_sys_dev_unexp [D 16:57:53.715420] [SM Frame PUSH]: (0x10111d70) frame: 0x10111e30 [D 16:57:53.715444] [SM Locating]: (0x10111d70) op-id: 400 [D 16:57:53.715467] client_op_state_get_machine 400 [D 16:57:53.715490] [SM Locating]: (0x10111d70) located: sysdev_unexp_sm:post [D 16:57:53.715514] PINT_client_state_machine_post smcb 0x10111d70, op: PVFS_DEV_UNEXPECTED [D 16:57:53.715537] [SM Entering]: (0x10111d70) sysdev_unexp_sm:post (status: 0) [D 16:57:53.715561] [SM Exiting]: (0x10111d70) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.715587] Posted PVFS_DEV_UNEXPECTED (80) (waiting for test)(-1073741839) [D 16:57:53.715614] PINT_sys_dev_unexp [D 16:57:53.715641] [SM Frame PUSH]: (0x10113c60) frame: 0x10113d20 [D 16:57:53.715664] [SM Locating]: (0x10113c60) op-id: 400 [D 16:57:53.715687] client_op_state_get_machine 400 [D 16:57:53.715710] [SM Locating]: (0x10113c60) located: sysdev_unexp_sm:post [D 16:57:53.715734] PINT_client_state_machine_post smcb 0x10113c60, op: PVFS_DEV_UNEXPECTED [D 16:57:53.715757] [SM Entering]: (0x10113c60) sysdev_unexp_sm:post (status: 0) [D 16:57:53.715783] [SM Exiting]: (0x10113c60) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.715807] Posted PVFS_DEV_UNEXPECTED (82) (waiting for test)(-1073741839) [D 16:57:53.715835] PINT_sys_dev_unexp [D 16:57:53.715861] [SM Frame PUSH]: (0x10115b50) frame: 0x10115c10 [D 16:57:53.715885] [SM Locating]: (0x10115b50) op-id: 400 [D 16:57:53.715909] client_op_state_get_machine 400 [D 16:57:53.715931] [SM Locating]: (0x10115b50) located: sysdev_unexp_sm:post [D 16:57:53.715954] PINT_client_state_machine_post smcb 0x10115b50, op: PVFS_DEV_UNEXPECTED [D 16:57:53.715978] [SM Entering]: (0x10115b50) sysdev_unexp_sm:post (status: 0) [D 16:57:53.716003] [SM Exiting]: (0x10115b50) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.716028] Posted PVFS_DEV_UNEXPECTED (84) (waiting for test)(-1073741839) [D 16:57:53.716055] PINT_sys_dev_unexp [D 16:57:53.716082] [SM Frame PUSH]: (0x10117a40) frame: 0x10117b00 [D 16:57:53.716106] [SM Locating]: (0x10117a40) op-id: 400 [D 16:57:53.716129] client_op_state_get_machine 400 [D 16:57:53.716152] [SM Locating]: (0x10117a40) located: sysdev_unexp_sm:post [D 16:57:53.716175] PINT_client_state_machine_post smcb 0x10117a40, op: PVFS_DEV_UNEXPECTED [D 16:57:53.716198] [SM Entering]: (0x10117a40) sysdev_unexp_sm:post (status: 0) [D 16:57:53.716223] [SM Exiting]: (0x10117a40) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.716248] Posted PVFS_DEV_UNEXPECTED (86) (waiting for test)(-1073741839) [D 16:57:53.716276] PINT_sys_dev_unexp [D 16:57:53.716303] [SM Frame PUSH]: (0x10119930) frame: 0x101199f0 [D 16:57:53.716328] [SM Locating]: (0x10119930) op-id: 400 [D 16:57:53.716351] client_op_state_get_machine 400 [D 16:57:53.716374] [SM Locating]: (0x10119930) located: sysdev_unexp_sm:post [D 16:57:53.716397] PINT_client_state_machine_post smcb 0x10119930, op: PVFS_DEV_UNEXPECTED [D 16:57:53.716421] [SM Entering]: (0x10119930) sysdev_unexp_sm:post (status: 0) [D 16:57:53.716445] [SM Exiting]: (0x10119930) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.716470] Posted PVFS_DEV_UNEXPECTED (88) (waiting for test)(-1073741839) [D 16:57:53.716498] PINT_sys_dev_unexp [D 16:57:53.716525] [SM Frame PUSH]: (0x1011b820) frame: 0x1011b8e0 [D 16:57:53.716548] [SM Locating]: (0x1011b820) op-id: 400 [D 16:57:53.716571] client_op_state_get_machine 400 [D 16:57:53.716594] [SM Locating]: (0x1011b820) located: sysdev_unexp_sm:post [D 16:57:53.716618] PINT_client_state_machine_post smcb 0x1011b820, op: PVFS_DEV_UNEXPECTED [D 16:57:53.716641] [SM Entering]: (0x1011b820) sysdev_unexp_sm:post (status: 0) [D 16:57:53.716666] [SM Exiting]: (0x1011b820) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.716691] Posted PVFS_DEV_UNEXPECTED (90) (waiting for test)(-1073741839) [D 16:57:53.716718] PINT_sys_dev_unexp [D 16:57:53.716742] [SM Frame PUSH]: (0x1011d710) frame: 0x1011d7d0 [D 16:57:53.716769] [SM Locating]: (0x1011d710) op-id: 400 [D 16:57:53.716794] client_op_state_get_machine 400 [D 16:57:53.716816] [SM Locating]: (0x1011d710) located: sysdev_unexp_sm:post [D 16:57:53.716840] PINT_client_state_machine_post smcb 0x1011d710, op: PVFS_DEV_UNEXPECTED [D 16:57:53.716864] [SM Entering]: (0x1011d710) sysdev_unexp_sm:post (status: 0) [D 16:57:53.716890] [SM Exiting]: (0x1011d710) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.716915] Posted PVFS_DEV_UNEXPECTED (92) (waiting for test)(-1073741839) [D 16:57:53.716944] PINT_sys_dev_unexp [D 16:57:53.716968] [SM Frame PUSH]: (0x1011f600) frame: 0x1011f6c0 [D 16:57:53.716992] [SM Locating]: (0x1011f600) op-id: 400 [D 16:57:53.717015] client_op_state_get_machine 400 [D 16:57:53.717038] [SM Locating]: (0x1011f600) located: sysdev_unexp_sm:post [D 16:57:53.717061] PINT_client_state_machine_post smcb 0x1011f600, op: PVFS_DEV_UNEXPECTED [D 16:57:53.717084] [SM Entering]: (0x1011f600) sysdev_unexp_sm:post (status: 0) [D 16:57:53.717113] [SM Exiting]: (0x1011f600) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.717138] Posted PVFS_DEV_UNEXPECTED (94) (waiting for test)(-1073741839) [D 16:57:53.717165] PINT_sys_dev_unexp [D 16:57:53.717189] [SM Frame PUSH]: (0x101214f0) frame: 0x101215b0 [D 16:57:53.717213] [SM Locating]: (0x101214f0) op-id: 400 [D 16:57:53.717236] client_op_state_get_machine 400 [D 16:57:53.717259] [SM Locating]: (0x101214f0) located: sysdev_unexp_sm:post [D 16:57:53.717282] PINT_client_state_machine_post smcb 0x101214f0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.717306] [SM Entering]: (0x101214f0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.717330] [SM Exiting]: (0x101214f0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.717355] Posted PVFS_DEV_UNEXPECTED (96) (waiting for test)(-1073741839) [D 16:57:53.717388] PINT_sys_dev_unexp [D 16:57:53.717415] [SM Frame PUSH]: (0x101233e0) frame: 0x101234a0 [D 16:57:53.717441] [SM Locating]: (0x101233e0) op-id: 400 [D 16:57:53.717467] client_op_state_get_machine 400 [D 16:57:53.717493] [SM Locating]: (0x101233e0) located: sysdev_unexp_sm:post [D 16:57:53.717516] PINT_client_state_machine_post smcb 0x101233e0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.717540] [SM Entering]: (0x101233e0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.717565] [SM Exiting]: (0x101233e0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.717590] Posted PVFS_DEV_UNEXPECTED (98) (waiting for test)(-1073741839) [D 16:57:53.717619] PINT_sys_dev_unexp [D 16:57:53.717643] [SM Frame PUSH]: (0x101252d0) frame: 0x10125390 [D 16:57:53.717667] [SM Locating]: (0x101252d0) op-id: 400 [D 16:57:53.717693] client_op_state_get_machine 400 [D 16:57:53.717716] [SM Locating]: (0x101252d0) located: sysdev_unexp_sm:post [D 16:57:53.717739] PINT_client_state_machine_post smcb 0x101252d0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.717762] [SM Entering]: (0x101252d0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.717787] [SM Exiting]: (0x101252d0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.717812] Posted PVFS_DEV_UNEXPECTED (100) (waiting for test)(-1073741839) [D 16:57:53.717842] PINT_sys_dev_unexp [D 16:57:53.717865] [SM Frame PUSH]: (0x101271c0) frame: 0x10127280 [D 16:57:53.717889] [SM Locating]: (0x101271c0) op-id: 400 [D 16:57:53.717912] client_op_state_get_machine 400 [D 16:57:53.717935] [SM Locating]: (0x101271c0) located: sysdev_unexp_sm:post [D 16:57:53.717958] PINT_client_state_machine_post smcb 0x101271c0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.717982] [SM Entering]: (0x101271c0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.718007] [SM Exiting]: (0x101271c0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.718031] Posted PVFS_DEV_UNEXPECTED (102) (waiting for test)(-1073741839) [D 16:57:53.718061] PINT_sys_dev_unexp [D 16:57:53.718085] [SM Frame PUSH]: (0x101290b0) frame: 0x10129170 [D 16:57:53.718109] [SM Locating]: (0x101290b0) op-id: 400 [D 16:57:53.718132] client_op_state_get_machine 400 [D 16:57:53.718154] [SM Locating]: (0x101290b0) located: sysdev_unexp_sm:post [D 16:57:53.718180] PINT_client_state_machine_post smcb 0x101290b0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.718204] [SM Entering]: (0x101290b0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.718230] [SM Exiting]: (0x101290b0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.718254] Posted PVFS_DEV_UNEXPECTED (104) (waiting for test)(-1073741839) [D 16:57:53.718281] PINT_sys_dev_unexp [D 16:57:53.718308] [SM Frame PUSH]: (0x1012afa0) frame: 0x1012b060 [D 16:57:53.718332] [SM Locating]: (0x1012afa0) op-id: 400 [D 16:57:53.718355] client_op_state_get_machine 400 [D 16:57:53.718378] [SM Locating]: (0x1012afa0) located: sysdev_unexp_sm:post [D 16:57:53.718401] PINT_client_state_machine_post smcb 0x1012afa0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.718425] [SM Entering]: (0x1012afa0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.718450] [SM Exiting]: (0x1012afa0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.718475] Posted PVFS_DEV_UNEXPECTED (106) (waiting for test)(-1073741839) [D 16:57:53.718502] PINT_sys_dev_unexp [D 16:57:53.718531] [SM Frame PUSH]: (0x1012ce90) frame: 0x1012cf50 [D 16:57:53.718555] [SM Locating]: (0x1012ce90) op-id: 400 [D 16:57:53.718578] client_op_state_get_machine 400 [D 16:57:53.718601] [SM Locating]: (0x1012ce90) located: sysdev_unexp_sm:post [D 16:57:53.718625] PINT_client_state_machine_post smcb 0x1012ce90, op: PVFS_DEV_UNEXPECTED [D 16:57:53.718647] [SM Entering]: (0x1012ce90) sysdev_unexp_sm:post (status: 0) [D 16:57:53.718673] [SM Exiting]: (0x1012ce90) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.718698] Posted PVFS_DEV_UNEXPECTED (108) (waiting for test)(-1073741839) [D 16:57:53.718726] PINT_sys_dev_unexp [D 16:57:53.718754] [SM Frame PUSH]: (0x1012ed80) frame: 0x1012ee40 [D 16:57:53.718777] [SM Locating]: (0x1012ed80) op-id: 400 [D 16:57:53.718801] client_op_state_get_machine 400 [D 16:57:53.718824] [SM Locating]: (0x1012ed80) located: sysdev_unexp_sm:post [D 16:57:53.718847] PINT_client_state_machine_post smcb 0x1012ed80, op: PVFS_DEV_UNEXPECTED [D 16:57:53.718871] [SM Entering]: (0x1012ed80) sysdev_unexp_sm:post (status: 0) [D 16:57:53.718895] [SM Exiting]: (0x1012ed80) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.718920] Posted PVFS_DEV_UNEXPECTED (110) (waiting for test)(-1073741839) [D 16:57:53.718948] PINT_sys_dev_unexp [D 16:57:53.718975] [SM Frame PUSH]: (0x10130c70) frame: 0x10130d30 [D 16:57:53.718998] [SM Locating]: (0x10130c70) op-id: 400 [D 16:57:53.719021] client_op_state_get_machine 400 [D 16:57:53.719044] [SM Locating]: (0x10130c70) located: sysdev_unexp_sm:post [D 16:57:53.719068] PINT_client_state_machine_post smcb 0x10130c70, op: PVFS_DEV_UNEXPECTED [D 16:57:53.719091] [SM Entering]: (0x10130c70) sysdev_unexp_sm:post (status: 0) [D 16:57:53.719116] [SM Exiting]: (0x10130c70) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.719141] Posted PVFS_DEV_UNEXPECTED (112) (waiting for test)(-1073741839) [D 16:57:53.719169] PINT_sys_dev_unexp [D 16:57:53.719196] [SM Frame PUSH]: (0x10132b60) frame: 0x10132c20 [D 16:57:53.719220] [SM Locating]: (0x10132b60) op-id: 400 [D 16:57:53.719243] client_op_state_get_machine 400 [D 16:57:53.719265] [SM Locating]: (0x10132b60) located: sysdev_unexp_sm:post [D 16:57:53.719288] PINT_client_state_machine_post smcb 0x10132b60, op: PVFS_DEV_UNEXPECTED [D 16:57:53.719312] [SM Entering]: (0x10132b60) sysdev_unexp_sm:post (status: 0) [D 16:57:53.719337] [SM Exiting]: (0x10132b60) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.719363] Posted PVFS_DEV_UNEXPECTED (114) (waiting for test)(-1073741839) [D 16:57:53.719393] PINT_sys_dev_unexp [D 16:57:53.719421] [SM Frame PUSH]: (0x10134a50) frame: 0x10134b10 [D 16:57:53.719445] [SM Locating]: (0x10134a50) op-id: 400 [D 16:57:53.719468] client_op_state_get_machine 400 [D 16:57:53.719491] [SM Locating]: (0x10134a50) located: sysdev_unexp_sm:post [D 16:57:53.719513] PINT_client_state_machine_post smcb 0x10134a50, op: PVFS_DEV_UNEXPECTED [D 16:57:53.719537] [SM Entering]: (0x10134a50) sysdev_unexp_sm:post (status: 0) [D 16:57:53.719565] [SM Exiting]: (0x10134a50) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.719590] Posted PVFS_DEV_UNEXPECTED (116) (waiting for test)(-1073741839) [D 16:57:53.719616] PINT_sys_dev_unexp [D 16:57:53.719644] [SM Frame PUSH]: (0x10136940) frame: 0x10136a00 [D 16:57:53.719668] [SM Locating]: (0x10136940) op-id: 400 [D 16:57:53.719691] client_op_state_get_machine 400 [D 16:57:53.719714] [SM Locating]: (0x10136940) located: sysdev_unexp_sm:post [D 16:57:53.719737] PINT_client_state_machine_post smcb 0x10136940, op: PVFS_DEV_UNEXPECTED [D 16:57:53.719760] [SM Entering]: (0x10136940) sysdev_unexp_sm:post (status: 0) [D 16:57:53.719785] [SM Exiting]: (0x10136940) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.719810] Posted PVFS_DEV_UNEXPECTED (118) (waiting for test)(-1073741839) [D 16:57:53.719838] PINT_sys_dev_unexp [D 16:57:53.719864] [SM Frame PUSH]: (0x10138830) frame: 0x101388f0 [D 16:57:53.719888] [SM Locating]: (0x10138830) op-id: 400 [D 16:57:53.719911] client_op_state_get_machine 400 [D 16:57:53.719934] [SM Locating]: (0x10138830) located: sysdev_unexp_sm:post [D 16:57:53.719958] PINT_client_state_machine_post smcb 0x10138830, op: PVFS_DEV_UNEXPECTED [D 16:57:53.719982] [SM Entering]: (0x10138830) sysdev_unexp_sm:post (status: 0) [D 16:57:53.720006] [SM Exiting]: (0x10138830) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.720031] Posted PVFS_DEV_UNEXPECTED (120) (waiting for test)(-1073741839) [D 16:57:53.720059] PINT_sys_dev_unexp [D 16:57:53.720083] [SM Frame PUSH]: (0x1013a720) frame: 0x1013a7e0 [D 16:57:53.720113] [SM Locating]: (0x1013a720) op-id: 400 [D 16:57:53.720137] client_op_state_get_machine 400 [D 16:57:53.720160] [SM Locating]: (0x1013a720) located: sysdev_unexp_sm:post [D 16:57:53.720184] PINT_client_state_machine_post smcb 0x1013a720, op: PVFS_DEV_UNEXPECTED [D 16:57:53.720207] [SM Entering]: (0x1013a720) sysdev_unexp_sm:post (status: 0) [D 16:57:53.720232] [SM Exiting]: (0x1013a720) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.720257] Posted PVFS_DEV_UNEXPECTED (122) (waiting for test)(-1073741839) [D 16:57:53.720285] PINT_sys_dev_unexp [D 16:57:53.720309] [SM Frame PUSH]: (0x1013c610) frame: 0x1013c6d0 [D 16:57:53.720333] [SM Locating]: (0x1013c610) op-id: 400 [D 16:57:53.720355] client_op_state_get_machine 400 [D 16:57:53.720378] [SM Locating]: (0x1013c610) located: sysdev_unexp_sm:post [D 16:57:53.720401] PINT_client_state_machine_post smcb 0x1013c610, op: PVFS_DEV_UNEXPECTED [D 16:57:53.720425] [SM Entering]: (0x1013c610) sysdev_unexp_sm:post (status: 0) [D 16:57:53.720453] [SM Exiting]: (0x1013c610) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.720479] Posted PVFS_DEV_UNEXPECTED (124) (waiting for test)(-1073741839) [D 16:57:53.720505] PINT_sys_dev_unexp [D 16:57:53.720529] [SM Frame PUSH]: (0x1013e500) frame: 0x1013e5c0 [D 16:57:53.720553] [SM Locating]: (0x1013e500) op-id: 400 [D 16:57:53.720576] client_op_state_get_machine 400 [D 16:57:53.720599] [SM Locating]: (0x1013e500) located: sysdev_unexp_sm:post [D 16:57:53.720622] PINT_client_state_machine_post smcb 0x1013e500, op: PVFS_DEV_UNEXPECTED [D 16:57:53.720645] [SM Entering]: (0x1013e500) sysdev_unexp_sm:post (status: 0) [D 16:57:53.720670] [SM Exiting]: (0x1013e500) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.720695] Posted PVFS_DEV_UNEXPECTED (126) (waiting for test)(-1073741839) [D 16:57:53.720726] PINT_sys_dev_unexp [D 16:57:53.720749] [SM Frame PUSH]: (0x101403f0) frame: 0x101404b0 [D 16:57:53.720772] [SM Locating]: (0x101403f0) op-id: 400 [D 16:57:53.720796] client_op_state_get_machine 400 [D 16:57:53.720819] [SM Locating]: (0x101403f0) located: sysdev_unexp_sm:post [D 16:57:53.720842] PINT_client_state_machine_post smcb 0x101403f0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.720866] [SM Entering]: (0x101403f0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.720890] [SM Exiting]: (0x101403f0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.720918] Posted PVFS_DEV_UNEXPECTED (128) (waiting for test)(-1073741839) [D 16:57:53.720949] PINT_sys_dev_unexp [D 16:57:53.720973] [SM Frame PUSH]: (0x101422e0) frame: 0x101423a0 [D 16:57:53.720995] [SM Locating]: (0x101422e0) op-id: 400 [D 16:57:53.721018] client_op_state_get_machine 400 [D 16:57:53.721041] [SM Locating]: (0x101422e0) located: sysdev_unexp_sm:post [D 16:57:53.721065] PINT_client_state_machine_post smcb 0x101422e0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.721088] [SM Entering]: (0x101422e0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.721114] [SM Exiting]: (0x101422e0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.721138] Posted PVFS_DEV_UNEXPECTED (130) (waiting for test)(-1073741839) [D 16:57:53.721168] PINT_sys_dev_unexp [D 16:57:53.721192] [SM Frame PUSH]: (0x101441d0) frame: 0x10144290 [D 16:57:53.721216] [SM Locating]: (0x101441d0) op-id: 400 [D 16:57:53.721239] client_op_state_get_machine 400 [D 16:57:53.721261] [SM Locating]: (0x101441d0) located: sysdev_unexp_sm:post [D 16:57:53.721284] PINT_client_state_machine_post smcb 0x101441d0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.721308] [SM Entering]: (0x101441d0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.721333] [SM Exiting]: (0x101441d0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.721358] Posted PVFS_DEV_UNEXPECTED (132) (waiting for test)(-1073741839) [D 16:57:53.721390] PINT_sys_dev_unexp [D 16:57:53.721418] [SM Frame PUSH]: (0x101460c0) frame: 0x10146180 [D 16:57:53.721444] [SM Locating]: (0x101460c0) op-id: 400 [D 16:57:53.721469] client_op_state_get_machine 400 [D 16:57:53.721495] [SM Locating]: (0x101460c0) located: sysdev_unexp_sm:post [D 16:57:53.721519] PINT_client_state_machine_post smcb 0x101460c0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.721542] [SM Entering]: (0x101460c0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.721568] [SM Exiting]: (0x101460c0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.721592] Posted PVFS_DEV_UNEXPECTED (134) (waiting for test)(-1073741839) [D 16:57:53.721640] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 10 [D 16:57:53.721684] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 1, bytes available: 1 [D 16:57:53.721714] [SM Entering]: (0x100cc3b0) sysdev_unexp_sm:cleanup (status: 0) [D 16:57:53.721739] [SM Exiting]: (0x100cc3b0) sysdev_unexp_sm:cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.721763] client_state_machine_terminate smcb 0x100cc3b0 [D 16:57:53.721786] add smcb 0x100cc3b0 to completion list [D 16:57:53.721810] PINT_sys_release: id 8 [D 16:57:53.721835] PINT_sys_testsome returned unexp vfs_request 0x100caf20, tag: 848 [D 16:57:53.721861] [+] dev req msg: sz: 680,tag: 848,data: 0x10146b30,type: 0 [D 16:57:53.721889] [*] handling new unexp vfs_request 0x100caf20 [D 16:57:53.721913] is_op_in_progress called on tag 848 [D 16:57:53.721940] Got an fs mount request for host: ib://da13:3345/2n-320 [D 16:57:53.721964] Using Mount Point [D 16:57:53.721993] Got Configuration Server: ib://da13:3345 (len=14) [D 16:57:53.722017] Got FS Name: 2n-320 (len=6) [D 16:57:53.722064] BMI_ib_initialize: init. [D 16:57:53.722094] openib_ib_initialize: init. [D 16:57:53.722976] openib_ib_initialize: max 16380 completion queue entries. [D 16:57:53.723282] BMI_ib_initialize: done. [D 16:57:53.723326] [SM Frame PUSH]: (0x100cc660) frame: 0x101479a0 [D 16:57:53.723352] [SM Locating]: (0x100cc660) op-id: 19 [D 16:57:53.723375] client_op_state_get_machine 19 [D 16:57:53.723402] [SM Locating]: (0x100cc660) located: server_get_config_nested_sm:setup_msgpair [D 16:57:53.723434] PINT_client_state_machine_post smcb 0x100cc660, op: PVFS_SYS_FS_ADD [D 16:57:53.723458] [SM Entering]: (0x100cc660) server_get_config_nested_sm:setup_msgpair (status: 0) [D 16:57:53.723483] get_config state: server_get_config_setup_msgpair [D 16:57:53.723506] [SM Exiting]: (0x100cc660) server_get_config_nested_sm:setup_msgpair (error code: 0), (action: COMPLETE) [D 16:57:53.723531] [SM Entering]: (0x100cc660) msgpairarray_sm:init (status: 0) [D 16:57:53.723562] (0x100cc660) msgpairarray state: init (1 msgpair(s)) [D 16:57:53.723587] [SM Exiting]: (0x100cc660) msgpairarray_sm:init (error code: 0), (action: COMPLETE) [D 16:57:53.723610] [SM Entering]: (0x100cc660) msgpairarray_sm:post (status: 0) [D 16:57:53.723637] msgpairarray_post: sm 0x100cc660 2 total message(s) with 2 incomplete [D 16:57:53.723662] PINT_encode [D 16:57:53.723685] encode_common [D 16:57:53.723711] lebf_encode_req [D 16:57:53.723735] PINT_encode_calc_max_size [D 16:57:53.723800] msgpairarray_post: sm 0x100cc660 msgpair 0: posting recv [D 16:57:53.723827] BMI_post_recv: addr: 269273120, offset: 0x101482e0, size: 16416, tag: 1 [E 16:57:53.725006] Warning: openib_new_connection: asked for 70 send WRs on QP, got 0. [D 16:57:53.725671] post_recv: new rq 0x1014e100. [D 16:57:53.725718] memcache_register: hit [0] 0x101482e0 len 16416 (via 0x101482e0 len 16416) refcnt now 2. [D 16:57:53.725755] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.725785] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.725810] msgpairarray_post: sm 0x100cc660 msgpair 0: posting send [D 16:57:53.725836] BMI_post_sendunexpected_list: addr: 269273120, count: 1, total_size: 24, tag: 1 [D 16:57:53.725861] element 0: offset: 0x101482c0, size: 24 [D 16:57:53.725888] post_send: sq 0x1014e3c0 len 24 peer da13:3345. [D 16:57:53.725920] encourage_send_waiting_buffer: sq 0x1014e3c0 sent EAGER len 24. [D 16:57:53.725949] [SM Exiting]: (0x100cc660) msgpairarray_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.725978] Posted PVFS_SYS_FS_ADD (137) (waiting for test)(-1073741839) [D 16:57:53.726037] ib_check_cq: send to da13:3345 completed locally: sq 0x1014e3c0 -> SQ_WAITING_USER_TEST. [D 16:57:53.726062] ib_check_cq: recv from da13:3345 len 1536 type MSG_EAGER_SEND credit 1. [D 16:57:53.726087] encourage_recv_incoming: recv eager len 1536. [D 16:57:53.726112] encourage_recv_incoming: matched rq 0x1014e100 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.726136] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.726159] memcache_deregister: dec refcount [0] 0x101482e0 len 16416 (via 0x101482e0 len 16416) refcnt now 1. [D 16:57:53.726184] test_sq: sq 0x1014e3c0 completed 24 to da13:3345. [D 16:57:53.726208] test_rq: rq 0x1014e100 completed 1520 from da13:3345. [D 16:57:53.726233] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.726260] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.726286] [SM Entering]: (0x100cc660) msgpairarray_sm:complete (status: 1) [D 16:57:53.726310] msgpairarray_complete: sm 0x100cc660 status_user_tag 1 msgarray_count 1 [D 16:57:53.726334] msgpairarray: 1 operations remain [D 16:57:53.726357] [SM Exiting]: (0x100cc660) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.726381] [SM Entering]: (0x100cc660) msgpairarray_sm:complete (status: 0) [D 16:57:53.726405] msgpairarray_complete: sm 0x100cc660 status_user_tag 0 msgarray_count 1 [D 16:57:53.726428] msgpairarray: all operations complete [D 16:57:53.726450] [SM Exiting]: (0x100cc660) msgpairarray_sm:complete (error code: 190), (action: COMPLETE) [D 16:57:53.726474] [SM Entering]: (0x100cc660) msgpairarray_sm:completion_fn (status: 0) [D 16:57:53.726498] (0x100cc660) msgpairarray state: completion_fn [D 16:57:53.726522] PINT_decode [D 16:57:53.726552] lebf_decode_resp [D 16:57:53.726577] PINT_encode_release [D 16:57:53.726600] lebf_encode_rel [D 16:57:53.726623] PINT_decode_release [D 16:57:53.726646] lebf_decode_rel [D 16:57:53.726669] msgpairarray_completion_fn: sm 0x100cc660 msgpair 0 marked complete [D 16:57:53.726693] [SM Exiting]: (0x100cc660) msgpairarray_sm:completion_fn (error code: 0), (action: COMPLETE) [D 16:57:53.726717] [SM Entering]: (0x100cc660) server_get_config_nested_sm:parse (status: 0) [D 16:57:53.727265] [SM Exiting]: (0x100cc660) server_get_config_nested_sm:parse (error code: 0), (action: COMPLETE) [D 16:57:53.727291] [SM Entering]: (0x100cc660) server_get_config_nested_sm:cleanup (status: 0) [D 16:57:53.727317] [SM Exiting]: (0x100cc660) server_get_config_nested_sm:cleanup (error code: 0), (action: COMPLETE) [D 16:57:53.727342] [SM Entering]: (0x100cc660) fs_add_sm:parent_cleanup (status: 0) [D 16:57:53.727366] [BMI CONTROL]: BMI_set_info: set_info: 0 option: 11 [D 16:57:53.727391] [BMI CONTROL]: BMI_set_info: set_info: 0 option: 12 [D 16:57:53.727430] * Adding new dynamic mount point [7,0] [D 16:57:53.727458] PINT_server_config_mgr_add_config: adding config 0x101481b0 [D 16:57:53.727483] mapped fs_id 1334155764 => config 0x101481b0 [D 16:57:53.727515] Set min handle recycle time to 360 seconds [D 16:57:53.727538] Reloading handle mappings for fs_id 1334155764 [D 16:57:53.727566] [SM Exiting]: (0x100cc660) fs_add_sm:parent_cleanup (error code: 1), (action: COMPLETE) [D 16:57:53.727591] [SM Entering]: (0x100cc660) fs_add_sm:final_cleanup (status: 0) [D 16:57:53.727615] [SM Exiting]: (0x100cc660) fs_add_sm:final_cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.727639] client_state_machine_terminate smcb 0x100cc660 [D 16:57:53.727662] add smcb 0x100cc660 to completion list [D 16:57:53.727685] PINT_sys_release: id 137 [D 16:57:53.727716] PVFS2_VFS_OP_FS_MOUNT complete (vfs_request 0x100caf20) wtime = 0.005775, utime=0.001629, stime=0.004062 (seconds) [D 16:57:53.727757] PINT_sys_testsome returned completed vfs_request 0x100caf20 [D 16:57:53.727784] [BMI CONTROL]: BMI_set_info: set_info: 269273120 option: 8 [D 16:57:53.727807] [BMI CONTROL]: BMI_set_info: searching for ref 269273120 [D 16:57:53.727831] BMI forceful cancel mode enabled [D 16:57:53.727855] FS mount got root handle 1048576 on fs id 1334155764 [D 16:57:53.727884] write_device_response: writing device response. tag: 848 [D 16:57:53.727921] downcall write returned 1 [D 16:57:53.727945] PINT_sys_release: id 137 [D 16:57:53.727970] PINT_sys_dev_unexp [D 16:57:53.727993] [SM Frame PUSH]: (0x100cc660) frame: 0x101479a0 [D 16:57:53.728016] [SM Locating]: (0x100cc660) op-id: 400 [D 16:57:53.728040] client_op_state_get_machine 400 [D 16:57:53.728063] [SM Locating]: (0x100cc660) located: sysdev_unexp_sm:post [D 16:57:53.728086] PINT_client_state_machine_post smcb 0x100cc660, op: PVFS_DEV_UNEXPECTED [D 16:57:53.728110] [SM Entering]: (0x100cc660) sysdev_unexp_sm:post (status: 0) [D 16:57:53.728135] [SM Exiting]: (0x100cc660) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.728159] Posted PVFS_DEV_UNEXPECTED (139) (waiting for test)(-1073741839) [D 16:57:53.728183] [-] reposted unexp req [0x100caf20] due to normal_completion [D 16:57:53.728209] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 10 [D 16:57:53.728239] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 1, bytes available: 1 [D 16:57:53.728266] [SM Entering]: (0x100ce2a0) sysdev_unexp_sm:cleanup (status: 0) [D 16:57:53.728289] [SM Exiting]: (0x100ce2a0) sysdev_unexp_sm:cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.728314] client_state_machine_terminate smcb 0x100ce2a0 [D 16:57:53.728336] add smcb 0x100ce2a0 to completion list [D 16:57:53.728360] PINT_sys_release: id 10 [D 16:57:53.728384] PINT_sys_testsome returned unexp vfs_request 0x100cce10, tag: 847 [D 16:57:53.728407] [+] dev req msg: sz: 680,tag: 847,data: 0x1014e510,type: 0 [D 16:57:53.728431] [*] handling new unexp vfs_request 0x100cce10 [D 16:57:53.728454] is_op_in_progress called on tag 847 [D 16:57:53.728479] Got a lookup request for 4g (fsid 1334155764 | parent 1048576) [D 16:57:53.728506] PVFS_isys_ref_lookup entered [D 16:57:53.728533] [SM Frame PUSH]: (0x100cccb0) frame: 0x100ce2a0 [D 16:57:53.728557] [SM Locating]: (0x100cccb0) op-id: 11 [D 16:57:53.728580] client_op_state_get_machine 11 [D 16:57:53.728606] [SM Locating]: (0x100cccb0) located: client_lookup_sm:lookup_segment_start [D 16:57:53.728633] initialize_context called [D 16:57:53.728661] original pathname is: 4g [D 16:57:53.728684] cur_seg_name[0]: 4g [D 16:57:53.728707] pathname is: 4g [D 16:57:53.728730] *seg_remaining is: 4g [D 16:57:53.728755] lookup got: 4g (parent 1048576) [D 16:57:53.728778] PINT_client_state_machine_post smcb 0x100cccb0, op: PVFS_SYS_LOOKUP [D 16:57:53.728802] [SM Entering]: (0x100cccb0) client_lookup_sm:lookup_segment_start (status: 0) [D 16:57:53.728828] lookup_segment_start [D 16:57:53.728851] [SM Exiting]: (0x100cccb0) client_lookup_sm:lookup_segment_start (error code: 0), (action: COMPLETE) [D 16:57:53.728875] [SM Entering]: (0x100cccb0) client_lookup_sm:lookup_segment_query_ncache (status: 0) [D 16:57:53.728899] lookup_segment_query_ncache: segment [4g] [D 16:57:53.728921] ncache: get_cached_entry(): [4g] [D 16:57:53.728945] ncache: miss: name=[4g] [D 16:57:53.728968] *** ncache clean miss on first segment of 4g [D 16:57:53.728991] [SM Exiting]: (0x100cccb0) client_lookup_sm:lookup_segment_query_ncache (error code: 1), (action: COMPLETE) [D 16:57:53.729015] [SM Entering]: (0x100cccb0) client_lookup_sm:lookup_segment_setup_msgpair (status: 0) [D 16:57:53.729039] lookup_segment_setup_msgpair [D 16:57:53.729062] Looking up segment 4g under handle 1048576 [D 16:57:53.729086] [SM Exiting]: (0x100cccb0) client_lookup_sm:lookup_segment_setup_msgpair (error code: 0), (action: COMPLETE) [D 16:57:53.729110] [SM Entering]: (0x100cccb0) msgpairarray_sm:init (status: 0) [D 16:57:53.729134] (0x100cccb0) msgpairarray state: init (1 msgpair(s)) [D 16:57:53.729157] [SM Exiting]: (0x100cccb0) msgpairarray_sm:init (error code: 0), (action: COMPLETE) [D 16:57:53.729181] [SM Entering]: (0x100cccb0) msgpairarray_sm:post (status: 0) [D 16:57:53.729205] msgpairarray_post: sm 0x100cccb0 2 total message(s) with 2 incomplete [D 16:57:53.729228] PINT_encode [D 16:57:53.729252] encode_common [D 16:57:53.729275] lebf_encode_req [D 16:57:53.729298] PINT_encode_calc_max_size [D 16:57:53.729361] msgpairarray_post: sm 0x100cccb0 msgpair 0: posting recv [D 16:57:53.729387] BMI_post_recv: addr: 269273120, offset: 0x101527e0, size: 8224, tag: 2 [D 16:57:53.729413] post_recv: new rq 0x100cebe0. [D 16:57:53.729436] memcache_register: hit [0] 0x101527e0 len 8224 (via 0x101527e0 len 8224) refcnt now 2. [D 16:57:53.729464] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.729490] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.729515] msgpairarray_post: sm 0x100cccb0 msgpair 0: posting send [D 16:57:53.729539] BMI_post_sendunexpected_list: addr: 269273120, count: 1, total_size: 52, tag: 2 [D 16:57:53.729563] element 0: offset: 0x10146c50, size: 52 [D 16:57:53.729587] post_send: sq 0x100cec70 len 52 peer da13:3345. [D 16:57:53.729613] encourage_send_waiting_buffer: sq 0x100cec70 sent EAGER len 52. [D 16:57:53.729638] [SM Exiting]: (0x100cccb0) msgpairarray_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.729662] Posted PVFS_SYS_LOOKUP (142) (waiting for test)(-1073741839) [D 16:57:53.729690] ib_check_cq: send to da13:3345 completed locally: sq 0x100cec70 -> SQ_WAITING_USER_TEST. [D 16:57:53.729718] ib_check_cq: recv from da13:3345 len 104 type MSG_EAGER_SEND credit 1. [D 16:57:53.729742] encourage_recv_incoming: recv eager len 104. [D 16:57:53.729765] encourage_recv_incoming: matched rq 0x100cebe0 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.729788] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.729811] memcache_deregister: dec refcount [0] 0x101527e0 len 8224 (via 0x101527e0 len 8224) refcnt now 1. [D 16:57:53.729837] test_sq: sq 0x100cec70 completed 52 to da13:3345. [D 16:57:53.729860] test_rq: rq 0x100cebe0 completed 88 from da13:3345. [D 16:57:53.729888] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.729916] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.729946] [SM Entering]: (0x100cccb0) msgpairarray_sm:complete (status: 1) [D 16:57:53.729971] msgpairarray_complete: sm 0x100cccb0 status_user_tag 1 msgarray_count 1 [D 16:57:53.729998] msgpairarray: 1 operations remain [D 16:57:53.730021] [SM Exiting]: (0x100cccb0) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.730047] [SM Entering]: (0x100cccb0) msgpairarray_sm:complete (status: 0) [D 16:57:53.730071] msgpairarray_complete: sm 0x100cccb0 status_user_tag 0 msgarray_count 1 [D 16:57:53.730094] msgpairarray: all operations complete [D 16:57:53.730116] [SM Exiting]: (0x100cccb0) msgpairarray_sm:complete (error code: 190), (action: COMPLETE) [D 16:57:53.730140] [SM Entering]: (0x100cccb0) msgpairarray_sm:completion_fn (status: 0) [D 16:57:53.730164] (0x100cccb0) msgpairarray state: completion_fn [D 16:57:53.730187] PINT_decode [D 16:57:53.730209] lebf_decode_resp [D 16:57:53.730237] lookup_segment_lookup_comp_fn [D 16:57:53.730259] - Resolved 1 segments [D 16:57:53.730281] *** ncache update on 4g target (1431655764|1334155764) parent (1048576|1334155764) [D 16:57:53.730306] ncache: update(): name [4g] [D 16:57:53.730332] ncache: update(): return=0 [D 16:57:53.730355] PINT_encode_release [D 16:57:53.730377] lebf_encode_rel [D 16:57:53.730400] PINT_decode_release [D 16:57:53.730422] lebf_decode_rel [D 16:57:53.730445] msgpairarray_completion_fn: sm 0x100cccb0 msgpair 0 marked complete [D 16:57:53.730468] [SM Exiting]: (0x100cccb0) msgpairarray_sm:completion_fn (error code: 0), (action: COMPLETE) [D 16:57:53.730492] [SM Entering]: (0x100cccb0) client_lookup_sm:lookup_segment_verify_attr_present (status: 0) [D 16:57:53.730516] lookup state: lookup_segment_verify_attr_present [D 16:57:53.730539] -- we have the attrs for 4g [D 16:57:53.730562] [SM Exiting]: (0x100cccb0) client_lookup_sm:lookup_segment_verify_attr_present (error code: 0), (action: COMPLETE) [D 16:57:53.730586] [SM Entering]: (0x100cccb0) client_lookup_sm:lookup_segment_check_attr_type (status: 0) [D 16:57:53.730609] lookup state: lookup_segment_check_attr_type [D 16:57:53.730631] [SM Exiting]: (0x100cccb0) client_lookup_sm:lookup_segment_check_attr_type (error code: 4), (action: COMPLETE) [D 16:57:53.730655] [SM Entering]: (0x100cccb0) client_lookup_sm:lookup_context_check_completion (status: 0) [D 16:57:53.730679] lookup state: lookup_context_check_completion [D 16:57:53.730702] [SM Exiting]: (0x100cccb0) client_lookup_sm:lookup_context_check_completion (error code: 0), (action: COMPLETE) [D 16:57:53.730726] [SM Entering]: (0x100cccb0) client_lookup_sm:lookup_cleanup (status: 0) [D 16:57:53.730750] lookup state: lookup_cleanup [D 16:57:53.730772] Freeing segment 4g [D 16:57:53.730794] Freeing remaining segment 4g [D 16:57:53.730818] All contexts finalized [D 16:57:53.730840] Lookup resolved segment 4g to 1431655764 [D 16:57:53.730863] [SM Exiting]: (0x100cccb0) client_lookup_sm:lookup_cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.730887] client_state_machine_terminate smcb 0x100cccb0 [D 16:57:53.730910] add smcb 0x100cccb0 to completion list [D 16:57:53.730933] PINT_sys_release: id 142 [D 16:57:53.730959] PVFS2_VFS_OP_LOOKUP complete (vfs_request 0x100cce10) wtime = 0.002480, utime=0.000000, stime=0.000000 (seconds) [D 16:57:53.730986] PINT_sys_testsome returned completed vfs_request 0x100cce10 [D 16:57:53.731010] write_device_response: writing device response. tag: 847 [D 16:57:53.731040] downcall write returned 1 [D 16:57:53.731063] PINT_sys_release: id 142 [D 16:57:53.731086] PINT_sys_dev_unexp [D 16:57:53.731110] [SM Frame PUSH]: (0x100cccb0) frame: 0x100ce2a0 [D 16:57:53.731134] [SM Locating]: (0x100cccb0) op-id: 400 [D 16:57:53.731157] client_op_state_get_machine 400 [D 16:57:53.731179] [SM Locating]: (0x100cccb0) located: sysdev_unexp_sm:post [D 16:57:53.731203] PINT_client_state_machine_post smcb 0x100cccb0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.731225] [SM Entering]: (0x100cccb0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.731251] [SM Exiting]: (0x100cccb0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.731276] Posted PVFS_DEV_UNEXPECTED (144) (waiting for test)(-1073741839) [D 16:57:53.731300] [-] reposted unexp req [0x100cce10] due to normal_completion [D 16:57:53.731326] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 10 [D 16:57:53.731353] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 1, bytes available: 1 [D 16:57:53.731384] [SM Entering]: (0x100d0190) sysdev_unexp_sm:cleanup (status: 0) [D 16:57:53.731408] [SM Exiting]: (0x100d0190) sysdev_unexp_sm:cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.731431] client_state_machine_terminate smcb 0x100d0190 [D 16:57:53.731454] add smcb 0x100d0190 to completion list [D 16:57:53.731477] PINT_sys_release: id 12 [D 16:57:53.731502] PINT_sys_testsome returned unexp vfs_request 0x100ced00, tag: 849 [D 16:57:53.731526] [+] dev req msg: sz: 680,tag: 849,data: 0x1014e510,type: 0 [D 16:57:53.731550] [*] handling new unexp vfs_request 0x100ced00 [D 16:57:53.731573] is_op_in_progress called on tag 849 [D 16:57:53.731596] got a getattr request for fsid 1334155764 | handle 1431655764 [D 16:57:53.731623] PVFS_isys_getattr entered [D 16:57:53.731648] [SM Frame PUSH]: (0x100d0a90) frame: 0x100d0190 [D 16:57:53.731671] [SM Locating]: (0x100d0a90) op-id: 5 [D 16:57:53.731694] client_op_state_get_machine 5 [D 16:57:53.731717] [SM Locating]: (0x100d0a90) located: client_getattr_sm:acache_lookup [D 16:57:53.731741] attrmask being passed to server: [D 16:57:53.731764] mask = 0xc8c00: [D 16:57:53.731787] PVFS_ATTR_META_DIST [D 16:57:53.731809] PVFS_ATTR_META_DFILES [D 16:57:53.731832] PVFS_ATTR_DATA_SIZE [D 16:57:53.731854] PINT_client_state_machine_post smcb 0x100d0a90, op: PVFS_SYS_GETATTR [D 16:57:53.731877] [SM Entering]: (0x100d0a90) client_getattr_sm:acache_lookup (status: 0) [D 16:57:53.731906] getattr_acache_lookup: handle 1431655764 fsid 1334155764 [D 16:57:53.731931] acache: get_cached_entry(): H=1431655764 [D 16:57:53.731954] acache: miss: H=1431655764 [D 16:57:53.731978] acache: clean acache miss: [1431655764] [D 16:57:53.732001] [SM Exiting]: (0x100d0a90) client_getattr_sm:acache_lookup (error code: 1), (action: COMPLETE) [D 16:57:53.732025] [SM Entering]: (0x100d0a90) client_getattr_sm:object_getattr_setup_msgpair (status: 0) [D 16:57:53.732048] (0x100d0190) getattr_object_getattr_setup_msgpair [D 16:57:53.732073] [SM Exiting]: (0x100d0a90) client_getattr_sm:object_getattr_setup_msgpair (error code: 0), (action: COMPLETE) [D 16:57:53.732097] [SM Entering]: (0x100d0a90) msgpairarray_sm:init (status: 0) [D 16:57:53.732122] (0x100d0a90) msgpairarray state: init (1 msgpair(s)) [D 16:57:53.732146] [SM Exiting]: (0x100d0a90) msgpairarray_sm:init (error code: 0), (action: COMPLETE) [D 16:57:53.732170] [SM Entering]: (0x100d0a90) msgpairarray_sm:post (status: 0) [D 16:57:53.732192] msgpairarray_post: sm 0x100d0a90 2 total message(s) with 2 incomplete [D 16:57:53.732217] PINT_encode [D 16:57:53.732239] encode_common [D 16:57:53.732263] lebf_encode_req [D 16:57:53.732285] PINT_encode_calc_max_size [D 16:57:53.732330] msgpairarray_post: sm 0x100d0a90 msgpair 0: posting recv [D 16:57:53.732356] BMI_post_recv: addr: 269273120, offset: 0x10154810, size: 9280, tag: 3 [D 16:57:53.732381] post_recv: new rq 0x1014e7c0. [D 16:57:53.732405] memcache_register: hit [0] 0x10154810 len 9280 (via 0x10154810 len 9280) refcnt now 2. [D 16:57:53.732433] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.732458] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.732483] msgpairarray_post: sm 0x100d0a90 msgpair 0: posting send [D 16:57:53.732507] BMI_post_sendunexpected_list: addr: 269273120, count: 1, total_size: 40, tag: 3 [D 16:57:53.732531] element 0: offset: 0x1014e450, size: 40 [D 16:57:53.732555] post_send: sq 0x100cebe0 len 40 peer da13:3345. [D 16:57:53.732582] encourage_send_waiting_buffer: sq 0x100cebe0 sent EAGER len 40. [D 16:57:53.732606] [SM Exiting]: (0x100d0a90) msgpairarray_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.732631] Posted PVFS_SYS_GETATTR (147) (waiting for test)(-1073741839) [D 16:57:53.732659] ib_check_cq: send to da13:3345 completed locally: sq 0x100cebe0 -> SQ_WAITING_USER_TEST. [D 16:57:53.732686] ib_check_cq: recv from da13:3345 len 144 type MSG_EAGER_SEND credit 1. [D 16:57:53.732709] encourage_recv_incoming: recv eager len 144. [D 16:57:53.732735] encourage_recv_incoming: matched rq 0x1014e7c0 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.732759] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.732783] memcache_deregister: dec refcount [0] 0x10154810 len 9280 (via 0x10154810 len 9280) refcnt now 1. [D 16:57:53.732808] test_sq: sq 0x100cebe0 completed 40 to da13:3345. [D 16:57:53.732831] test_rq: rq 0x1014e7c0 completed 128 from da13:3345. [D 16:57:53.732856] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.732881] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.732908] [SM Entering]: (0x100d0a90) msgpairarray_sm:complete (status: 1) [D 16:57:53.732932] msgpairarray_complete: sm 0x100d0a90 status_user_tag 1 msgarray_count 1 [D 16:57:53.732954] msgpairarray: 1 operations remain [D 16:57:53.732977] [SM Exiting]: (0x100d0a90) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.733001] [SM Entering]: (0x100d0a90) msgpairarray_sm:complete (status: 0) [D 16:57:53.733024] msgpairarray_complete: sm 0x100d0a90 status_user_tag 0 msgarray_count 1 [D 16:57:53.733048] msgpairarray: all operations complete [D 16:57:53.733071] [SM Exiting]: (0x100d0a90) msgpairarray_sm:complete (error code: 190), (action: COMPLETE) [D 16:57:53.733094] [SM Entering]: (0x100d0a90) msgpairarray_sm:completion_fn (status: 0) [D 16:57:53.733118] (0x100d0a90) msgpairarray state: completion_fn [D 16:57:53.733140] PINT_decode [D 16:57:53.733162] lebf_decode_resp [D 16:57:53.733190] getattr_object_getattr_comp_fn called [D 16:57:53.733215] getattr_object_getattr_comp_fn: 2 datafiles. [D 16:57:53.733239] PINT_encode_release [D 16:57:53.733261] lebf_encode_rel [D 16:57:53.733283] PINT_decode_release [D 16:57:53.733305] lebf_decode_rel [D 16:57:53.733329] msgpairarray_completion_fn: sm 0x100d0a90 msgpair 0 marked complete [D 16:57:53.733352] [SM Exiting]: (0x100d0a90) msgpairarray_sm:completion_fn (error code: 2), (action: COMPLETE) [D 16:57:53.733376] [SM Entering]: (0x100d0a90) client_datafile_getattr_sizes_sm:datafile_getattr_setup_msgpairarray (status: 0) [D 16:57:53.733401] datafile_getattr: getting size for handle 2863311532 [D 16:57:53.733424] datafile_getattr: getting size for handle 1431655768 [D 16:57:53.733448] mapped handle 2863311532 to server 269273120 [D 16:57:53.733477] mapped handle 1431655768 to server 269813328 [D 16:57:53.733501] [SM Exiting]: (0x100d0a90) client_datafile_getattr_sizes_sm:datafile_getattr_setup_msgpairarray (error code: 0), (action: COMPLETE) [D 16:57:53.733526] [SM Entering]: (0x100d0a90) msgpairarray_sm:init (status: 0) [D 16:57:53.733549] (0x100d0a90) msgpairarray state: init (2 msgpair(s)) [D 16:57:53.733572] [SM Exiting]: (0x100d0a90) msgpairarray_sm:init (error code: 0), (action: COMPLETE) [D 16:57:53.733595] [SM Entering]: (0x100d0a90) msgpairarray_sm:post (status: 0) [D 16:57:53.733618] msgpairarray_post: sm 0x100d0a90 4 total message(s) with 4 incomplete [D 16:57:53.733643] PINT_encode [D 16:57:53.733665] encode_common [D 16:57:53.733688] lebf_encode_req [D 16:57:53.733711] PINT_encode_calc_max_size [D 16:57:53.733734] msgpairarray_post: sm 0x100d0a90 msgpair 0: posting recv [D 16:57:53.733758] BMI_post_recv: addr: 269273120, offset: 0x10154810, size: 9280, tag: 4 [D 16:57:53.733783] post_recv: new rq 0x100d09a0. [D 16:57:53.733807] memcache_register: hit [0] 0x10154810 len 9280 (via 0x10154810 len 9280) refcnt now 2. [D 16:57:53.733835] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.733860] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.733887] msgpairarray_post: sm 0x100d0a90 msgpair 0: posting send [D 16:57:53.733915] BMI_post_sendunexpected_list: addr: 269273120, count: 1, total_size: 40, tag: 4 [D 16:57:53.733942] element 0: offset: 0x1014e7e0, size: 40 [D 16:57:53.733968] post_send: sq 0x1014fc10 len 40 peer da13:3345. [D 16:57:53.733997] encourage_send_waiting_buffer: sq 0x1014fc10 sent EAGER len 40. [D 16:57:53.734023] PINT_encode [D 16:57:53.734047] encode_common [D 16:57:53.734070] lebf_encode_req [D 16:57:53.734093] PINT_encode_calc_max_size [D 16:57:53.734139] msgpairarray_post: sm 0x100d0a90 msgpair 1: posting recv [D 16:57:53.734165] BMI_post_recv: addr: 269813328, offset: 0x10156c60, size: 9280, tag: 5 [E 16:57:53.735059] Warning: openib_new_connection: asked for 70 send WRs on QP, got 0. [D 16:57:53.738773] ib_check_cq: send to da13:3345 completed locally: sq 0x1014fc10 -> SQ_WAITING_USER_TEST. [D 16:57:53.738813] ib_check_cq: recv from da13:3345 len 88 type MSG_EAGER_SEND credit 1. [D 16:57:53.738841] encourage_recv_incoming: recv eager len 88. [D 16:57:53.738867] encourage_recv_incoming: matched rq 0x100d09a0 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.738894] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.738921] memcache_deregister: dec refcount [0] 0x10154810 len 9280 (via 0x10154810 len 9280) refcnt now 1. [D 16:57:53.738951] post_recv: new rq 0x10150e70. [D 16:57:53.738978] memcache_register: hit [0] 0x10156c60 len 9280 (via 0x10156c60 len 9280) refcnt now 2. [D 16:57:53.739013] test_sq: sq 0x1014fc10 completed 40 to da13:3345. [D 16:57:53.739038] test_rq: rq 0x100d09a0 completed 72 from da13:3345. [D 16:57:53.739064] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.739090] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.739115] msgpairarray_post: sm 0x100d0a90 msgpair 1: posting send [D 16:57:53.739142] BMI_post_sendunexpected_list: addr: 269813328, count: 1, total_size: 40, tag: 5 [D 16:57:53.739167] element 0: offset: 0x1014fd50, size: 40 [D 16:57:53.739191] post_send: sq 0x100d09a0 len 40 peer da12:3345. [D 16:57:53.739216] encourage_send_waiting_buffer: sq 0x100d09a0 sent EAGER len 40. [D 16:57:53.739242] [SM Exiting]: (0x100d0a90) msgpairarray_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.739273] [SM Entering]: (0x100d0a90) msgpairarray_sm:complete (status: 2) [D 16:57:53.739297] msgpairarray_complete: sm 0x100d0a90 status_user_tag 2 msgarray_count 2 [D 16:57:53.739321] msgpairarray: 3 operations remain [D 16:57:53.739344] [SM Exiting]: (0x100d0a90) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.739368] [SM Entering]: (0x100d0a90) msgpairarray_sm:complete (status: 0) [D 16:57:53.739391] msgpairarray_complete: sm 0x100d0a90 status_user_tag 0 msgarray_count 2 [D 16:57:53.739415] msgpairarray: 2 operations remain [D 16:57:53.739437] [SM Exiting]: (0x100d0a90) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.739464] ib_check_cq: send to da12:3345 completed locally: sq 0x100d09a0 -> SQ_WAITING_USER_TEST. [D 16:57:53.739490] ib_check_cq: recv from da12:3345 len 88 type MSG_EAGER_SEND credit 1. [D 16:57:53.739513] encourage_recv_incoming: recv eager len 88. [D 16:57:53.739537] encourage_recv_incoming: matched rq 0x10150e70 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.739560] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.739583] memcache_deregister: dec refcount [0] 0x10156c60 len 9280 (via 0x10156c60 len 9280) refcnt now 1. [D 16:57:53.739608] test_sq: sq 0x100d09a0 completed 40 to da12:3345. [D 16:57:53.739631] test_rq: rq 0x10150e70 completed 72 from da12:3345. [D 16:57:53.739657] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.739682] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.739707] [SM Entering]: (0x100d0a90) msgpairarray_sm:complete (status: 3) [D 16:57:53.739731] msgpairarray_complete: sm 0x100d0a90 status_user_tag 3 msgarray_count 2 [D 16:57:53.739755] msgpairarray: 1 operations remain [D 16:57:53.739778] [SM Exiting]: (0x100d0a90) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.739802] [SM Entering]: (0x100d0a90) msgpairarray_sm:complete (status: 1) [D 16:57:53.739825] msgpairarray_complete: sm 0x100d0a90 status_user_tag 1 msgarray_count 2 [D 16:57:53.739849] msgpairarray: all operations complete [D 16:57:53.739875] [SM Exiting]: (0x100d0a90) msgpairarray_sm:complete (error code: 190), (action: COMPLETE) [D 16:57:53.739899] [SM Entering]: (0x100d0a90) msgpairarray_sm:completion_fn (status: 1) [D 16:57:53.739923] (0x100d0a90) msgpairarray state: completion_fn [D 16:57:53.739947] PINT_decode [D 16:57:53.739970] lebf_decode_resp [D 16:57:53.739995] datafile_getattr: size of datafile 0 is 2147483648 [D 16:57:53.740017] PINT_encode_release [D 16:57:53.740040] lebf_encode_rel [D 16:57:53.740064] PINT_decode_release [D 16:57:53.740086] lebf_decode_rel [D 16:57:53.740109] msgpairarray_completion_fn: sm 0x100d0a90 msgpair 0 marked complete [D 16:57:53.740133] PINT_decode [D 16:57:53.740156] lebf_decode_resp [D 16:57:53.740179] datafile_getattr: size of datafile 1 is 2147483648 [D 16:57:53.740201] PINT_encode_release [D 16:57:53.740223] lebf_encode_rel [D 16:57:53.740246] PINT_decode_release [D 16:57:53.740269] lebf_decode_rel [D 16:57:53.740291] msgpairarray_completion_fn: sm 0x100d0a90 msgpair 1 marked complete [D 16:57:53.740315] [SM Exiting]: (0x100d0a90) msgpairarray_sm:completion_fn (error code: 0), (action: COMPLETE) [D 16:57:53.740339] [SM Entering]: (0x100d0a90) client_datafile_getattr_sizes_sm:datafile_getattr_cleanup (status: 1) [D 16:57:53.740364] [SM Exiting]: (0x100d0a90) client_datafile_getattr_sizes_sm:datafile_getattr_cleanup (error code: 0), (action: COMPLETE) [D 16:57:53.740387] [SM Entering]: (0x100d0a90) client_getattr_sm:acache_insert (status: 1) [D 16:57:53.740412] acache: update(): H=1431655764 [D 16:57:53.740438] acache: update(): attr_status=0, size_status=0 [D 16:57:53.740463] acache: update(): return=0 [D 16:57:53.740486] trying to add object reference to acache [D 16:57:53.740509] [SM Exiting]: (0x100d0a90) client_getattr_sm:acache_insert (error code: 0), (action: COMPLETE) [D 16:57:53.740532] [SM Entering]: (0x100d0a90) client_getattr_sm:cleanup (status: 1) [D 16:57:53.740555] (0x100d0190) getattr state: getattr_cleanup [D 16:57:53.740578] [SM Exiting]: (0x100d0a90) client_getattr_sm:cleanup (error code: 0), (action: COMPLETE) [D 16:57:53.740602] [SM Entering]: (0x100d0a90) client_sysint_getattr_sm:set_sys_response (status: 1) [D 16:57:53.740627] [SM Exiting]: (0x100d0a90) client_sysint_getattr_sm:set_sys_response (error code: 0), (action: TERMINATE) [D 16:57:53.740652] client_state_machine_terminate smcb 0x100d0a90 [D 16:57:53.740674] add smcb 0x100d0a90 to completion list [D 16:57:53.740697] PINT_sys_release: id 147 [D 16:57:53.740726] PVFS2_VFS_OP_GETATTR complete (vfs_request 0x100ced00) wtime = 0.009127, utime=0.002012, stime=0.005145 (seconds) [D 16:57:53.740758] PINT_sys_testsome returned completed vfs_request 0x100ced00 [D 16:57:53.740782] object type = 1 [D 16:57:53.740805] write_device_response: writing device response. tag: 849 [D 16:57:53.740838] downcall write returned 1 [D 16:57:53.740862] PINT_sys_release: id 147 [D 16:57:53.740891] PINT_sys_dev_unexp [D 16:57:53.740917] [SM Frame PUSH]: (0x100d0a90) frame: 0x100d0190 [D 16:57:53.740946] [SM Locating]: (0x100d0a90) op-id: 400 [D 16:57:53.740970] client_op_state_get_machine 400 [D 16:57:53.741002] [SM Locating]: (0x100d0a90) located: sysdev_unexp_sm:post [D 16:57:53.741025] PINT_client_state_machine_post smcb 0x100d0a90, op: PVFS_DEV_UNEXPECTED [D 16:57:53.741051] [SM Entering]: (0x100d0a90) sysdev_unexp_sm:post (status: 0) [D 16:57:53.741099] [SM Exiting]: (0x100d0a90) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.741136] Posted PVFS_DEV_UNEXPECTED (153) (waiting for test)(-1073741839) [D 16:57:53.741179] [-] reposted unexp req [0x100ced00] due to normal_completion [D 16:57:53.741214] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 10 [D 16:57:53.741847] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 1, bytes available: 1 [D 16:57:53.741879] [SM Entering]: (0x100d2080) sysdev_unexp_sm:cleanup (status: 0) [D 16:57:53.741903] [SM Exiting]: (0x100d2080) sysdev_unexp_sm:cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.741927] client_state_machine_terminate smcb 0x100d2080 [D 16:57:53.741953] add smcb 0x100d2080 to completion list [D 16:57:53.741977] PINT_sys_release: id 14 [D 16:57:53.742002] PINT_sys_testsome returned unexp vfs_request 0x100d0bf0, tag: 850 [D 16:57:53.742026] [+] dev req msg: sz: 680,tag: 850,data: 0x1014e510,type: 0 [D 16:57:53.742050] [*] handling new unexp vfs_request 0x100d0bf0 [D 16:57:53.742073] is_op_in_progress called on tag 850 [D 16:57:53.742096] Got a lookup request for 4g2 (fsid 1334155764 | parent 1048576) [D 16:57:53.742121] PVFS_isys_ref_lookup entered [D 16:57:53.742145] [SM Frame PUSH]: (0x100d2980) frame: 0x100d2080 [D 16:57:53.742168] [SM Locating]: (0x100d2980) op-id: 11 [D 16:57:53.742191] client_op_state_get_machine 11 [D 16:57:53.742214] [SM Locating]: (0x100d2980) located: client_lookup_sm:lookup_segment_start [D 16:57:53.742239] initialize_context called [D 16:57:53.742264] original pathname is: 4g2 [D 16:57:53.742287] cur_seg_name[0]: 4g2 [D 16:57:53.742310] pathname is: 4g2 [D 16:57:53.742333] *seg_remaining is: 4g2 [D 16:57:53.742356] lookup got: 4g2 (parent 1048576) [D 16:57:53.742379] PINT_client_state_machine_post smcb 0x100d2980, op: PVFS_SYS_LOOKUP [D 16:57:53.742402] [SM Entering]: (0x100d2980) client_lookup_sm:lookup_segment_start (status: 0) [D 16:57:53.742426] lookup_segment_start [D 16:57:53.742448] [SM Exiting]: (0x100d2980) client_lookup_sm:lookup_segment_start (error code: 0), (action: COMPLETE) [D 16:57:53.742472] [SM Entering]: (0x100d2980) client_lookup_sm:lookup_segment_query_ncache (status: 0) [D 16:57:53.742496] lookup_segment_query_ncache: segment [4g2] [D 16:57:53.742519] ncache: get_cached_entry(): [4g2] [D 16:57:53.742543] ncache: miss: name=[4g2] [D 16:57:53.742566] *** ncache clean miss on first segment of 4g2 [D 16:57:53.742588] [SM Exiting]: (0x100d2980) client_lookup_sm:lookup_segment_query_ncache (error code: 1), (action: COMPLETE) [D 16:57:53.742612] [SM Entering]: (0x100d2980) client_lookup_sm:lookup_segment_setup_msgpair (status: 0) [D 16:57:53.742636] lookup_segment_setup_msgpair [D 16:57:53.742659] Looking up segment 4g2 under handle 1048576 [D 16:57:53.742685] [SM Exiting]: (0x100d2980) client_lookup_sm:lookup_segment_setup_msgpair (error code: 0), (action: COMPLETE) [D 16:57:53.742710] [SM Entering]: (0x100d2980) msgpairarray_sm:init (status: 0) [D 16:57:53.742733] (0x100d2980) msgpairarray state: init (1 msgpair(s)) [D 16:57:53.742756] [SM Exiting]: (0x100d2980) msgpairarray_sm:init (error code: 0), (action: COMPLETE) [D 16:57:53.742780] [SM Entering]: (0x100d2980) msgpairarray_sm:post (status: 0) [D 16:57:53.742804] msgpairarray_post: sm 0x100d2980 2 total message(s) with 2 incomplete [D 16:57:53.742828] PINT_encode [D 16:57:53.742852] encode_common [D 16:57:53.742875] lebf_encode_req [D 16:57:53.742902] PINT_encode_calc_max_size [D 16:57:53.742928] msgpairarray_post: sm 0x100d2980 msgpair 0: posting recv [D 16:57:53.742956] BMI_post_recv: addr: 269273120, offset: 0x101527e0, size: 8224, tag: 6 [D 16:57:53.742984] post_recv: new rq 0x10150fa0. [D 16:57:53.743010] memcache_register: hit [0] 0x101527e0 len 8224 (via 0x101527e0 len 8224) refcnt now 2. [D 16:57:53.743038] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.743063] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.743088] msgpairarray_post: sm 0x100d2980 msgpair 0: posting send [D 16:57:53.743113] BMI_post_sendunexpected_list: addr: 269273120, count: 1, total_size: 52, tag: 6 [D 16:57:53.743137] element 0: offset: 0x100ceab0, size: 52 [D 16:57:53.743161] post_send: sq 0x1014f220 len 52 peer da13:3345. [D 16:57:53.743187] encourage_send_waiting_buffer: sq 0x1014f220 sent EAGER len 52. [D 16:57:53.743212] [SM Exiting]: (0x100d2980) msgpairarray_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.743237] Posted PVFS_SYS_LOOKUP (156) (waiting for test)(-1073741839) [D 16:57:53.743265] ib_check_cq: send to da13:3345 completed locally: sq 0x1014f220 -> SQ_WAITING_USER_TEST. [D 16:57:53.743291] ib_check_cq: recv from da13:3345 len 104 type MSG_EAGER_SEND credit 1. [D 16:57:53.743318] encourage_recv_incoming: recv eager len 104. [D 16:57:53.743342] encourage_recv_incoming: matched rq 0x10150fa0 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.743365] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.743389] memcache_deregister: dec refcount [0] 0x101527e0 len 8224 (via 0x101527e0 len 8224) refcnt now 1. [D 16:57:53.743413] test_sq: sq 0x1014f220 completed 52 to da13:3345. [D 16:57:53.743437] test_rq: rq 0x10150fa0 completed 88 from da13:3345. [D 16:57:53.743462] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.743487] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.743514] [SM Entering]: (0x100d2980) msgpairarray_sm:complete (status: 1) [D 16:57:53.743536] msgpairarray_complete: sm 0x100d2980 status_user_tag 1 msgarray_count 1 [D 16:57:53.743560] msgpairarray: 1 operations remain [D 16:57:53.743583] [SM Exiting]: (0x100d2980) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.743607] [SM Entering]: (0x100d2980) msgpairarray_sm:complete (status: 0) [D 16:57:53.743630] msgpairarray_complete: sm 0x100d2980 status_user_tag 0 msgarray_count 1 [D 16:57:53.743654] msgpairarray: all operations complete [D 16:57:53.743677] [SM Exiting]: (0x100d2980) msgpairarray_sm:complete (error code: 190), (action: COMPLETE) [D 16:57:53.743700] [SM Entering]: (0x100d2980) msgpairarray_sm:completion_fn (status: 0) [D 16:57:53.743723] (0x100d2980) msgpairarray state: completion_fn [D 16:57:53.743746] PINT_decode [D 16:57:53.743769] lebf_decode_resp [D 16:57:53.743793] lookup_segment_lookup_comp_fn [D 16:57:53.743816] - Resolved 1 segments [D 16:57:53.743839] *** ncache update on 4g2 target (1431655751|1334155764) parent (1048576|1334155764) [D 16:57:53.743863] ncache: update(): name [4g2] [D 16:57:53.743888] ncache: update(): return=0 [D 16:57:53.743911] PINT_encode_release [D 16:57:53.743933] lebf_encode_rel [D 16:57:53.743956] PINT_decode_release [D 16:57:53.743979] lebf_decode_rel [D 16:57:53.744002] msgpairarray_completion_fn: sm 0x100d2980 msgpair 0 marked complete [D 16:57:53.744026] [SM Exiting]: (0x100d2980) msgpairarray_sm:completion_fn (error code: 0), (action: COMPLETE) [D 16:57:53.744050] [SM Entering]: (0x100d2980) client_lookup_sm:lookup_segment_verify_attr_present (status: 0) [D 16:57:53.744073] lookup state: lookup_segment_verify_attr_present [D 16:57:53.744096] -- we have the attrs for 4g2 [D 16:57:53.744118] [SM Exiting]: (0x100d2980) client_lookup_sm:lookup_segment_verify_attr_present (error code: 0), (action: COMPLETE) [D 16:57:53.744142] [SM Entering]: (0x100d2980) client_lookup_sm:lookup_segment_check_attr_type (status: 0) [D 16:57:53.744166] lookup state: lookup_segment_check_attr_type [D 16:57:53.744189] [SM Exiting]: (0x100d2980) client_lookup_sm:lookup_segment_check_attr_type (error code: 4), (action: COMPLETE) [D 16:57:53.744213] [SM Entering]: (0x100d2980) client_lookup_sm:lookup_context_check_completion (status: 0) [D 16:57:53.744236] lookup state: lookup_context_check_completion [D 16:57:53.744259] [SM Exiting]: (0x100d2980) client_lookup_sm:lookup_context_check_completion (error code: 0), (action: COMPLETE) [D 16:57:53.744283] [SM Entering]: (0x100d2980) client_lookup_sm:lookup_cleanup (status: 0) [D 16:57:53.744307] lookup state: lookup_cleanup [D 16:57:53.744329] Freeing segment 4g2 [D 16:57:53.744352] Freeing remaining segment 4g2 [D 16:57:53.744376] All contexts finalized [D 16:57:53.744398] Lookup resolved segment 4g2 to 1431655751 [D 16:57:53.744421] [SM Exiting]: (0x100d2980) client_lookup_sm:lookup_cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.744444] client_state_machine_terminate smcb 0x100d2980 [D 16:57:53.744467] add smcb 0x100d2980 to completion list [D 16:57:53.744490] PINT_sys_release: id 156 [D 16:57:53.744517] PVFS2_VFS_OP_LOOKUP complete (vfs_request 0x100d0bf0) wtime = 0.002421, utime=0.000000, stime=0.000000 (seconds) [D 16:57:53.744544] PINT_sys_testsome returned completed vfs_request 0x100d0bf0 [D 16:57:53.744567] write_device_response: writing device response. tag: 850 [D 16:57:53.744599] downcall write returned 1 [D 16:57:53.744623] PINT_sys_release: id 156 [D 16:57:53.744646] PINT_sys_dev_unexp [D 16:57:53.744670] [SM Frame PUSH]: (0x1014f0f0) frame: 0x100d2080 [D 16:57:53.744693] [SM Locating]: (0x1014f0f0) op-id: 400 [D 16:57:53.744716] client_op_state_get_machine 400 [D 16:57:53.744739] [SM Locating]: (0x1014f0f0) located: sysdev_unexp_sm:post [D 16:57:53.744762] PINT_client_state_machine_post smcb 0x1014f0f0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.744785] [SM Entering]: (0x1014f0f0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.744810] [SM Exiting]: (0x1014f0f0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.744834] Posted PVFS_DEV_UNEXPECTED (158) (waiting for test)(-1073741839) [D 16:57:53.744858] [-] reposted unexp req [0x100d0bf0] due to normal_completion [D 16:57:53.744891] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 10 [D 16:57:53.744918] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 1, bytes available: 1 [D 16:57:53.744945] [SM Entering]: (0x100d3f70) sysdev_unexp_sm:cleanup (status: 0) [D 16:57:53.744969] [SM Exiting]: (0x100d3f70) sysdev_unexp_sm:cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.744993] client_state_machine_terminate smcb 0x100d3f70 [D 16:57:53.745015] add smcb 0x100d3f70 to completion list [D 16:57:53.745038] PINT_sys_release: id 16 [D 16:57:53.745062] PINT_sys_testsome returned unexp vfs_request 0x100d2ae0, tag: 851 [D 16:57:53.745086] [+] dev req msg: sz: 680,tag: 851,data: 0x1014e510,type: 0 [D 16:57:53.745111] [*] handling new unexp vfs_request 0x100d2ae0 [D 16:57:53.745134] is_op_in_progress called on tag 851 [D 16:57:53.745158] got a getattr request for fsid 1334155764 | handle 1431655751 [D 16:57:53.745182] PVFS_isys_getattr entered [D 16:57:53.745206] [SM Frame PUSH]: (0x1014f1b0) frame: 0x100d3f70 [D 16:57:53.745229] [SM Locating]: (0x1014f1b0) op-id: 5 [D 16:57:53.745252] client_op_state_get_machine 5 [D 16:57:53.745275] [SM Locating]: (0x1014f1b0) located: client_getattr_sm:acache_lookup [D 16:57:53.745299] attrmask being passed to server: [D 16:57:53.745323] mask = 0xc8c00: [D 16:57:53.745345] PVFS_ATTR_META_DIST [D 16:57:53.745368] PVFS_ATTR_META_DFILES [D 16:57:53.745389] PVFS_ATTR_DATA_SIZE [D 16:57:53.745412] PINT_client_state_machine_post smcb 0x1014f1b0, op: PVFS_SYS_GETATTR [D 16:57:53.745435] [SM Entering]: (0x1014f1b0) client_getattr_sm:acache_lookup (status: 0) [D 16:57:53.745459] getattr_acache_lookup: handle 1431655751 fsid 1334155764 [D 16:57:53.745483] acache: get_cached_entry(): H=1431655751 [D 16:57:53.745506] acache: miss: H=1431655751 [D 16:57:53.745529] acache: clean acache miss: [1431655751] [D 16:57:53.745553] [SM Exiting]: (0x1014f1b0) client_getattr_sm:acache_lookup (error code: 1), (action: COMPLETE) [D 16:57:53.745575] [SM Entering]: (0x1014f1b0) client_getattr_sm:object_getattr_setup_msgpair (status: 0) [D 16:57:53.745599] (0x100d3f70) getattr_object_getattr_setup_msgpair [D 16:57:53.745624] [SM Exiting]: (0x1014f1b0) client_getattr_sm:object_getattr_setup_msgpair (error code: 0), (action: COMPLETE) [D 16:57:53.745649] [SM Entering]: (0x1014f1b0) msgpairarray_sm:init (status: 0) [D 16:57:53.745673] (0x1014f1b0) msgpairarray state: init (1 msgpair(s)) [D 16:57:53.745696] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:init (error code: 0), (action: COMPLETE) [D 16:57:53.745718] [SM Entering]: (0x1014f1b0) msgpairarray_sm:post (status: 0) [D 16:57:53.745742] msgpairarray_post: sm 0x1014f1b0 2 total message(s) with 2 incomplete [D 16:57:53.745766] PINT_encode [D 16:57:53.745789] encode_common [D 16:57:53.745812] lebf_encode_req [D 16:57:53.745834] PINT_encode_calc_max_size [D 16:57:53.745858] msgpairarray_post: sm 0x1014f1b0 msgpair 0: posting recv [D 16:57:53.745882] BMI_post_recv: addr: 269273120, offset: 0x10156c60, size: 9280, tag: 7 [D 16:57:53.745906] post_recv: new rq 0x100cebe0. [D 16:57:53.745930] memcache_register: hit [0] 0x10156c60 len 9280 (via 0x10156c60 len 9280) refcnt now 2. [D 16:57:53.745958] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.745985] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.746010] msgpairarray_post: sm 0x1014f1b0 msgpair 0: posting send [D 16:57:53.746034] BMI_post_sendunexpected_list: addr: 269273120, count: 1, total_size: 40, tag: 7 [D 16:57:53.746058] element 0: offset: 0x100d2ab0, size: 40 [D 16:57:53.746082] post_send: sq 0x100d48b0 len 40 peer da13:3345. [D 16:57:53.746109] encourage_send_waiting_buffer: sq 0x100d48b0 sent EAGER len 40. [D 16:57:53.746133] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.746157] Posted PVFS_SYS_GETATTR (161) (waiting for test)(-1073741839) [D 16:57:53.746185] ib_check_cq: send to da13:3345 completed locally: sq 0x100d48b0 -> SQ_WAITING_USER_TEST. [D 16:57:53.746212] ib_check_cq: recv from da13:3345 len 144 type MSG_EAGER_SEND credit 1. [D 16:57:53.746235] encourage_recv_incoming: recv eager len 144. [D 16:57:53.746259] encourage_recv_incoming: matched rq 0x100cebe0 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.746282] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.746305] memcache_deregister: dec refcount [0] 0x10156c60 len 9280 (via 0x10156c60 len 9280) refcnt now 1. [D 16:57:53.746331] test_sq: sq 0x100d48b0 completed 40 to da13:3345. [D 16:57:53.746354] test_rq: rq 0x100cebe0 completed 128 from da13:3345. [D 16:57:53.746379] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.746404] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.746430] [SM Entering]: (0x1014f1b0) msgpairarray_sm:complete (status: 1) [D 16:57:53.746454] msgpairarray_complete: sm 0x1014f1b0 status_user_tag 1 msgarray_count 1 [D 16:57:53.746478] msgpairarray: 1 operations remain [D 16:57:53.746500] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.746523] [SM Entering]: (0x1014f1b0) msgpairarray_sm:complete (status: 0) [D 16:57:53.746547] msgpairarray_complete: sm 0x1014f1b0 status_user_tag 0 msgarray_count 1 [D 16:57:53.746570] msgpairarray: all operations complete [D 16:57:53.746593] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:complete (error code: 190), (action: COMPLETE) [D 16:57:53.746617] [SM Entering]: (0x1014f1b0) msgpairarray_sm:completion_fn (status: 0) [D 16:57:53.746640] (0x1014f1b0) msgpairarray state: completion_fn [D 16:57:53.746663] PINT_decode [D 16:57:53.746685] lebf_decode_resp [D 16:57:53.746709] getattr_object_getattr_comp_fn called [D 16:57:53.746733] getattr_object_getattr_comp_fn: 2 datafiles. [D 16:57:53.746757] PINT_encode_release [D 16:57:53.746779] lebf_encode_rel [D 16:57:53.746802] PINT_decode_release [D 16:57:53.746824] lebf_decode_rel [D 16:57:53.746848] msgpairarray_completion_fn: sm 0x1014f1b0 msgpair 0 marked complete [D 16:57:53.746870] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:completion_fn (error code: 2), (action: COMPLETE) [D 16:57:53.746898] [SM Entering]: (0x1014f1b0) client_datafile_getattr_sizes_sm:datafile_getattr_setup_msgpairarray (status: 0) [D 16:57:53.746927] datafile_getattr: getting size for handle 4294967277 [D 16:57:53.746953] datafile_getattr: getting size for handle 2863311516 [D 16:57:53.746980] mapped handle 4294967277 to server 269273120 [D 16:57:53.747007] mapped handle 2863311516 to server 269813328 [D 16:57:53.747031] [SM Exiting]: (0x1014f1b0) client_datafile_getattr_sizes_sm:datafile_getattr_setup_msgpairarray (error code: 0), (action: COMPLETE) [D 16:57:53.747055] [SM Entering]: (0x1014f1b0) msgpairarray_sm:init (status: 0) [D 16:57:53.747077] (0x1014f1b0) msgpairarray state: init (2 msgpair(s)) [D 16:57:53.747100] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:init (error code: 0), (action: COMPLETE) [D 16:57:53.747124] [SM Entering]: (0x1014f1b0) msgpairarray_sm:post (status: 0) [D 16:57:53.747148] msgpairarray_post: sm 0x1014f1b0 4 total message(s) with 4 incomplete [D 16:57:53.747172] PINT_encode [D 16:57:53.747194] encode_common [D 16:57:53.747220] lebf_encode_req [D 16:57:53.747242] PINT_encode_calc_max_size [D 16:57:53.747265] msgpairarray_post: sm 0x1014f1b0 msgpair 0: posting recv [D 16:57:53.747290] BMI_post_recv: addr: 269273120, offset: 0x10156c60, size: 9280, tag: 8 [D 16:57:53.747315] post_recv: new rq 0x100d2990. [D 16:57:53.747339] memcache_register: hit [0] 0x10156c60 len 9280 (via 0x10156c60 len 9280) refcnt now 2. [D 16:57:53.747366] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.747391] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.747416] msgpairarray_post: sm 0x1014f1b0 msgpair 0: posting send [D 16:57:53.747441] BMI_post_sendunexpected_list: addr: 269273120, count: 1, total_size: 40, tag: 8 [D 16:57:53.747465] element 0: offset: 0x100d2ab0, size: 40 [D 16:57:53.747488] post_send: sq 0x100cebe0 len 40 peer da13:3345. [D 16:57:53.747514] encourage_send_waiting_buffer: sq 0x100cebe0 sent EAGER len 40. [D 16:57:53.747540] PINT_encode [D 16:57:53.747563] encode_common [D 16:57:53.747586] lebf_encode_req [D 16:57:53.747608] PINT_encode_calc_max_size [D 16:57:53.747631] msgpairarray_post: sm 0x1014f1b0 msgpair 1: posting recv [D 16:57:53.747655] BMI_post_recv: addr: 269813328, offset: 0x10154810, size: 9280, tag: 9 [D 16:57:53.747680] ib_check_cq: send to da13:3345 completed locally: sq 0x100cebe0 -> SQ_WAITING_USER_TEST. [D 16:57:53.747707] ib_check_cq: recv from da13:3345 len 88 type MSG_EAGER_SEND credit 1. [D 16:57:53.747731] encourage_recv_incoming: recv eager len 88. [D 16:57:53.747754] encourage_recv_incoming: matched rq 0x100d2990 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.747777] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.747800] memcache_deregister: dec refcount [0] 0x10156c60 len 9280 (via 0x10156c60 len 9280) refcnt now 1. [D 16:57:53.747826] post_recv: new rq 0x10151080. [D 16:57:53.747849] memcache_register: hit [0] 0x10154810 len 9280 (via 0x10154810 len 9280) refcnt now 2. [D 16:57:53.747877] test_sq: sq 0x100cebe0 completed 40 to da13:3345. [D 16:57:53.747901] test_rq: rq 0x100d2990 completed 72 from da13:3345. [D 16:57:53.747926] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.747951] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.747976] msgpairarray_post: sm 0x1014f1b0 msgpair 1: posting send [D 16:57:53.748001] BMI_post_sendunexpected_list: addr: 269813328, count: 1, total_size: 40, tag: 9 [D 16:57:53.748024] element 0: offset: 0x10150f20, size: 40 [D 16:57:53.748048] post_send: sq 0x1014f490 len 40 peer da12:3345. [D 16:57:53.748074] encourage_send_waiting_buffer: sq 0x1014f490 sent EAGER len 40. [D 16:57:53.748099] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.748126] [SM Entering]: (0x1014f1b0) msgpairarray_sm:complete (status: 2) [D 16:57:53.748150] msgpairarray_complete: sm 0x1014f1b0 status_user_tag 2 msgarray_count 2 [D 16:57:53.748174] msgpairarray: 3 operations remain [D 16:57:53.748196] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.748220] [SM Entering]: (0x1014f1b0) msgpairarray_sm:complete (status: 0) [D 16:57:53.748244] msgpairarray_complete: sm 0x1014f1b0 status_user_tag 0 msgarray_count 2 [D 16:57:53.748267] msgpairarray: 2 operations remain [D 16:57:53.748290] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.748317] ib_check_cq: send to da12:3345 completed locally: sq 0x1014f490 -> SQ_WAITING_USER_TEST. [D 16:57:53.748344] ib_check_cq: recv from da12:3345 len 88 type MSG_EAGER_SEND credit 1. [D 16:57:53.748368] encourage_recv_incoming: recv eager len 88. [D 16:57:53.748391] encourage_recv_incoming: matched rq 0x10151080 now RQ_EAGER_WAITING_USER_TEST. [D 16:57:53.748414] encourage_recv_incoming: early registration not needed, dereg after eager. [D 16:57:53.748437] memcache_deregister: dec refcount [0] 0x10154810 len 9280 (via 0x10154810 len 9280) refcnt now 1. [D 16:57:53.748465] test_sq: sq 0x1014f490 completed 40 to da12:3345. [D 16:57:53.748490] test_rq: rq 0x10151080 completed 72 from da12:3345. [D 16:57:53.748515] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 0 [D 16:57:53.748539] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 0, bytes available: -1 [D 16:57:53.748566] [SM Entering]: (0x1014f1b0) msgpairarray_sm:complete (status: 3) [D 16:57:53.748590] msgpairarray_complete: sm 0x1014f1b0 status_user_tag 3 msgarray_count 2 [D 16:57:53.748613] msgpairarray: 1 operations remain [D 16:57:53.748636] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:complete (error code: 0), (action: DEFERRED) [D 16:57:53.748660] [SM Entering]: (0x1014f1b0) msgpairarray_sm:complete (status: 1) [D 16:57:53.748682] msgpairarray_complete: sm 0x1014f1b0 status_user_tag 1 msgarray_count 2 [D 16:57:53.748706] msgpairarray: all operations complete [D 16:57:53.748729] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:complete (error code: 190), (action: COMPLETE) [D 16:57:53.748752] [SM Entering]: (0x1014f1b0) msgpairarray_sm:completion_fn (status: 1) [D 16:57:53.748776] (0x1014f1b0) msgpairarray state: completion_fn [D 16:57:53.748799] PINT_decode [D 16:57:53.748821] lebf_decode_resp [D 16:57:53.748844] datafile_getattr: size of datafile 0 is 2147483648 [D 16:57:53.748867] PINT_encode_release [D 16:57:53.748894] lebf_encode_rel [D 16:57:53.748918] PINT_decode_release [D 16:57:53.748940] lebf_decode_rel [D 16:57:53.748963] msgpairarray_completion_fn: sm 0x1014f1b0 msgpair 0 marked complete [D 16:57:53.748987] PINT_decode [D 16:57:53.749009] lebf_decode_resp [D 16:57:53.749032] datafile_getattr: size of datafile 1 is 2147483648 [D 16:57:53.749054] PINT_encode_release [D 16:57:53.749076] lebf_encode_rel [D 16:57:53.749099] PINT_decode_release [D 16:57:53.749122] lebf_decode_rel [D 16:57:53.749145] msgpairarray_completion_fn: sm 0x1014f1b0 msgpair 1 marked complete [D 16:57:53.749168] [SM Exiting]: (0x1014f1b0) msgpairarray_sm:completion_fn (error code: 0), (action: COMPLETE) [D 16:57:53.749192] [SM Entering]: (0x1014f1b0) client_datafile_getattr_sizes_sm:datafile_getattr_cleanup (status: 1) [D 16:57:53.749216] [SM Exiting]: (0x1014f1b0) client_datafile_getattr_sizes_sm:datafile_getattr_cleanup (error code: 0), (action: COMPLETE) [D 16:57:53.749239] [SM Entering]: (0x1014f1b0) client_getattr_sm:acache_insert (status: 1) [D 16:57:53.749263] acache: update(): H=1431655751 [D 16:57:53.749288] acache: update(): attr_status=0, size_status=0 [D 16:57:53.749312] acache: update(): return=0 [D 16:57:53.749335] trying to add object reference to acache [D 16:57:53.749357] [SM Exiting]: (0x1014f1b0) client_getattr_sm:acache_insert (error code: 0), (action: COMPLETE) [D 16:57:53.749381] [SM Entering]: (0x1014f1b0) client_getattr_sm:cleanup (status: 1) [D 16:57:53.749403] (0x100d3f70) getattr state: getattr_cleanup [D 16:57:53.749426] [SM Exiting]: (0x1014f1b0) client_getattr_sm:cleanup (error code: 0), (action: COMPLETE) [D 16:57:53.749450] [SM Entering]: (0x1014f1b0) client_sysint_getattr_sm:set_sys_response (status: 1) [D 16:57:53.749475] [SM Exiting]: (0x1014f1b0) client_sysint_getattr_sm:set_sys_response (error code: 0), (action: TERMINATE) [D 16:57:53.749499] client_state_machine_terminate smcb 0x1014f1b0 [D 16:57:53.749522] add smcb 0x1014f1b0 to completion list [D 16:57:53.749545] PINT_sys_release: id 161 [D 16:57:53.749570] PVFS2_VFS_OP_GETATTR complete (vfs_request 0x100d2ae0) wtime = 0.004411, utime=0.001220, stime=0.002747 (seconds) [D 16:57:53.749598] PINT_sys_testsome returned completed vfs_request 0x100d2ae0 [D 16:57:53.749621] object type = 1 [D 16:57:53.749644] write_device_response: writing device response. tag: 851 [D 16:57:53.749671] downcall write returned 1 [D 16:57:53.749695] PINT_sys_release: id 161 [D 16:57:53.749718] PINT_sys_dev_unexp [D 16:57:53.749743] [SM Frame PUSH]: (0x1014f1b0) frame: 0x100d3f70 [D 16:57:53.749766] [SM Locating]: (0x1014f1b0) op-id: 400 [D 16:57:53.749789] client_op_state_get_machine 400 [D 16:57:53.749812] [SM Locating]: (0x1014f1b0) located: sysdev_unexp_sm:post [D 16:57:53.749837] PINT_client_state_machine_post smcb 0x1014f1b0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.749861] [SM Entering]: (0x1014f1b0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.749886] [SM Exiting]: (0x1014f1b0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.749911] Posted PVFS_DEV_UNEXPECTED (167) (waiting for test)(-1073741839) [D 16:57:53.749935] [-] reposted unexp req [0x100d2ae0] due to normal_completion [D 16:57:53.749960] [DEV]: Entered PINT_dev_test_unexpected: incount: 5, timeout: 10 [D 16:57:53.749988] [DEV]: PINT_dev_test_unexpected Exit: incount: 5, outcount: 1, bytes available: 1 [D 16:57:53.750014] [SM Entering]: (0x100d5e60) sysdev_unexp_sm:cleanup (status: 0) [D 16:57:53.750038] [SM Exiting]: (0x100d5e60) sysdev_unexp_sm:cleanup (error code: 0), (action: TERMINATE) [D 16:57:53.750061] client_state_machine_terminate smcb 0x100d5e60 [D 16:57:53.750084] add smcb 0x100d5e60 to completion list [D 16:57:53.750107] PINT_sys_release: id 18 [D 16:57:53.750132] PINT_sys_testsome returned unexp vfs_request 0x100d49d0, tag: 852 [D 16:57:53.750156] [+] dev req msg: sz: 680,tag: 852,data: 0x1014e510,type: 0 [D 16:57:53.750180] [*] handling new unexp vfs_request 0x100d49d0 [D 16:57:53.750203] is_op_in_progress called on tag 852 [D 16:57:53.750226] got a getattr request for fsid 1334155764 | handle 1431655751 [D 16:57:53.750249] PVFS_isys_getattr entered [D 16:57:53.750273] [SM Frame PUSH]: (0x100d6760) frame: 0x100d5e60 [D 16:57:53.750297] [SM Locating]: (0x100d6760) op-id: 5 [D 16:57:53.750319] client_op_state_get_machine 5 [D 16:57:53.750342] [SM Locating]: (0x100d6760) located: client_getattr_sm:acache_lookup [D 16:57:53.750366] attrmask being passed to server: [D 16:57:53.750389] mask = 0xc8c00: [D 16:57:53.750411] PVFS_ATTR_META_DIST [D 16:57:53.750433] PVFS_ATTR_META_DFILES [D 16:57:53.750455] PVFS_ATTR_DATA_SIZE [D 16:57:53.750477] PINT_client_state_machine_post smcb 0x100d6760, op: PVFS_SYS_GETATTR [D 16:57:53.750501] [SM Entering]: (0x100d6760) client_getattr_sm:acache_lookup (status: 0) [D 16:57:53.750524] getattr_acache_lookup: handle 1431655751 fsid 1334155764 [D 16:57:53.750548] acache: get_cached_entry(): H=1431655751 [D 16:57:53.750572] acache: status=0, attr_status=0, size_status=0 [D 16:57:53.750594] acache: copying out attr. [D 16:57:53.750617] acache: copying out size. [D 16:57:53.750639] acache: hit: H=1431655751, size_status=0, attr_status=0 [D 16:57:53.750663] acache: acache hit [1431655751] [D 16:57:53.750686] [SM Exiting]: (0x100d6760) client_getattr_sm:acache_lookup (error code: 0), (action: COMPLETE) [D 16:57:53.750710] [SM Entering]: (0x100d6760) client_getattr_sm:cleanup (status: 0) [D 16:57:53.750733] (0x100d5e60) getattr state: getattr_cleanup [D 16:57:53.750756] [SM Exiting]: (0x100d6760) client_getattr_sm:cleanup (error code: 0), (action: COMPLETE) [D 16:57:53.750780] [SM Entering]: (0x100d6760) client_sysint_getattr_sm:set_sys_response (status: 0) [D 16:57:53.750803] [SM Exiting]: (0x100d6760) client_sysint_getattr_sm:set_sys_response (error code: 0), (action: TERMINATE) [D 16:57:53.750828] client_state_machine_terminate smcb 0x100d6760 [D 16:57:53.750850] add smcb 0x100d6760 to completion list [D 16:57:53.750874] Posted PVFS_SYS_GETATTR (18446744073709551615) (ran to termination)(0) [D 16:57:53.750902] object type = 1 [D 16:57:53.750928] PVFS2_VFS_OP_GETATTR complete (vfs_request 0x100d49d0) wtime = 0.000701, utime=0.000000, stime=0.000000 (seconds) [D 16:57:53.750958] write_device_response: writing device response. tag: 852 [D 16:57:53.750990] PINT_sys_release: id -1 [D 16:57:53.751015] PINT_sys_dev_unexp [D 16:57:53.751039] [SM Frame PUSH]: (0x100ceab0) frame: 0x100d5e60 [D 16:57:53.751063] [SM Locating]: (0x100ceab0) op-id: 400 [D 16:57:53.751086] client_op_state_get_machine 400 [D 16:57:53.751108] [SM Locating]: (0x100ceab0) located: sysdev_unexp_sm:post [D 16:57:53.751132] PINT_client_state_machine_post smcb 0x100ceab0, op: PVFS_DEV_UNEXPECTED [D 16:57:53.751154] [SM Entering]: (0x100ceab0) sysdev_unexp_sm:post (status: 0) [D 16:57:53.751182] [SM Exiting]: (0x100ceab0) sysdev_unexp_sm:post (error code: 0), (action: DEFERRED) [D 16:57:53.751207] Posted PVFS_DEV_UNEXPECTED (169) (waiting for test)(-1073741839) [D 16:57:53.751231] [-] reposted unexp req [0x100d49d0] due to inlined completion [D 16:57:53.751255] FRAME GET smcb 0x100d6760 index 0 -> frame: NULL [E 16:57:53.751284] pvfs2-client-core: caught signal 11