Support #17285

keep1.9tee4 lost a disk

Added by Ward Vandewege 9 months ago. Updated 9 months ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Category:
-
Target version:
Start date:
Due date:
% Done:

0%

Estimated time:
Story points:
-

History

#1 Updated by Ward Vandewege 9 months ago

  • Status changed from New to In Progress

#2 Updated by Ward Vandewege 9 months ago

A keep disk died on keep1.9tee4. The remaining disks have plenty of free space. I removed it from the arvados config and ran keep-balance:

Jan 22 15:20:36 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"collections: 704164/704164","time":"2021-01-22T15:20:36.713108164Z"}
Jan 22 15:20:36 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"collections: 704164/704164","time":"2021-01-22T15:20:36.731525108Z"}
Jan 22 15:20:37 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"get_state: took 1345.995934833s","time":"2021-01-22T15:20:37.123123882Z"}
Jan 22 15:20:37 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"changeset_compute: start","time":"2021-01-22T15:20:37.123772806Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"changeset_compute: took 6.971601036s","time":"2021-01-22T15:20:44.095392634Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"===","time":"2021-01-22T15:20:44.095476559Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"16487 replicas (16487 blocks, 518435516 bytes) lost (0=have\u003cwant)","time":"2021-01-22T15:20:44.095521510Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"54976 replicas (54976 blocks, 827709689766 bytes) underreplicated (0\u003chave\u003cwant)","time":"2021-01-22T15:20:44.095552726Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"869374 replicas (434687 blocks, 2895181251366 bytes) just right (have=want)","time":"2021-01-22T15:20:44.095576689Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) overreplicated (have\u003ewant\u003e0)","time":"2021-01-22T15:20:44.095604669Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"24 replicas (24 blocks, 908950 bytes) unreferenced (have\u003ewant=0, new)","time":"2021-01-22T15:20:44.095632600Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) garbage (have\u003ewant=0, old)","time":"2021-01-22T15:20:44.095653930Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"===","time":"2021-01-22T15:20:44.095679008Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"storage class \"default\": 924350 replicas (489663 blocks, 3722890941132 bytes) needed","time":"2021-01-22T15:20:44.100022835Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"storage class \"default\": 24 replicas (24 blocks, 908950 bytes) unneeded","time":"2021-01-22T15:20:44.100083377Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"storage class \"default\": 54976 replicas (54976 blocks, 827709689766 bytes) pulling","time":"2021-01-22T15:20:44.100113822Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"storage class \"default\": 16487 replicas (16487 blocks, 518435516 bytes) unachievable","time":"2021-01-22T15:20:44.100143703Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"===","time":"2021-01-22T15:20:44.100162842Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"924350 replicas (489663 blocks, 3722890941132 bytes) total commitment (excluding unreferenced)","time":"2021-01-22T15:20:44.100191883Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"924374 replicas (489687 blocks, 3722891850082 bytes) total usage","time":"2021-01-22T15:20:44.100225129Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"===","time":"2021-01-22T15:20:44.100243056Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"9tee4-bi6l4-1fum8ggyzc88g87 (keep1.9tee4.arvadosapi.com:25107, disk): ChangeSet{Pulls:54976, Trashes:0}\n","time":"2021-01-22T15:20:44.100326077Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"9tee4-bi6l4-uwgvqzzw4z97qca (keep0.9tee4.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0}\n","time":"2021-01-22T15:20:44.100359485Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"===","time":"2021-01-22T15:20:44.100383706Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"Replication level distribution:","time":"2021-01-22T15:20:44.100409128Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":" 0:  16487 ############################################","time":"2021-01-22T15:20:44.100439312Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":" 1:  55000 #################################################","time":"2021-01-22T15:20:44.100460292Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":" 2: 434687 ###########################################################","time":"2021-01-22T15:20:44.100488010Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"===","time":"2021-01-22T15:20:44.100506086Z"}
Jan 22 15:20:44 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"send_pull_lists: start","time":"2021-01-22T15:20:44.539121981Z"}
Jan 22 15:20:45 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"send_pull_lists: took 0.633789786s","time":"2021-01-22T15:20:45.172930331Z"}
Jan 22 15:20:45 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"send_trash_lists: start","time":"2021-01-22T15:20:45.173013006Z"}
Jan 22 15:20:45 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"send_trash_lists: took 0.001106095s","time":"2021-01-22T15:20:45.174135997Z"}
Jan 22 15:20:45 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"sweep: took 1354.263222403s","time":"2021-01-22T15:20:45.174247301Z"}
Jan 22 15:20:45 9tee4.arvadosapi.com keep-balance[19927]: {"PID":19927,"level":"info","msg":"run succeeded","time":"2021-01-22T15:20:45.174267167Z"}

