Using existing output directory "/tmp/dsc"
start access at:127.0.0.1:9998
start ds: 8810
start ds: 8820
start ds: 8830
Starting downstairs at port 8810
Make output file at "/tmp/dsc/downstairs-8810.txt"
[8810][0] reports Starting
Starting downstairs at port 8820
Make output file at "/tmp/dsc/downstairs-8820.txt"
[8820][1] reports Starting
Starting downstairs at port 8830
[8830][2] reports Starting
Make output file at "/tmp/dsc/downstairs-8830.txt"
Downstairs /var/tmp/dsc/8810 port 8810 PID:Some(1447)
[8810][0] reports Running
Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1448)
[8820][1] reports Running
Downstairs /var/tmp/dsc/8830 port 8830 PID:Some(1449)
[8830][2] reports Running
Feb 03 17:21:18.842 INFO listening, local_addr: 127.0.0.1:9998
Control access at:127.0.0.1:9998
Feb 03 17:21:23.908 INFO accepted connection, remote_addr: 127.0.0.1:55467, 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 03 17:21:23.908 INFO request completed, latency_us: 161, response_code: 204, uri: /disablerestart/all, method: POST, req_id: 781e6431-add9-4474-b001-a3c2153e8290[8810] Disable keep_running
, [8830] Disable keep_running
remote_addr: 127.0.0.1:55467, local_addr: 127.0.0.1:9998
[8820] Disable keep_running
Feb 03 17:28:25.770 INFO accepted connection, remote_addr: 127.0.0.1:57836, local_addr: 127.0.0.1:9998
Main task has work to do, go find it
got dsc Shutdown
Shutdown
Feb 03 17:28:25.770Shut it down
 INFO request completed[8810] Disable keep_running
, [8810] Got stop action so:false kr:false
latency_us: 70, response_code: 204, uri: /shutdown, method: POST, req_id: 8b6608a3-a0e0-4706-b190-e37e6b1cbba2, remote_addr: 127.0.0.1:57836, [8830] Disable keep_running
local_addr[8820] Disable keep_running
:[8820] Got stop action so:false kr:false
 127.0.0.1:9998
[8830] Got stop action so:false kr:false
[8830] Exited with: ExitStatus(unix_wait_status(9))
[8830][2] reports Exit
[8820] Exited with: ExitStatus(unix_wait_status(9))
[8820][1] reports Exit
[8810] Exited with: ExitStatus(unix_wait_status(9))
[8810][0] reports Exit
3T17:21:23.925116284Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452}
{"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.9251297Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452}
{"msg":"Crucible f5577520-9e2c-4ca5-8596-714d5f924dd9 has session id: eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925137032Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Upstairs opts: Upstairs UUID: f5577520-9e2c-4ca5-8596-714d5f924dd9, 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-03T17:21:23.925154498Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Crucible stats registered with UUID: f5577520-9e2c-4ca5-8596-714d5f924dd9","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925161711Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
Crucible runtime is spawned
{"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925268144Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452}
{"msg":"f5577520-9e2c-4ca5-8596-714d5f924dd9 active request set","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.92537105Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.92537975Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925401333Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925414316Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925427764Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925440779Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925453017Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925464871Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"io task","client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925483947Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"io task","client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925497627Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"io task","client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925666022Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"io task","client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925687976Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"io task","client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.925701784Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"io task","client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.926121481Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.926141849Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.926256809Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.926276114Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.926293813Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.926306254Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.926932242Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.927002459Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.92706556Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.938998641Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939015498Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939023526Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939142293Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939152001Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939159562Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939534762Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939545235Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939552727Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939565147Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939572946Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939580206Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939587323Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939594607Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.93960182Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939609173Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"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-03T17:21:23.939616322Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939623345Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.93963058Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939637764Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939644849Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"":"downstairs","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939652694Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939664586Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"0","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.93967671Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"1","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
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-03T17:21:23.939699426Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"client":"2","":"downstairs","session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939712166Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.93972359Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"f5577520-9e2c-4ca5-8596-714d5f924dd9 is now active with session: eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939735029Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939745443Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452,"session_id":"eeb8d3ac-ddcd-49e4-bc7e-859f7c03c4cd"}
{"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:23.939754766Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452}
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: 263983 263982 263981 263980 263979
Upstairs last five completed:   262984 262983 262982 262981 262980
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-03T17:28:24.534673265Z","hostname":"ip-10-150-1-120.us-west-2.compute.internal","pid":1452}