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
Starting downstairs at port 8830
[8810][0] reports Starting
Make output file at "/tmp/dsc/downstairs-8830.txt"
Make output file at "/tmp/dsc/downstairs-8820.txt"
[8820][1] reports Starting
[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 06 22:14:46.279 INFO listening, local_addr: 127.0.[8820][1] reports Running
0.1:9998
Control access at:127.0.0.1:9998
Feb 06 22:14:51.316 INFO accepted connection, remote_addr: 127.0.0.1:52684, 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 06 22:14:51.317 INFO request completed, latency_us: 103, [8810] Disable keep_running
response_code[8820] Disable keep_running
: [8830] Disable keep_running
204, uri: /disablerestart/all, method: POST, req_id: ef63a307-56f9-4bfc-ac8f-ced6b05e9bc7, remote_addr: 127.0.0.1:52684, local_addr: 127.0.0.1:9998
Feb 06 22:18:33.898 INFO accepted connection, remote_addr: 127.0.0.1:40133, local_addr: 127.0.0.1:9998
Main task has work to do, go find it
got dsc Shutdown
Shutdown
Feb 06 22:18:33.899 INFO request completed[8810] Disable keep_running
, Shut it down
latency_us[8830] Disable keep_running
:[8830] Got stop action so:false kr:false
 45, response_code: 204, uri: /shutdown[8820] Disable keep_running
, method:[8820] Got stop action so:false kr:false
 POST, req_id: 4dd3ae7c-7d95-484d-bf37-90a3a35b2e94, remote_addr: 127.0.0.1:40133, local_addr: 127.0.0.1:9998
[8810] Got stop action so:false kr:false
[8830] Exited with: ExitStatus(unix_wait_status(9))
[8820] Exited with: ExitStatus(unix_wait_status(9))
[8810] Exited with: ExitStatus(unix_wait_status(9))
[8830][2] reports Exit
[8820][1] reports Exit
[8810][0] reports Exit
4333Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456}
{"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328420573Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456}
{"msg":"Crucible f29da1ae-c018-4f56-beec-a1be8ff82c81 has session id: bc5a40dd-5f86-4db0-ac3a-68392c375d55","v":0,"Crucible runtime is spawned
name":"crucible","level":30,"time":"2024-02-06T22:14:51.328436143Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Upstairs opts: Upstairs UUID: f29da1ae-c018-4f56-beec-a1be8ff82c81, 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-06T22:14:51.328445543Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Crucible stats registered with UUID: f29da1ae-c018-4f56-beec-a1be8ff82c81","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328450043Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328458583Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456}
{"msg":"f29da1ae-c018-4f56-beec-a1be8ff82c81 active request set","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328531694Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328537524Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328550605Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328555514Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328559905Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328564035Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328568215Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328572395Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"io task","client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328581295Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"io task","client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328635106Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"io task","client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328661406Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"io task","client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328734347Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"io task","client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.328751107Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"io task","client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.32899005Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.32899783Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.32905027Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.329061971Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.329073381Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.329081071Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.329375774Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.329388314Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.329461605Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337082375Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337091835Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337096775Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337100565Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337104985Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337109095Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337112775Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337116875Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337121605Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337126115Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337134466Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337139446Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337143906Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337148236Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337152596Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337157186Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"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-06T22:14:51.337161446Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337165646Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337169856Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337174006Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337178186Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"":"downstairs","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337182386Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337186036Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"0","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337190286Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"1","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337196186Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"client":"2","":"downstairs","session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337200446Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
,"time":"2024-02-06T22:14:51.337204186Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"f29da1ae-c018-4f56-beec-a1be8ff82c81 is now active with session: bc5a40dd-5f86-4db0-ac3a-68392c375d55","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337211826Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337215776Z","hostname":"ip-10-150-1-71.us-west-2.compute.internal","pid":1456,"session_id":"bc5a40dd-5f86-4db0-ac3a-68392c375d55"}
{"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:51.337219527Z","hostname":"ip-10-150-1-71.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: 263586 263585 263584 263583 263582
Upstairs last five completed:   262587 262586 262585 262584 262583
CLIENT: Up:0 ds:0 act:3
CLIENT: All crucible jobs finished, exiting program