dns tests log to stdout/stderr

[davepacheco]

cargo test on something close to "main" includes:

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running unittests src/bin/dns-server.rs (target/debug/deps/dns_server-631e9e3a107ee037)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running unittests src/bin/dnsadm.rs (target/debug/deps/dnsadm-128f4764df480da8)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/basic_test.rs (target/debug/deps/basic_test-f5371bc7d2fec5f9)

running 6 tests
Jun 23 23:04:20.695Jun 23 23:04:20.695Jun 23 23:04:20.695   Jun 23 23:04:20.695Jun 23 23:04:20.695  Jun 23 23:04:20.695 INFOINFOINFOINFOINFO   listeninglisteninglistening listening , , listening, , local_addr, local_addrlocal_addrlocal_addr:::   [[[local_addr::1::1::1]:]:64251:]:3940251917
 

[::1]:33474INFO
:  listening[::1]:44640, 
local_addr: [::1]:61184
Jun 23 23:04:21.005Jun 23 23:04:21.005  Jun 23 23:04:21.005Jun 23 23:04:21.005INFO INFO  INFO accepted connectionaccepted connectionINFO , , remote_addrremote_addraccepted connection ::, accepted connectionremote_addr :,  remote_addr[::1]:59491[::1]:61294:, local_addr , :[::1]:47204 , [local_addr::1]:local_addr51917:
:  [::1[]:::133474]:64251

 [::1]:52959, local_addr: [::1]:39402
Jun 23 23:04:21.007 Jun 23 23:04:21.007INFO  INFOrequest completedJun 23 23:04:21.007,   response_code:request completedINFO 200 , , request completeduri:, response_code response_code/get-records, ::method : 200 GET, , urireq_id200::  , 653f25f7-eca3-493a-b811-a623ab3fd66e/get-records, remote_addr, uri:method [:::1:]:59491  , GETlocal_addr/get-records:,  req_id[, ::1:]:51917method 
:3d0cdce4-2ee0-4796-b1af-22b6cbc32349 , GETremote_addr, :req_id :[ ::1]:2c096c45-d37a-4af3-9c65-91199ed0aa1c47204, , remote_addr:local_addr :[ ::1]:[52959::1]:, 64251local_addr
: [::1]:39402Jun 23 23:04:21.007
 INFO request completed, response_code: 200, uri: /get-records, method: GET, req_id:test servfail ...  okf199dab1-e138-4bbb-ba79-18fe305f30ee
, remote_addr: [::1]:61294, local_addr: [::1]:33474
test nxdomain ... ok
Jun 23 23:04:21.009 Jun 23 23:04:21.009Jun 23 23:04:21.009INFO   Jun 23 23:04:21.009INFOrequest completed, INFO  response_code :INFOrequest completed ,  200response_code, :request completeduri :200,  , uri/set-recordsresponse_code:,  method:/set-records:, method  :PUT PUT, 200, req_idreq_id::,   57002f6c-4db3-4c51-9ca7-109517d18781c7733199-2fe3-4683-a596-9786f6fbb14furi, , remote_addrremote_addr:: :[::1 ]: 59491[, ::1]:local_addr52959:, /set-records local_addr[::1]::51917, 
 method[::1:]:39402 Jun 23 23:04:21.009
PUT , INFOreq_id Jun 23 23:04:21.009:request completed  , response_codeINFO34bfaaeb-e1d8-46c8-b0d6-cabb7fa5994f:  request completed200, , , uriresponse_code:remote_addr :/get-records :200, method,  :uri :GET[,  ::1req_id/get-records]::, 47204 methoddf0cfc87-6458-4300-a6e0-ef09f0225606:,  remote_addrGET:request completed , [, ::1req_id]:59491:, response_codelocal_addr :02b33a81-a529-4ac5-b2fa-ca7315be416a :[, ::1]:51917remote_addr :
200 , , [local_addruri:::1: ]: [52959::1]:/set-records64251
, , methodlocal_addrJun 23 23:04:21.010::  INFO PUT request completed, [, req_id::1response_code:]::  3940220087c5ddc3-124a-4ffc-a89e-e42c5985d96b, , uri
:remote_addr :/get-records,  Jun 23 23:04:21.010method[:::1]: 61294GET, , req_idlocal_addr::  dc87f028-422c-4501-b3f6-78576d06f82b[, ::1]:remote_addr33474:  
[ERRO::1]:47204 , No records found for devron.oxide.internalJun 23 23:04:21.010local_addr: 
 INFO[::1]: 64251request completed
, response_codeJun 23 23:04:21.011:  INFO200 , received request to begin graceful shutdownuri, :local_addr :/get-records , [::1]:method64251:
 GET, req_id: Jun 23 23:04:21.011956eeaf6-2c92-4bcc-becc-45ec301a18a3 , ERROremote_addr :No records found for devron.oxide.internal 
[::1]:61294, local_addr: [::1]:33474
Jun 23 23:04:21.011Jun 23 23:04:21.011 Jun 23 23:04:21.011  INFOINFO  received request to begin graceful shutdownreceived request to begin graceful shutdown, , local_addrlocal_addr::  [[::1::1]:]:3347439402

INFO received request to begin graceful shutdown, local_addr: [::1]:51917
test srv_crud ... ok
test multi_record_crud ... ok
test aaaa_crud ... ok
test empty_record ... ok

test result: ok. 6 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.46s

I think those log messages are coming from the DNS tests. I imagine they should do something similar to what we do for setting up Nexus, Sled Agent, Oximeter etc. where the log output goes to a LogContext created for the test. Besides cleaning up the terminal output, this separates the output from tests that are run concurrently, keeps the output around on disk if the test fails, and also creates a combined log for everything in the test.