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(1451)
[8810][0] reports Running
Downstairs /var/tmp/dsc/8830 port 8830 PID:Some(1452)
[8830][2] reports Running
Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1453)
Feb 13 21:40:37.835 INFO[8820][1] reports Running
 listening, local_addr: 127.0.0.1:9998
Control access at:127.0.0.1:9998
Feb 13 21:40:42.874 INFO accepted connection, remote_addr: 127.0.0.1:59648, 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 13 21:40:42.874 INFO request completed, latency_us: 114, response_code: 204, uri: [8810] Disable keep_running
/disablerestart/all[8820] Disable keep_running
, method: POST, req_id: a52fefed-000f-4c0c-86c8-487c12c7091e, remote_addr: [8830] Disable keep_running
127.0.0.1:59648, local_addr: 127.0.0.1:9998
Feb 13 21:44:39.453 INFO accepted connection, remote_addr: 127.0.0.1:65128, local_addr: 127.0.0.1:9998
Main task has work to do, go find it
got dsc Shutdown
Shutdown
Shut it down
Feb 13 21:44:39.453[8810] Disable keep_running
 [8810] Got stop action so:false kr:false
INFO[8830] Disable keep_running
 [8830] Got stop action so:false kr:false
request completed[8820] Disable keep_running
, [8820] Got stop action so:false kr:false
latency_us: 45, response_code: 204, uri: /shutdown, method: POST, req_id: 749b772c-e164-41f5-af2c-8e6f4814926e, remote_addr: 127.0.0.1:65128, local_addr: 127.0.0.1:9998
[8830] Exited with: ExitStatus(unix_wait_status(9))
[8830][2] reports Exit
[8820] Exited with: ExitStatus(unix_wait_status(9))
[8810] Exited with: ExitStatus(unix_wait_status(9))
[8820][1] reports Exit
[8810][0] reports Exit
e":"2024-02-13T21:40:42.886014909Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456}
{"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886024358Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456}
{"msg":"Crucible fb52ff55-130c-4bb3-beeb-ed5ddf28e222 has session id: c1a154a9-01ec-42ed-b38e-92aaf9edc58c","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886031897Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Upstairs opts: Upstairs UUID: fb52ff55-130c-4bb3-beeb-ed5ddf28e222, 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-13T21:40:42.886041747Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Crucible stats registered with UUID: fb52ff55-130c-4bb3-beeb-ed5ddf28e222","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886046136Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886050016Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456}
{"msg":"fb52ff55-130c-4bb3-beeb-ed5ddf28e222 active request set","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886053525Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886057235Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886068024Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886072804Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886077143Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886081323Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886085532Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886132178Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"io task","client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886141017Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"io task","client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886145726Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"io task","client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886237098Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"io task","client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886246597Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"io task","client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886325989Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"io task","client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886548608Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886561086Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886607632Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886614151Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886654317Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.886660587Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.886859668Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.886918162Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.886924962Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893563533Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893574282Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893579622Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893583591Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893587881Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893592071Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893676982Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893683332Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.893687732Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.893694711Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.89369932Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.89370372Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.893707959Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.893712239Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.893716419Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.893720538Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"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-13T21:40:42.893724778Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893729008Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893733207Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893737487Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893741716Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893745956Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893749655Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893753865Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893760174Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893764604Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893768464Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal"Wait for a query_work_queue command to finish before sending IO
,"pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"fb52ff55-130c-4bb3-beeb-ed5ddf28e222 is now active with session: c1a154a9-01ec-42ed-b38e-92aaf9edc58c","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893775553Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893779303Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456,"session_id":"c1a154a9-01ec-42ed-b38e-92aaf9edc58c"}
{"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-13T21:40:42.893783032Z","hostname":"ip-10-150-1-241.us-west-2.compute.internal","pid":1456}
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: 263613 263612 263611 263610 263609
Upstairs last five completed:   262614 262613 262612 262611 262610
CLIENT: Up:0 ds:0 act:3
CLIENT: All crucible jobs finished, exiting program