crucible pantry and agent log in unparseable text instead of bunyan format

[davepacheco]

Elsewhere we've used the bunyan format for logs, and I think it's been pretty essential to be able to parse them while debugging. I noticed in dogfood that the crucible pantry logs appear to be plaintext:

# tail /var/svc/log/oxide-crucible-pantry:default.log.0
May 11 05:45:06.427 INFO request completed, response_code: 204, uri: /crucible/pantry/0/volume/ff78438f-2fa4-4043-bc41-f4e710372386/bulk_write, method: POST, req_id: 0c5bd64c-ecd7-4b88-a02b-0bf64319df38, remote_addr: [fd00:1122:3344:10c::4]:58630, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot
May 11 05:45:06.452 INFO accepted connection, remote_addr: [fd00:1122:3344:10c::4]:62739, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot
May 11 05:45:06.465 INFO request completed, response_code: 204, uri: /crucible/pantry/0/volume/ff78438f-2fa4-4043-bc41-f4e710372386/bulk_write, method: POST, req_id: dff3794e-dc39-414a-b282-890228e1529c, remote_addr: [fd00:1122:3344:10c::4]:62739, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot
May 11 05:45:06.528 INFO accepted connection, remote_addr: [fd00:1122:3344:10c::4]:60532, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot
May 11 05:45:06.530 INFO accepted connection, remote_addr: [fd00:1122:3344:10c::4]:47171, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot
May 11 05:45:06.545 INFO request completed, response_code: 204, uri: /crucible/pantry/0/volume/ff78438f-2fa4-4043-bc41-f4e710372386/bulk_write, method: POST, req_id: 255d96e1-3935-4764-8ab4-223804127c57, remote_addr: [fd00:1122:3344:10c::4]:60532, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot
May 11 05:45:06.557 INFO request completed, response_code: 204, uri: /crucible/pantry/0/volume/ff78438f-2fa4-4043-bc41-f4e710372386/bulk_write, method: POST, req_id: 10c47072-0c30-4637-b62c-b8dd9c3c0550, remote_addr: [fd00:1122:3344:10c::4]:47171, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot
May 11 05:45:07.824 INFO accepted connection, remote_addr: [fd00:1122:3344:10c::4]:37102, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshotMay 11 05:45:07.825 INFO flush with snap requested

May 11 05:45:07.932 INFO request completed, response_code: 204, uri: /crucible/pantry/0/volume/ff78438f-2fa4-4043-bc41-f4e710372386/snapshot, method: POST, req_id: b1d8e67b-97a7-470b-ba4e-10c02391631e, remote_addr: [fd00:1122:3344:10c::4]:37102, local_addr: [fd00:1122:3344:10c::12]:17000, component: dropshot

I'm not sure but this looks like what you might get if you're using dropshot's ConfigLogging::StderrTerminal instead of ConfigLogging::File.

I'm not sure if this is also why some of the log records appear to be running into each other (notice the May 11 05:45:07.825 in the middle of a line, and then two newlines in a row later).

[davepacheco]

(while debugging oxidecomputer/omicron#3085)

[davepacheco]

Looks like that applies to the agent, too: oxidecomputer/omicron#3085 (comment)