Using existing output directory "/tmp/dsc"
start ds: 8810
start ds: 8820
start ds: 8830
start access at:127.0.0.1:9998
Starting downstairs at port 8810
Make output file at "/tmp/dsc/downstairs-8810.txt"
Starting downstairs at port 8820
Make output file at "/tmp/dsc/downstairs-8820.txt"
[8810][0] reports Starting
[8820][1] reports Starting
Starting downstairs at port 8830
Make output file at "/tmp/dsc/downstairs-8830.txt"
[8830][2] reports Starting
Downstairs /var/tmp/dsc/8810 port 8810 PID:Some(1444)
[8810][0] reports Running
Downstairs /var/tmp/dsc/8830 port 8830 PID:Some(1445)
[8830][2] reports Running
Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1446)
[8820][1] reports Running
Feb 04 13:58:10.646 INFO listening, local_addr: 127.0.0.1:9998
Control access at:127.0.0.1:9998
Feb 04 13:58:15.714 INFO accepted connection, remote_addr: 127.0.0.1:50633, local_addr: 127.0.0.1:9998
Main task has work to do, go find it
got dsc DisableRestartAll
disable restart on all: 3
Feb 04 13:58:15.715 INFO request completed, latency_us: 171, response_code: 204, uri: /disablerestart/all, method: POST, req_id: 370f4ddb-65a0-4ea4-94d5-f9b3a4bef03e, remote_addr: 127[8810] Disable keep_running
.[8820] Disable keep_running
0.0.1:50633, local_addr: 127[8830] Disable keep_running
.0.0.1:9998
Feb 04 14:05:16.242 INFO accepted connection, remote_addr: 127.0.0.1:58776, local_addr: 127.0.0.1:9998
Main task has work to do, go find it
got dsc Shutdown
Shutdown
Shut it down
Feb 04 14:05:16.243 INFO request completed, latency_us: 76, response_code: 204, uri[8820] Disable keep_running
:[8810] Disable keep_running
 [8810] Got stop action so:false kr:false
/shutdown, method: POST, req_id: b13932b9-4bba-4347-bbeb-75e427489240, remote_addr: 127.0.0.1:58776, [8830] Disable keep_running
local_addr: 127.0.0.1:9998
[8820] Got stop action so:false kr:false
[8830] Got stop action so:false kr:false
[8810] Exited with: ExitStatus(unix_wait_status(9))
[8810][0] reports Exit
[8830] Exited with: ExitStatus(unix_wait_status(9))
[8820] Exited with: ExitStatus(unix_wait_status(9))
[8830][2] reports Exit
[8820][1] reports Exit
-04T13:58:15.732982939Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449}
{"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.732991971Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449}
{"msg":"Crucible c4c1829e-dce3-496b-b8b0-5d2779d42bdd has session id: 632a40fd-bfaa-4ef6-9432-12907ae9290d","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733014453Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Upstairs opts: Upstairs UUID: c4c1829e-dce3-496b-b8b0-5d2779d42bdd, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false,  cert_pem populated: false,  key_pem populated: false,  root_cert_pem populated: false,  Control: None,  read_only: false","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733030279Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Crucible stats registered with UUID: c4c1829e-dce3-496b-b8b0-5d2779d42bdd","Crucible runtime is spawned
v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733064722Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733087334Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449}
{"msg":"c4c1829e-dce3-496b-b8b0-5d2779d42bdd active request set","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.73322524Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733235442Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733254007Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733261725Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733269032Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733277472Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733291001Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733388581Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"io task","client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733406005Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"io task","client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733413792Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"io task","client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733594258Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"io task","client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733612284Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"io task","client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.733625648Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"io task","client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.734149644Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.734165365Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.734173215Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.734180615Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.734257669Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.734267214Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.734998102Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.7350594Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.735375184Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.747178353Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.74719294Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.747200623Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.74985132Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749863876Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749871458Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.74987783Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749885029Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[0]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749892427Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[0]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749904478Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[0]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749912119Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[1]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749919344Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[1]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749926556Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[1]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749933731Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[2]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749940947Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[2]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749948033Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"[2]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.74995532Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749962368Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749969425Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749976421Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.74998355Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"":"downstairs","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.749990651Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.750010569Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"0","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
Wait for a query_work_queue command to finish before sending IO
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.750064552Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"1","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.750074307Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"client":"2","":"downstairs","session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.750081407Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.750087634Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"c4c1829e-dce3-496b-b8b0-5d2779d42bdd is now active with session: 632a40fd-bfaa-4ef6-9432-12907ae9290d","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.75009398Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.750100168Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449,"session_id":"632a40fd-bfaa-4ef6-9432-12907ae9290d"}
{"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:15.750106341Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449}
Region: es:16384 ec:1600 bs:4096  ts:107374182400  tb:26214400  max_io:256 or 1048576
Fill test
CLIENT: Tests done.  All submitted work has been ACK'd
----------------------------------------------------------------
 Crucible gen:1 GIO:true work queues:  Upstairs:0  downstairs:0
Downstairs last five completed: 263980 263979 263978 263977 263976
Upstairs last five completed:   262981 262980 262979 262978 262977
CLIENT: Up:0 ds:0 act:3
CLIENT: All crucible jobs finished, exiting program
{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2024-02-04T14:05:14.999497456Z","hostname":"ip-10-150-1-114.us-west-2.compute.internal","pid":1449}