Compare with a previous run, before the disk died, and you can see the lost blocks were already lost (this is a very old test cluster):

Jan 21 17:24:44 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"collections: 703622/703622","time":"2021-01-21T17:24:44.364856139Z"}
Jan 21 17:24:44 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"collections: 703622/703622","time":"2021-01-21T17:24:44.385146912Z"}
Jan 21 17:24:44 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"get_state: took 1382.943961558s","time":"2021-01-21T17:24:44.722827072Z"}
Jan 21 17:24:44 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"changeset_compute: start","time":"2021-01-21T17:24:44.722962754Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"changeset_compute: took 7.352897402s","time":"2021-01-21T17:24:52.075879262Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"===","time":"2021-01-21T17:24:52.075967767Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"16487 replicas (16487 blocks, 518435516 bytes) lost (0=have\u003cwant)","time":"2021-01-21T17:24:52.076012176Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) underreplicated (0\u003chave\u003cwant)","time":"2021-01-21T17:24:52.076045268Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"978560 replicas (489280 blocks, 4550577175872 bytes) just right (have=want)","time":"2021-01-21T17:24:52.076067271Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) overreplicated (have\u003ewant\u003e0)","time":"2021-01-21T17:24:52.076094737Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) unreferenced (have\u003ewant=0, new)","time":"2021-01-21T17:24:52.076122511Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) garbage (have\u003ewant=0, old)","time":"2021-01-21T17:24:52.076143214Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"===","time":"2021-01-21T17:24:52.076167476Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"storage class \"default\": 978560 replicas (489280 blocks, 4550577175872 bytes) needed","time":"2021-01-21T17:24:52.076198435Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"storage class \"default\": 0 replicas (0 blocks, 0 bytes) unneeded","time":"2021-01-21T17:24:52.076218881Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"storage class \"default\": 0 replicas (0 blocks, 0 bytes) pulling","time":"2021-01-21T17:24:52.076250241Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"storage class \"default\": 16487 replicas (16487 blocks, 518435516 bytes) unachievable","time":"2021-01-21T17:24:52.076278293Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"===","time":"2021-01-21T17:24:52.076297007Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"978560 replicas (489280 blocks, 4550577175872 bytes) total commitment (excluding unreferenced)","time":"2021-01-21T17:24:52.076323763Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"978560 replicas (489280 blocks, 4550577175872 bytes) total usage","time":"2021-01-21T17:24:52.076351345Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"===","time":"2021-01-21T17:24:52.076369170Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"9tee4-bi6l4-1fum8ggyzc88g87 (keep1.9tee4.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0}\n","time":"2021-01-21T17:24:52.076401620Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"9tee4-bi6l4-uwgvqzzw4z97qca (keep0.9tee4.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0}\n","time":"2021-01-21T17:24:52.076431994Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"===","time":"2021-01-21T17:24:52.076449788Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"Replication level distribution:","time":"2021-01-21T17:24:52.076473834Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":" 0:  16487 ############################################","time":"2021-01-21T17:24:52.076497190Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":" 1:      0 ","time":"2021-01-21T17:24:52.076524303Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":" 2: 489280 ###########################################################","time":"2021-01-21T17:24:52.076549889Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"===","time":"2021-01-21T17:24:52.076567117Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"send_pull_lists: start","time":"2021-01-21T17:24:52.512516545Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"send_pull_lists: took 0.002966203s","time":"2021-01-21T17:24:52.515482544Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"send_trash_lists: start","time":"2021-01-21T17:24:52.515618393Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"send_trash_lists: took 0.001134535s","time":"2021-01-21T17:24:52.516757031Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"sweep: took 1390.788955814s","time":"2021-01-21T17:24:52.516817968Z"}
Jan 21 17:24:52 9tee4.arvadosapi.com keep-balance[31759]: {"PID":31759,"level":"info","msg":"run succeeded","time":"2021-01-21T17:24:52.516837703Z"}

I'll just let the keepstore on keep1 process its pull list.

#3 Updated by Ward Vandewege 9 months ago

Making progress:

