Actions
Bug #21254
closed
keep-balance TestRunForever is racey
Status:
Resolved
Priority:
Normal
Assigned To:
Category:
Tests
Target version:
Story points:
-
Release:
Release relationship:
Auto
Description
---------------------------------------------------------------------- FAIL: balance_run_test.go:626: runSuite.TestRunForever time="2023-12-01T16:12:59.498333882Z" level=info msg="acquiring service lock" time="2023-12-01T16:12:59.502981282Z" level=info msg="starting up: will scan every 1ms and on SIGUSR1" time="2023-12-01T16:12:59.503086322Z" level=info msg="acquiring active lock" time="2023-12-01T16:12:59.507383962Z" level=info msg="sweep: start" time="2023-12-01T16:12:59.507475162Z" level=info msg="skipping zzzzz-bi6l4-h0a0xwut9qa6g3a with service type \"proxy\"" time="2023-12-01T16:12:59.507625422Z" level=info msg="clearing existing trash lists, in case the new rendezvous order differs from previous run" time="2023-12-01T16:12:59.507637742Z" level=info msg="send_trash_lists: start" time="2023-12-01T16:12:59.507729922Z" level=info msg="send_trash_lists: took 8.984e-05s" time="2023-12-01T16:12:59.507745142Z" level=info msg="get_state: start" time="2023-12-01T16:12:59.507796493Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.507822133Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.507829242Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.507830262Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.507834573Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.507849442Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.507857102Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.507884102Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.507890993Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.507902693Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.507911482Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): add 2 entries to map" time="2023-12-01T16:12:59.507919333Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): added 2 entries to map at 1x (2 replicas)" time="2023-12-01T16:12:59.507925093Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.507940293Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.507946173Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.507958922Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.508212042Z" level=info msg="heap 4661248 stack 819200 heapalloc 2625568 virt 1351573504 res 27389952" time="2023-12-01T16:12:59.514064253Z" level=info msg="collections: 293/3" time="2023-12-01T16:12:59.514127573Z" level=info msg="get_state: took 0.0063806s" time="2023-12-01T16:12:59.514141513Z" level=info msg="changeset_compute: start" time="2023-12-01T16:12:59.514189002Z" level=info msg="6a4ff0499484c6c79c95cd8c566bd25f+249025 refs=3 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.514199333Z" level=info msg="cdd549ae79fe6640fa3d5c6261d8303c+195 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.514221902Z" level=info msg="d21353cfe035e3e384563ee55eadbb2f+67108864 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.514210302Z" level=info msg="acbd18db4cc2f85cedef654fccc4a4d8+3 refs=6 needed=2 unneeded=2 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=stay,12345679000000000 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345680000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=trash,12345681000000000 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=trash,12345682000000000]" time="2023-12-01T16:12:59.514251633Z" level=info msg="5c77a43e329b9838cbec18ff42790e57+55605760 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.514269542Z" level=info msg="92b53930db60fe94be2a73fc771ba921+34 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.514271222Z" level=info msg="85877ca2d7e05498dd3d109baf2df106+95 refs=5 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.514284993Z" level=info msg="56ac2557b1ded11ccab7293dc47d1e88+44 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.514290202Z" level=info msg="4c6c2c0ac8aa0696edd7316a3be5ca3c+5 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.514223253Z" level=info msg="73feffa4b7f6bb68e44cf984c85f6e88+3 refs=220 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.514209942Z" level=info msg="8c12f5f5297b7337598170c6f531fcee+7882 refs=14 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.514305693Z" level=info msg="fca529cfe035e3e384563ee55eadbb2f+67108863 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.514313813Z" level=info msg="8258b505536a9ab47baa2f4281cb932a+9 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.514321362Z" level=info msg="37b51d194a7513e45b56f6524f2d51f2+3 refs=32 needed=1 unneeded=0 pulling=2 map[archive:2 default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=pull,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=pull,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345678000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.514326713Z" level=info msg="4d20280d5e516a0109768d49ab0f3318+3 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.514330233Z" level=info msg="f0ef7081e1539ac00ef5b761b4fb01b3+12 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.514335482Z" level=info msg="3858f62230ac3c915f300c664312c63f+6 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.514338202Z" level=info msg="29d7797f1888013986899bc9083783fa+3 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.514342042Z" level=info msg="2bbc341c702df4d8f42ec31f16c10120+64 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.514683662Z" level=info msg="changeset_compute: took 0.000539369s" time="2023-12-01T16:12:59.514692353Z" level=info msg="===" time="2023-12-01T16:12:59.514698422Z" level=info msg="17 replicas (17 blocks, 190080867 bytes) lost (0=have<want)" time="2023-12-01T16:12:59.514706073Z" level=info msg="2 replicas (1 blocks, 6 bytes) underreplicated (0<have<want)" time="2023-12-01T16:12:59.514710593Z" level=info msg="0 replicas (0 blocks, 0 bytes) just right (have=want)" time="2023-12-01T16:12:59.514715222Z" level=info msg="2 replicas (1 blocks, 6 bytes) overreplicated (have>want>0)" time="2023-12-01T16:12:59.514721122Z" level=info msg="0 replicas (0 blocks, 0 bytes) unreferenced (have>want=0, new)" time="2023-12-01T16:12:59.514725362Z" level=info msg="0 replicas (0 blocks, 0 bytes) garbage (have>want=0, old)" time="2023-12-01T16:12:59.514730442Z" level=info msg="===" time="2023-12-01T16:12:59.514734493Z" level=info msg="storage class \"default\": 3 replicas (2 blocks, 9 bytes) needed" time="2023-12-01T16:12:59.514739322Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) unneeded" time="2023-12-01T16:12:59.514782713Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) pulling" time="2023-12-01T16:12:59.514791513Z" level=info msg="storage class \"default\": 17 replicas (17 blocks, 190080867 bytes) unachievable" time="2023-12-01T16:12:59.514800293Z" level=info msg="===" time="2023-12-01T16:12:59.514829133Z" level=info msg="3 replicas (2 blocks, 9 bytes) total commitment (excluding unreferenced)" time="2023-12-01T16:12:59.514834082Z" level=info msg="5 replicas (2 blocks, 15 bytes) total usage" time="2023-12-01T16:12:59.514858253Z" level=info msg="===" time="2023-12-01T16:12:59.514959933Z" level=info msg="zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.514968222Z" level=info msg="zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.514973722Z" level=info msg="zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.514978553Z" level=info msg="zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.514982962Z" level=info msg="===" time="2023-12-01T16:12:59.514985633Z" level=info msg="Replication level distribution:" time="2023-12-01T16:12:59.514990593Z" level=info msg=" 0: 17 #########################################################" time="2023-12-01T16:12:59.514994413Z" level=info msg=" 1: 1 #############" time="2023-12-01T16:12:59.514997342Z" level=info msg=" 2: 0 " time="2023-12-01T16:12:59.514999993Z" level=info msg=" 3: 0 " time="2023-12-01T16:12:59.515002562Z" level=info msg=" 4: 1 #############" time="2023-12-01T16:12:59.515005222Z" level=info msg="===" time="2023-12-01T16:12:59.515025393Z" level=info msg="send_pull_lists: start" time="2023-12-01T16:12:59.515166082Z" level=info msg="send_pull_lists: took 0.000139s" time="2023-12-01T16:12:59.515172582Z" level=info msg="send_trash_lists: start" time="2023-12-01T16:12:59.515234313Z" level=info msg="send_trash_lists: took 5.988e-05s" time="2023-12-01T16:12:59.515242473Z" level=info msg="sweep: took 0.007859451s" time="2023-12-01T16:12:59.515501482Z" level=info msg="run succeeded" time="2023-12-01T16:12:59.515508373Z" level=info msg="timer went off" time="2023-12-01T16:12:59.515511433Z" level=info msg="starting next run" time="2023-12-01T16:12:59.515635593Z" level=info msg="acquiring active lock" time="2023-12-01T16:12:59.515836793Z" level=info msg="sweep: start" time="2023-12-01T16:12:59.515933702Z" level=info msg="skipping zzzzz-bi6l4-h0a0xwut9qa6g3a with service type \"proxy\"" time="2023-12-01T16:12:59.516119113Z" level=info msg="get_state: start" time="2023-12-01T16:12:59.516160882Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.516171413Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.516179342Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.516216013Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.516225282Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.516230753Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.516244882Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.516245193Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.516256273Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.516262133Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.516267373Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): add 2 entries to map" time="2023-12-01T16:12:59.516189942Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.516278862Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): added 2 entries to map at 1x (2 replicas)" time="2023-12-01T16:12:59.516282722Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.516284182Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.516288142Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.516477893Z" level=info msg="heap 4546560 stack 884736 heapalloc 1973688 virt 1351573504 res 27389952" time="2023-12-01T16:12:59.517448562Z" level=info msg="collections: 293/3" time="2023-12-01T16:12:59.517532872Z" level=info msg="get_state: took 0.001412309s" time="2023-12-01T16:12:59.517541252Z" level=info msg="changeset_compute: start" time="2023-12-01T16:12:59.517568562Z" level=info msg="fca529cfe035e3e384563ee55eadbb2f+67108863 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.517585382Z" level=info msg="3858f62230ac3c915f300c664312c63f+6 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.517593472Z" level=info msg="92b53930db60fe94be2a73fc771ba921+34 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.517600572Z" level=info msg="d21353cfe035e3e384563ee55eadbb2f+67108864 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.517615362Z" level=info msg="8258b505536a9ab47baa2f4281cb932a+9 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.517614712Z" level=info msg="5c77a43e329b9838cbec18ff42790e57+55605760 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.517616812Z" level=info msg="8c12f5f5297b7337598170c6f531fcee+7882 refs=14 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.517626732Z" level=info msg="37b51d194a7513e45b56f6524f2d51f2+3 refs=32 needed=1 unneeded=0 pulling=2 map[archive:2 default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=pull,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=pull,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345678000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.517638882Z" level=info msg="cdd549ae79fe6640fa3d5c6261d8303c+195 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.517640462Z" level=info msg="85877ca2d7e05498dd3d109baf2df106+95 refs=5 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.517654152Z" level=info msg="29d7797f1888013986899bc9083783fa+3 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.517665272Z" level=info msg="73feffa4b7f6bb68e44cf984c85f6e88+3 refs=220 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.517669182Z" level=info msg="4c6c2c0ac8aa0696edd7316a3be5ca3c+5 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.517689642Z" level=info msg="4d20280d5e516a0109768d49ab0f3318+3 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.517706072Z" level=info msg="f0ef7081e1539ac00ef5b761b4fb01b3+12 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.517651682Z" level=info msg="2bbc341c702df4d8f42ec31f16c10120+64 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.517725842Z" level=info msg="56ac2557b1ded11ccab7293dc47d1e88+44 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.517742982Z" level=info msg="6a4ff0499484c6c79c95cd8c566bd25f+249025 refs=3 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.517631432Z" level=info msg="acbd18db4cc2f85cedef654fccc4a4d8+3 refs=6 needed=2 unneeded=2 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=stay,12345684000000000 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345686000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=trash,12345683000000000 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=trash,12345685000000000]" time="2023-12-01T16:12:59.517762262Z" level=info msg="changeset_compute: took 0.00022006s" time="2023-12-01T16:12:59.517765712Z" level=info msg="===" time="2023-12-01T16:12:59.517769722Z" level=info msg="17 replicas (17 blocks, 190080867 bytes) lost (0=have<want)" time="2023-12-01T16:12:59.517773412Z" level=info msg="2 replicas (1 blocks, 6 bytes) underreplicated (0<have<want)" time="2023-12-01T16:12:59.517776842Z" level=info msg="0 replicas (0 blocks, 0 bytes) just right (have=want)" time="2023-12-01T16:12:59.517780112Z" level=info msg="2 replicas (1 blocks, 6 bytes) overreplicated (have>want>0)" time="2023-12-01T16:12:59.517783602Z" level=info msg="0 replicas (0 blocks, 0 bytes) unreferenced (have>want=0, new)" time="2023-12-01T16:12:59.517787062Z" level=info msg="0 replicas (0 blocks, 0 bytes) garbage (have>want=0, old)" time="2023-12-01T16:12:59.517790202Z" level=info msg="===" time="2023-12-01T16:12:59.517793212Z" level=info msg="storage class \"default\": 3 replicas (2 blocks, 9 bytes) needed" time="2023-12-01T16:12:59.517796972Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) unneeded" time="2023-12-01T16:12:59.517800542Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) pulling" time="2023-12-01T16:12:59.517805492Z" level=info msg="storage class \"default\": 17 replicas (17 blocks, 190080867 bytes) unachievable" time="2023-12-01T16:12:59.517809062Z" level=info msg="===" time="2023-12-01T16:12:59.517812032Z" level=info msg="3 replicas (2 blocks, 9 bytes) total commitment (excluding unreferenced)" time="2023-12-01T16:12:59.517815532Z" level=info msg="5 replicas (2 blocks, 15 bytes) total usage" time="2023-12-01T16:12:59.517818162Z" level=info msg="===" time="2023-12-01T16:12:59.517822582Z" level=info msg="zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.517827982Z" level=info msg="zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.517832552Z" level=info msg="zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.517836992Z" level=info msg="zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.517840612Z" level=info msg="===" time="2023-12-01T16:12:59.517842902Z" level=info msg="Replication level distribution:" time="2023-12-01T16:12:59.517846742Z" level=info msg=" 0: 17 #########################################################" time="2023-12-01T16:12:59.517850042Z" level=info msg=" 1: 1 #############" time="2023-12-01T16:12:59.517852792Z" level=info msg=" 2: 0 " time="2023-12-01T16:12:59.517855652Z" level=info msg=" 3: 0 " time="2023-12-01T16:12:59.517858212Z" level=info msg=" 4: 1 #############" time="2023-12-01T16:12:59.517860772Z" level=info msg="===" time="2023-12-01T16:12:59.517865402Z" level=info msg="send_pull_lists: start" time="2023-12-01T16:12:59.518002292Z" level=info msg="send_pull_lists: took 0.00013474s" time="2023-12-01T16:12:59.518008792Z" level=info msg="send_trash_lists: start" time="2023-12-01T16:12:59.518101202Z" level=info msg="send_trash_lists: took 9.066e-05s" time="2023-12-01T16:12:59.518109222Z" level=info msg="sweep: took 0.00227284s" time="2023-12-01T16:12:59.518311382Z" level=info msg="run succeeded" time="2023-12-01T16:12:59.518318042Z" level=info msg="timer went off" time="2023-12-01T16:12:59.518320962Z" level=info msg="starting next run" time="2023-12-01T16:12:59.518421472Z" level=info msg="acquiring active lock" time="2023-12-01T16:12:59.518587102Z" level=info msg="sweep: start" time="2023-12-01T16:12:59.518649982Z" level=info msg="skipping zzzzz-bi6l4-h0a0xwut9qa6g3a with service type \"proxy\"" time="2023-12-01T16:12:59.518822812Z" level=info msg="get_state: start" time="2023-12-01T16:12:59.518856252Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.518884662Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.518881742Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.518887412Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.518891062Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.518911532Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.518923712Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.518978952Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.518925882Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.518986222Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.518992072Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.518990552Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.518997912Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.518952702Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): add 2 entries to map" time="2023-12-01T16:12:59.519008902Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): added 2 entries to map at 1x (2 replicas)" time="2023-12-01T16:12:59.519014052Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.519564142Z" level=info msg="heap 5275648 stack 917504 heapalloc 3221856 virt 1351573504 res 27709440" time="2023-12-01T16:12:59.520756652Z" level=info msg="collections: 293/3" time="2023-12-01T16:12:59.520817022Z" level=info msg="get_state: took 0.00199287s" time="2023-12-01T16:12:59.520825302Z" level=info msg="changeset_compute: start" time="2023-12-01T16:12:59.520865362Z" level=info msg="d21353cfe035e3e384563ee55eadbb2f+67108864 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.520883202Z" level=info msg="3858f62230ac3c915f300c664312c63f+6 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.520883442Z" level=info msg="92b53930db60fe94be2a73fc771ba921+34 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.520889962Z" level=info msg="85877ca2d7e05498dd3d109baf2df106+95 refs=5 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.520906492Z" level=info msg="acbd18db4cc2f85cedef654fccc4a4d8+3 refs=6 needed=2 unneeded=2 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=stay,12345687000000000 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345689000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=trash,12345688000000000 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=trash,12345690000000000]" time="2023-12-01T16:12:59.520913472Z" level=info msg="4d20280d5e516a0109768d49ab0f3318+3 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.520912932Z" level=info msg="73feffa4b7f6bb68e44cf984c85f6e88+3 refs=220 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.520922662Z" level=info msg="5c77a43e329b9838cbec18ff42790e57+55605760 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.520935102Z" level=info msg="cdd549ae79fe6640fa3d5c6261d8303c+195 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.520937522Z" level=info msg="6a4ff0499484c6c79c95cd8c566bd25f+249025 refs=3 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.520937382Z" level=info msg="2bbc341c702df4d8f42ec31f16c10120+64 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.520949992Z" level=info msg="56ac2557b1ded11ccab7293dc47d1e88+44 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.520955222Z" level=info msg="4c6c2c0ac8aa0696edd7316a3be5ca3c+5 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.520956862Z" level=info msg="37b51d194a7513e45b56f6524f2d51f2+3 refs=32 needed=1 unneeded=0 pulling=2 map[archive:2 default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=pull,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=pull,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345678000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.520965152Z" level=info msg="f0ef7081e1539ac00ef5b761b4fb01b3+12 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.520972722Z" level=info msg="8c12f5f5297b7337598170c6f531fcee+7882 refs=14 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.520975652Z" level=info msg="fca529cfe035e3e384563ee55eadbb2f+67108863 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.520980342Z" level=info msg="29d7797f1888013986899bc9083783fa+3 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.520987042Z" level=info msg="8258b505536a9ab47baa2f4281cb932a+9 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.521000932Z" level=info msg="changeset_compute: took 0.00017429s" time="2023-12-01T16:12:59.521004112Z" level=info msg="===" time="2023-12-01T16:12:59.521008162Z" level=info msg="17 replicas (17 blocks, 190080867 bytes) lost (0=have<want)" time="2023-12-01T16:12:59.521012272Z" level=info msg="2 replicas (1 blocks, 6 bytes) underreplicated (0<have<want)" time="2023-12-01T16:12:59.521015922Z" level=info msg="0 replicas (0 blocks, 0 bytes) just right (have=want)" time="2023-12-01T16:12:59.521019332Z" level=info msg="2 replicas (1 blocks, 6 bytes) overreplicated (have>want>0)" time="2023-12-01T16:12:59.521022592Z" level=info msg="0 replicas (0 blocks, 0 bytes) unreferenced (have>want=0, new)" time="2023-12-01T16:12:59.521026082Z" level=info msg="0 replicas (0 blocks, 0 bytes) garbage (have>want=0, old)" time="2023-12-01T16:12:59.521028872Z" level=info msg="===" time="2023-12-01T16:12:59.521031762Z" level=info msg="storage class \"default\": 3 replicas (2 blocks, 9 bytes) needed" time="2023-12-01T16:12:59.521035342Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) unneeded" time="2023-12-01T16:12:59.521038842Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) pulling" time="2023-12-01T16:12:59.521042692Z" level=info msg="storage class \"default\": 17 replicas (17 blocks, 190080867 bytes) unachievable" time="2023-12-01T16:12:59.521046252Z" level=info msg="===" time="2023-12-01T16:12:59.521049122Z" level=info msg="3 replicas (2 blocks, 9 bytes) total commitment (excluding unreferenced)" time="2023-12-01T16:12:59.521052592Z" level=info msg="5 replicas (2 blocks, 15 bytes) total usage" time="2023-12-01T16:12:59.521055232Z" level=info msg="===" time="2023-12-01T16:12:59.521059932Z" level=info msg="zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.521066172Z" level=info msg="zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.521071332Z" level=info msg="zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.521075862Z" level=info msg="zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.521079442Z" level=info msg="===" time="2023-12-01T16:12:59.521081822Z" level=info msg="Replication level distribution:" time="2023-12-01T16:12:59.521085512Z" level=info msg=" 0: 17 #########################################################" time="2023-12-01T16:12:59.521088952Z" level=info msg=" 1: 1 #############" time="2023-12-01T16:12:59.521091712Z" level=info msg=" 2: 0 " time="2023-12-01T16:12:59.521094252Z" level=info msg=" 3: 0 " time="2023-12-01T16:12:59.521096692Z" level=info msg=" 4: 1 #############" time="2023-12-01T16:12:59.521099072Z" level=info msg="===" time="2023-12-01T16:12:59.521104082Z" level=info msg="send_pull_lists: start" time="2023-12-01T16:12:59.521193802Z" level=info msg="send_pull_lists: took 8.868e-05s" time="2023-12-01T16:12:59.521198242Z" level=info msg="send_trash_lists: start" time="2023-12-01T16:12:59.521264842Z" level=info msg="send_trash_lists: took 6.614e-05s" time="2023-12-01T16:12:59.521273942Z" level=info msg="sweep: took 0.00268704s" time="2023-12-01T16:12:59.521496992Z" level=info msg="run succeeded" time="2023-12-01T16:12:59.521504212Z" level=info msg="timer went off" time="2023-12-01T16:12:59.521507452Z" level=info msg="starting next run" time="2023-12-01T16:12:59.521624372Z" level=info msg="acquiring active lock" time="2023-12-01T16:12:59.521841172Z" level=info msg="sweep: start" time="2023-12-01T16:12:59.521932212Z" level=info msg="skipping zzzzz-bi6l4-h0a0xwut9qa6g3a with service type \"proxy\"" time="2023-12-01T16:12:59.522134472Z" level=info msg="get_state: start" time="2023-12-01T16:12:59.522169912Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.522175752Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.522194322Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): add 2 entries to map" time="2023-12-01T16:12:59.522190932Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.522245152Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.522253042Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.522258842Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.522201142Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): added 2 entries to map at 1x (2 replicas)" time="2023-12-01T16:12:59.522271222Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.522212792Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.522281142Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.522286162Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.522213132Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.522309992Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.522315452Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.522320432Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.522434222Z" level=info msg="heap 5218304 stack 950272 heapalloc 2943912 virt 1351573504 res 27942912" time="2023-12-01T16:12:59.523451072Z" level=info msg="collections: 293/3" time="2023-12-01T16:12:59.523690373Z" level=info msg="get_state: took 0.00155289s" time="2023-12-01T16:12:59.523707862Z" level=info msg="changeset_compute: start" time="2023-12-01T16:12:59.523754473Z" level=info msg="3858f62230ac3c915f300c664312c63f+6 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.523782582Z" level=info msg="acbd18db4cc2f85cedef654fccc4a4d8+3 refs=6 needed=2 unneeded=2 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=stay,12345692000000000 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345691000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=trash,12345693000000000 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=trash,12345694000000000]" time="2023-12-01T16:12:59.523804653Z" level=info msg="4d20280d5e516a0109768d49ab0f3318+3 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.523855242Z" level=info msg="cdd549ae79fe6640fa3d5c6261d8303c+195 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.523897682Z" level=info msg="8258b505536a9ab47baa2f4281cb932a+9 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.523892473Z" level=info msg="2bbc341c702df4d8f42ec31f16c10120+64 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.524004762Z" level=info msg="6a4ff0499484c6c79c95cd8c566bd25f+249025 refs=3 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.524004942Z" level=info msg="8c12f5f5297b7337598170c6f531fcee+7882 refs=14 needed=0 unneeded=0 pulling=0 map[default:2] 2023/12/01 16:13:02 [info] 57881#57881: *2561 client 127.0.0.1 closed keepalive connection 2023/12/01 16:13:02 [info] 57881#57881: *2493 client 127.0.0.1 closed keepalive connection [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.524008833Z" level=info msg="4c6c2c0ac8aa0696edd7316a3be5ca3c+5 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.524032382Z" level=info msg="29d7797f1888013986899bc9083783fa+3 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.524051853Z" level=info msg="f0ef7081e1539ac00ef5b761b4fb01b3+12 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.524111242Z" level=info msg="92b53930db60fe94be2a73fc771ba921+34 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.524111822Z" level=info msg="fca529cfe035e3e384563ee55eadbb2f+67108863 refs=1 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.524032413Z" level=info msg="56ac2557b1ded11ccab7293dc47d1e88+44 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0]" time="2023-12-01T16:12:59.524039453Z" level=info msg="37b51d194a7513e45b56f6524f2d51f2+3 refs=32 needed=1 unneeded=0 pulling=2 map[archive:2 default:2] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=pull,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=pull,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=stay,12345678000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.524195933Z" level=info msg="5c77a43e329b9838cbec18ff42790e57+55605760 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.524206273Z" level=info msg="85877ca2d7e05498dd3d109baf2df106+95 refs=5 needed=0 unneeded=0 pulling=0 map[default:2] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.524204693Z" level=info msg="73feffa4b7f6bb68e44cf984c85f6e88+3 refs=220 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0]" time="2023-12-01T16:12:59.524215822Z" level=info msg="d21353cfe035e3e384563ee55eadbb2f+67108864 refs=2 needed=0 unneeded=0 pulling=0 map[default:2] [keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=none,0]" time="2023-12-01T16:12:59.524240253Z" level=info msg="changeset_compute: took 0.000531251s" time="2023-12-01T16:12:59.524244142Z" level=info msg="===" time="2023-12-01T16:12:59.524248653Z" level=info msg="17 replicas (17 blocks, 190080867 bytes) lost (0=have<want)" time="2023-12-01T16:12:59.524252933Z" level=info msg="2 replicas (1 blocks, 6 bytes) underreplicated (0<have<want)" time="2023-12-01T16:12:59.524256593Z" level=info msg="0 replicas (0 blocks, 0 bytes) just right (have=want)" time="2023-12-01T16:12:59.524260153Z" level=info msg="2 replicas (1 blocks, 6 bytes) overreplicated (have>want>0)" time="2023-12-01T16:12:59.524263473Z" level=info msg="0 replicas (0 blocks, 0 bytes) unreferenced (have>want=0, new)" time="2023-12-01T16:12:59.524266793Z" level=info msg="0 replicas (0 blocks, 0 bytes) garbage (have>want=0, old)" time="2023-12-01T16:12:59.524269622Z" level=info msg="===" time="2023-12-01T16:12:59.524272682Z" level=info msg="storage class \"default\": 3 replicas (2 blocks, 9 bytes) needed" time="2023-12-01T16:12:59.524276593Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) unneeded" time="2023-12-01T16:12:59.524280202Z" level=info msg="storage class \"default\": 2 replicas (1 blocks, 6 bytes) pulling" time="2023-12-01T16:12:59.524283893Z" level=info msg="storage class \"default\": 17 replicas (17 blocks, 190080867 bytes) unachievable" time="2023-12-01T16:12:59.524287762Z" level=info msg="===" time="2023-12-01T16:12:59.524290642Z" level=info msg="3 replicas (2 blocks, 9 bytes) total commitment (excluding unreferenced)" time="2023-12-01T16:12:59.524294182Z" level=info msg="5 replicas (2 blocks, 15 bytes) total usage" time="2023-12-01T16:12:59.524296893Z" level=info msg="===" time="2023-12-01T16:12:59.524301473Z" level=info msg="zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.524307893Z" level=info msg="zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:0} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.524312682Z" level=info msg="zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:1, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.524317262Z" level=info msg="zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.524320853Z" level=info msg="===" time="2023-12-01T16:12:59.524323293Z" level=info msg="Replication level distribution:" time="2023-12-01T16:12:59.524327033Z" level=info msg=" 0: 17 #########################################################" time="2023-12-01T16:12:59.524330513Z" level=info msg=" 1: 1 #############" time="2023-12-01T16:12:59.524333173Z" level=info msg=" 2: 0 " time="2023-12-01T16:12:59.524335673Z" level=info msg=" 3: 0 " time="2023-12-01T16:12:59.524338413Z" level=info msg=" 4: 1 #############" time="2023-12-01T16:12:59.524340873Z" level=info msg="===" time="2023-12-01T16:12:59.524345462Z" level=info msg="send_pull_lists: start" time="2023-12-01T16:12:59.524461302Z" level=info msg="send_pull_lists: took 0.0001141s" time="2023-12-01T16:12:59.524467442Z" level=info msg="send_trash_lists: start" time="2023-12-01T16:12:59.524528722Z" level=info msg="send_trash_lists: took 6.046e-05s" time="2023-12-01T16:12:59.524534253Z" level=info msg="sweep: took 0.0026935s" time="2023-12-01T16:12:59.524719053Z" level=info msg="run succeeded" time="2023-12-01T16:12:59.524725393Z" level=info msg="timer went off" time="2023-12-01T16:12:59.524728422Z" level=info msg="starting next run" time="2023-12-01T16:12:59.524829733Z" level=info msg="acquiring active lock" time="2023-12-01T16:12:59.525009153Z" level=info msg="sweep: start" time="2023-12-01T16:12:59.525098873Z" level=info msg="skipping zzzzz-bi6l4-h0a0xwut9qa6g3a with service type \"proxy\"" time="2023-12-01T16:12:59.525320482Z" level=info msg="get_state: start" time="2023-12-01T16:12:59.525355213Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.525387462Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.525395702Z" level=info msg="zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.525400673Z" level=info msg="mount zzzzz-ivpuk-300000000000000 (keep3-vol0) on zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.525415002Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.525432922Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.525438253Z" level=info msg="zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.525442962Z" level=info msg="mount zzzzz-ivpuk-100000000000000 (keep1-vol0) on zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.525453602Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.525470402Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): add 2 entries to map" time="2023-12-01T16:12:59.525470022Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): retrieve index from zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk)" time="2023-12-01T16:12:59.525475713Z" level=info msg="zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): added 2 entries to map at 1x (2 replicas)" time="2023-12-01T16:12:59.525480433Z" level=info msg="mount zzzzz-ivpuk-000000000000000 (keep0-vol0) on zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.525500853Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): add 1 entries to map" time="2023-12-01T16:12:59.525508003Z" level=info msg="zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): added 1 entries to map at 1x (1 replicas)" time="2023-12-01T16:12:59.525513173Z" level=info msg="mount zzzzz-ivpuk-200000000000000 (keep2-vol0) on zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): index done" time="2023-12-01T16:12:59.525708013Z" level=info msg="collections: 0/3" time="2023-12-01T16:12:59.525782573Z" level=info msg="get_state: took 0.00046077s" time="2023-12-01T16:12:59.525790813Z" level=info msg="changeset_compute: start" time="2023-12-01T16:12:59.525816203Z" level=info msg="acbd18db4cc2f85cedef654fccc4a4d8+3 refs=0 needed=0 unneeded=4 pulling=0 map[] [keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=trash,12345695000000000 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=trash,12345697000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=trash,12345698000000000 keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=trash,12345696000000000]" time="2023-12-01T16:12:59.525833193Z" level=info msg="37b51d194a7513e45b56f6524f2d51f2+3 refs=0 needed=0 unneeded=1 pulling=0 map[] [keep1.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-100000000000000=none,0 keep3.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-300000000000000=none,0 keep0.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-000000000000000=trash,12345678000000000 keep2.zzzzz.arvadosapi.com:25107/zzzzz-ivpuk-200000000000000=none,0]" time="2023-12-01T16:12:59.525846693Z" level=info msg="changeset_compute: took 5.534e-05s" time="2023-12-01T16:12:59.525849713Z" level=info msg="===" time="2023-12-01T16:12:59.525853393Z" level=info msg="0 replicas (0 blocks, 0 bytes) lost (0=have<want)" time="2023-12-01T16:12:59.525856853Z" level=info msg="0 replicas (0 blocks, 0 bytes) underreplicated (0<have<want)" time="2023-12-01T16:12:59.525860763Z" level=info msg="0 replicas (0 blocks, 0 bytes) just right (have=want)" time="2023-12-01T16:12:59.525864373Z" level=info msg="0 replicas (0 blocks, 0 bytes) overreplicated (have>want>0)" time="2023-12-01T16:12:59.525868043Z" level=info msg="0 replicas (0 blocks, 0 bytes) unreferenced (have>want=0, new)" time="2023-12-01T16:12:59.525871493Z" level=info msg="5 replicas (2 blocks, 15 bytes) garbage (have>want=0, old)" time="2023-12-01T16:12:59.525874363Z" level=info msg="===" time="2023-12-01T16:12:59.525877313Z" level=info msg="storage class \"default\": 0 replicas (0 blocks, 0 bytes) needed" time="2023-12-01T16:12:59.525880963Z" level=info msg="storage class \"default\": 5 replicas (2 blocks, 15 bytes) unneeded" time="2023-12-01T16:12:59.525884543Z" level=info msg="storage class \"default\": 0 replicas (0 blocks, 0 bytes) pulling" time="2023-12-01T16:12:59.525888173Z" level=info msg="storage class \"default\": 0 replicas (0 blocks, 0 bytes) unachievable" time="2023-12-01T16:12:59.525891283Z" level=info msg="===" time="2023-12-01T16:12:59.525901563Z" level=info msg="0 replicas (0 blocks, 0 bytes) total commitment (excluding unreferenced)" time="2023-12-01T16:12:59.525905053Z" level=info msg="5 replicas (2 blocks, 15 bytes) total usage" time="2023-12-01T16:12:59.525907843Z" level=info msg="===" time="2023-12-01T16:12:59.525912093Z" level=info msg="zzzzz-bi6l4-000000000000002 (keep2.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.525918183Z" level=info msg="zzzzz-bi6l4-000000000000003 (keep3.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.525922843Z" level=info msg="zzzzz-bi6l4-000000000000000 (keep0.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:2} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.525927363Z" level=info msg="zzzzz-bi6l4-000000000000001 (keep1.zzzzz.arvadosapi.com:25107, disk): ChangeSet{Pulls:0, Trashes:1} Deferred{Pulls:0 Trashes:0}\n" time="2023-12-01T16:12:59.525930933Z" level=info msg="===" time="2023-12-01T16:12:59.525933173Z" level=info msg="Replication level distribution:" time="2023-12-01T16:12:59.525936823Z" level=info msg=" 0: 0 " time="2023-12-01T16:12:59.525939613Z" level=info msg=" 1: 1 #############################################" time="2023-12-01T16:12:59.525942543Z" level=info msg=" 2: 0 " time="2023-12-01T16:12:59.525945003Z" level=info msg=" 3: 0 " time="2023-12-01T16:12:59.525947413Z" level=info msg=" 4: 1 #############################################" time="2023-12-01T16:12:59.525950063Z" level=info msg="===" time="2023-12-01T16:12:59.525953763Z" level=info msg="sweep: took 0.000945301s" time="2023-12-01T16:12:59.526474783Z" level=info msg="run failed: received zero collections" time="2023-12-01T16:12:59.526481473Z" level=info msg="timer went off" time="2023-12-01T16:12:59.526484613Z" level=info msg="starting next run" time="2023-12-01T16:12:59.526645963Z" level=info msg="acquiring active lock" time="2023-12-01T16:12:59.526654103Z" level=info msg="run succeeded" time="2023-12-01T16:12:59.526657903Z" level=info msg="timer went off" time="2023-12-01T16:12:59.526660733Z" level=info msg="starting next run" balance_run_test.go:667: c.Check(metrics, check.Matches, `(?ms).*\narvados_keepbalance_changeset_compute_seconds_count `+fmt.Sprintf("%d", pullReqs.Count()/4)+`\n.*`) ... value string = "" + ... "# HELP arvados_keep_dedup_block_ratio deduplication ratio, blocks referenced / blocks stored\n" + ... "# TYPE arvados_keep_dedup_block_ratio gauge\n" + ... "arvados_keep_dedup_block_ratio 0\n" + ... "# HELP arvados_keep_dedup_byte_ratio deduplication ratio, bytes referenced / bytes stored\n" + ... "# TYPE arvados_keep_dedup_byte_ratio gauge\n" + ... "arvados_keep_dedup_byte_ratio 0\n" + ... "# HELP arvados_keep_garbage_blocks blocks of garbage (unreferenced, old)\n" + ... "# TYPE arvados_keep_garbage_blocks gauge\n" + ... "arvados_keep_garbage_blocks 2\n" + ... "# HELP arvados_keep_garbage_bytes bytes of garbage (unreferenced, old)\n" + ... "# TYPE arvados_keep_garbage_bytes gauge\n" + ... "arvados_keep_garbage_bytes 15\n" + ... "# HELP arvados_keep_garbage_replicas replicas of garbage (unreferenced, old)\n" + ... "# TYPE arvados_keep_garbage_replicas gauge\n" + ... "arvados_keep_garbage_replicas 5\n" + ... "# HELP arvados_keep_lost_blocks blocks of lost\n" + ... "# TYPE arvados_keep_lost_blocks gauge\n" + ... "arvados_keep_lost_blocks 0\n" + ... "# HELP arvados_keep_lost_bytes bytes of lost\n" + ... "# TYPE arvados_keep_lost_bytes gauge\n" + ... "arvados_keep_lost_bytes 0\n" + ... "# HELP arvados_keep_lost_replicas replicas of lost\n" + ... "# TYPE arvados_keep_lost_replicas gauge\n" + ... "arvados_keep_lost_replicas 0\n" + ... "# HELP arvados_keep_overreplicated_blocks blocks of overreplicated\n" + ... "# TYPE arvados_keep_overreplicated_blocks gauge\n" + ... "arvados_keep_overreplicated_blocks 0\n" + ... "# HELP arvados_keep_overreplicated_bytes bytes of overreplicated\n" + ... "# TYPE arvados_keep_overreplicated_bytes gauge\n" + ... "arvados_keep_overreplicated_bytes 0\n" + ... "# HELP arvados_keep_overreplicated_replicas replicas of overreplicated\n" + ... "# TYPE arvados_keep_overreplicated_replicas gauge\n" + ... "arvados_keep_overreplicated_replicas 0\n" + ... "# HELP arvados_keep_total_blocks blocks of current backend storage usage\n" + ... "# TYPE arvados_keep_total_blocks gauge\n" + ... "arvados_keep_total_blocks 2\n" + ... "# HELP arvados_keep_total_bytes bytes of current backend storage usage\n" + ... "# TYPE arvados_keep_total_bytes gauge\n" + ... "arvados_keep_total_bytes 15\n" + ... "# HELP arvados_keep_total_replicas replicas of current backend storage usage\n" + ... "# TYPE arvados_keep_total_replicas gauge\n" + ... "arvados_keep_total_replicas 5\n" + ... "# HELP arvados_keep_transient_blocks blocks of transient (unreferenced, new)\n" + ... "# TYPE arvados_keep_transient_blocks gauge\n" + ... "arvados_keep_transient_blocks 0\n" + ... "# HELP arvados_keep_transient_bytes bytes of transient (unreferenced, new)\n" + ... "# TYPE arvados_keep_transient_bytes gauge\n" + ... "arvados_keep_transient_bytes 0\n" + ... "# HELP arvados_keep_transient_replicas replicas of transient (unreferenced, new)\n" + ... "# TYPE arvados_keep_transient_replicas gauge\n" + ... "arvados_keep_transient_replicas 0\n" + ... "# HELP arvados_keep_underreplicated_blocks blocks of underreplicated\n" + ... "# TYPE arvados_keep_underreplicated_blocks gauge\n" + ... "arvados_keep_underreplicated_blocks 0\n" + ... "# HELP arvados_keep_underreplicated_bytes bytes of underreplicated\n" + ... "# TYPE arvados_keep_underreplicated_bytes gauge\n" + ... "arvados_keep_underreplicated_bytes 0\n" + ... "# HELP arvados_keep_underreplicated_replicas replicas of underreplicated\n" + ... "# TYPE arvados_keep_underreplicated_replicas gauge\n" + ... "arvados_keep_underreplicated_replicas 0\n" + ... "# HELP arvados_keepbalance_changeset_compute_seconds wall clock time to compute changesets\n" + ... "# TYPE arvados_keepbalance_changeset_compute_seconds summary\n" + ... "arvados_keepbalance_changeset_compute_seconds_sum 0.0015203100000000002\n" + ... "arvados_keepbalance_changeset_compute_seconds_count 5\n" + ... "# HELP arvados_keepbalance_get_state_seconds wall clock time to get current state\n" + ... "# TYPE arvados_keepbalance_get_state_seconds summary\n" + ... "arvados_keepbalance_get_state_seconds_sum 0.011799439\n" + ... "arvados_keepbalance_get_state_seconds_count 5\n" + ... "# HELP arvados_keepbalance_send_pull_lists_seconds wall clock time to send pull lists\n" + ... "# TYPE arvados_keepbalance_send_pull_lists_seconds summary\n" + ... "arvados_keepbalance_send_pull_lists_seconds_sum 0.00047651999999999997\n" + ... "arvados_keepbalance_send_pull_lists_seconds_count 4\n" + ... "# HELP arvados_keepbalance_send_trash_lists_seconds wall clock time to send trash lists\n" + ... "# TYPE arvados_keepbalance_send_trash_lists_seconds summary\n" + ... "arvados_keepbalance_send_trash_lists_seconds_sum 0.00036698000000000004\n" + ... "arvados_keepbalance_send_trash_lists_seconds_count 5\n" + ... "# HELP arvados_keepbalance_sweep_seconds wall clock time to run one full sweep\n" + ... "# TYPE arvados_keepbalance_sweep_seconds summary\n" + ... "arvados_keepbalance_sweep_seconds_sum 0.016458132\n" + ... "arvados_keepbalance_sweep_seconds_count 5\n" ... regex string = "(?ms).*\\narvados_keepbalance_changeset_compute_seconds_count 4\\n.*"
Files
Updated by Brett Smith 5 months ago
Updated by Tom Clegg 5 months ago
- Target version changed from To be scheduled to Development 2024-01-03 sprint
- Assigned To set to Tom Clegg
- Status changed from New to In Progress
21254-test-race @ 9251549928dd5206d4a14e5f9811caa66aa64c65 -- developer-run-tests: #3952
Updated the test to let the 1st and 2nd runs start automatically (in order to confirm that actually works) and then switch strategies to sending SIGUSR1 to explicitly trigger additional runs one at a time, so it don't accidentally run 5x instead of 4x.
Ran updated test 100x without failing.
Updated by Brett Smith 5 months ago
Tom Clegg wrote in #note-2:
21254-test-race @ 9251549928dd5206d4a14e5f9811caa66aa64c65 -- developer-run-tests: #3952
This is good to merge, thanks. One observation and one idea.
I think the comment above your main diff has gotten out of date, especially: "We should complete all four runs in much less than a second." The loop seems to be waiting up to ten seconds, not one. But personally I think I would suggest striking this whole sentence given that you're now triggering most of the runs manually. It still technically makes sense, but less than it used to.
And that leads me to the thought, the way this test changes orchestration strategy halfway through is kinda funky. I wonder if it would be cleaner to break this into two tests: one that's focused on testing BalancePeriod, and just tests that lists meet certain minima; and another that triggers runs with SIGUSR1, and tests that lists match exactly what's expected. It's not urgent, though.
Thanks again.
Updated by Brett Smith 5 months ago
Tom Clegg wrote in #note-2:
21254-test-race @ 9251549928dd5206d4a14e5f9811caa66aa64c65 -- developer-run-tests: #3952
I made #21276 for the new test failure here.
Updated by Tom Clegg 5 months ago
21254-test-race @ 8209e167b7c32f7f233f54429390a7470a8127d9
splits RunForever into timer- and signal-triggered tests.
Updated by Brett Smith 5 months ago
Tom Clegg wrote in #note-5:
21254-test-race @ 8209e167b7c32f7f233f54429390a7470a8127d9
splits RunForever into timer- and signal-triggered tests.
Thanks, I do think this is a big step up for being able to follow the test mechanism and understand what's being tested.
It looks like you merged the previous version into main, and then refined it from here? That's fine, I said it was good to merge and I stand by that :), just checking we're on the same page about process.
I thought I might've found a potential race, and then I think I convinced myself that it's nigh impossible in practice, I'm gonna write out that thought process to see if we're on the same page. It's about the main loop in TestRunForever_TriggeredByTimer:
s.config.Collections.BalancePeriod = arvados.Duration(10 * time.Millisecond)
…
for t0 := time.Now(); time.Since(t0) < 10*time.Second; {
pulls := pullReqs.Count()
if pulls >= 16 && trashReqs.Count() == pulls+4 {
break
}
time.Sleep(time.Millisecond)
}
I had the thought, is it possible for keep-balance and the test loop to be perfectly out of sync so that trashReqs.Count() == pulls+4 never passes, because keep-balance is processing trash requests in the time between pullReqs.Count() and trashReqs.Count()? And then I thought, given that the BalancePeriod is 10ms, and the loop sleeps only 1ms, that might happen occasionally but the loop should have plenty of chances to check while keep-balance is asleep. If that doesn't happen we'll probably have much bigger problems across our test suite. So this is fine.
If we're on the same page about that then great, please merge, thanks.
Updated by Tom Clegg 5 months ago
Yes, it's conceivable that each iteration of the test's polling loop could repeatedly get unlucky and count pull/trash reqs during the interval when some, but not all, of the trash reqs have been sent for the current/latest run. But practically speaking I think this will never happen enough times in a row to reach the 10s test timeout.
Updated by Tom Clegg 5 months ago
Brett Smith wrote in #note-6:
It looks like you merged the previous version into main, and then refined it from here? That's fine, I said it was good to merge and I stand by that :), just checking we're on the same page about process.
Yes. I figured it was worth merging the previous fix to prevent anyone from wasting time on any additional jenkins failures while doing the follow-up.
Updated by Tom Clegg 5 months ago
- % Done changed from 0 to 100
- Status changed from In Progress to Resolved
Applied in changeset arvados|af083bfbaae0d542a25d663e28e66cefa765f501.
Updated by
Actions