Jan 22 22:22:09 9tee4.arvadosapi.com keep-balance[29947]: {"PID":29947,"level":"info","msg":"===","time":"2021-01-22T22:22:09.563610424Z"}
Jan 22 22:22:09 9tee4.arvadosapi.com keep-balance[29947]: {"PID":29947,"level":"info","msg":"Replication level distribution:","time":"2021-01-22T22:22:09.563634352Z"}
Jan 22 22:22:09 9tee4.arvadosapi.com keep-balance[29947]: {"PID":29947,"level":"info","msg":" 0:  16487 ############################################","time":"2021-01-22T22:22:09.563666784Z"}
Jan 22 22:22:09 9tee4.arvadosapi.com keep-balance[29947]: {"PID":29947,"level":"info","msg":" 1:  16961 ############################################","time":"2021-01-22T22:22:09.563693267Z"}
Jan 22 22:22:09 9tee4.arvadosapi.com keep-balance[29947]: {"PID":29947,"level":"info","msg":" 2: 473492 ###########################################################","time":"2021-01-22T22:22:09.563713473Z"}
Jan 22 22:22:09 9tee4.arvadosapi.com keep-balance[29947]: {"PID":29947,"level":"info","msg":"===","time":"2021-01-22T22:22:09.563741069Z"}

#4 Updated by Ward Vandewege 9 months ago

  • Status changed from In Progress to Resolved

All set now:

Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"===","time":"2021-01-23T14:14:20.627497212Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"16487 replicas (16487 blocks, 518435516 bytes) lost (0=have\u003cwant)","time":"2021-01-23T14:14:20.627886940Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) underreplicated (0\u003chave\u003cwant)","time":"2021-01-23T14:14:20.627922969Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"980858 replicas (490429 blocks, 4550647769776 bytes) just right (have=want)","time":"2021-01-23T14:14:20.627942401Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) overreplicated (have\u003ewant\u003e0)","time":"2021-01-23T14:14:20.627961506Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"24 replicas (24 blocks, 908950 bytes) unreferenced (have\u003ewant=0, new)","time":"2021-01-23T14:14:20.627979586Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"0 replicas (0 blocks, 0 bytes) garbage (have\u003ewant=0, old)","time":"2021-01-23T14:14:20.627998734Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"===","time":"2021-01-23T14:14:20.628014955Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"storage class \"default\": 980858 replicas (490429 blocks, 4550647769776 bytes) needed","time":"2021-01-23T14:14:20.628035943Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"storage class \"default\": 24 replicas (24 blocks, 908950 bytes) unneeded","time":"2021-01-23T14:14:20.628055074Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"storage class \"default\": 0 replicas (0 blocks, 0 bytes) pulling","time":"2021-01-23T14:14:20.628073565Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"storage class \"default\": 16487 replicas (16487 blocks, 518435516 bytes) unachievable","time":"2021-01-23T14:14:20.628098417Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"===","time":"2021-01-23T14:14:20.628113796Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"980858 replicas (490429 blocks, 4550647769776 bytes) total commitment (excluding unreferenced)","time":"2021-01-23T14:14:20.629660108Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"980882 replicas (490453 blocks, 4550648678726 bytes) total usage","time":"2021-01-23T14:14:20.629695422Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"===","time":"2021-01-23T14:14:20.629712341Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"9tee4-bi6l4-uwgvqzzw4z97qca (keep0.9tee4.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0}\n","time":"2021-01-23T14:14:20.629737150Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"9tee4-bi6l4-1fum8ggyzc88g87 (keep1.9tee4.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0}\n","time":"2021-01-23T14:14:20.629756267Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"===","time":"2021-01-23T14:14:20.629772821Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"Replication level distribution:","time":"2021-01-23T14:14:20.629807039Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":" 0:  16487 ############################################","time":"2021-01-23T14:14:20.629827598Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":" 1:     24 ##############","time":"2021-01-23T14:14:20.629846714Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":" 2: 490429 ###########################################################","time":"2021-01-23T14:14:20.629864739Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"===","time":"2021-01-23T14:14:20.629881799Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"send_pull_lists: start","time":"2021-01-23T14:14:20.935396774Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"send_pull_lists: took 0.004799194s","time":"2021-01-23T14:14:20.940198316Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"send_trash_lists: start","time":"2021-01-23T14:14:20.940254430Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"send_trash_lists: took 0.000838082s","time":"2021-01-23T14:14:20.941104082Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"sweep: took 1360.876776388s","time":"2021-01-23T14:14:20.941197409Z"}
Jan 23 14:14:20 9tee4.arvadosapi.com keep-balance[17404]: {"PID":17404,"level":"info","msg":"run succeeded","time":"2021-01-23T14:14:20.941216520Z"}

Also available in: Atom PDF