routewatch/log.txt
sneak ddb3cfa4f0 Add mutex to serialize database access
- Add internal mutex to Database struct with lock/unlock wrappers
- Add debug logging for lock acquisition and release with timing
- Wrap all write operations with database mutex
- Use _txlock=immediate in SQLite connection string

This works around apparent issues with SQLite's internal locking
not properly respecting busy_timeout in production environment.
2025-07-28 17:56:26 +02:00

121 lines
21 KiB
Plaintext

[Fx] PROVIDE fx.Lifecycle <= go.uber.org/fx.New.func1()
[Fx] PROVIDE fx.Shutdowner <= go.uber.org/fx.(*App).shutdowner-fm()
[Fx] PROVIDE fx.DotGraph <= go.uber.org/fx.(*App).dotGraph-fm()
[Fx] PROVIDE *logger.Logger <= git.eeqj.de/sneak/routewatch/internal/logger.New()
[Fx] PROVIDE *config.Config <= git.eeqj.de/sneak/routewatch/internal/config.New()
[Fx] PROVIDE *metrics.Tracker <= git.eeqj.de/sneak/routewatch/internal/metrics.New()
[Fx] PROVIDE database.Store <= fx.Annotate(git.eeqj.de/sneak/routewatch/internal/database.New(), fx.As([[database.Store]])
[Fx] PROVIDE *streamer.Streamer <= git.eeqj.de/sneak/routewatch/internal/streamer.New()
[Fx] PROVIDE *server.Server <= git.eeqj.de/sneak/routewatch/internal/server.New()
[Fx] PROVIDE *routewatch.RouteWatch <= git.eeqj.de/sneak/routewatch/internal/routewatch.New()
[Fx] INVOKE git.eeqj.de/sneak/routewatch/internal/routewatch.CLIEntry.func1()
[Fx] BEFORE RUN provide: go.uber.org/fx.New.func1()
[Fx] RUN provide: go.uber.org/fx.New.func1() in 4.083µs
[Fx] BEFORE RUN provide: git.eeqj.de/sneak/routewatch/internal/config.New()
[Fx] RUN provide: git.eeqj.de/sneak/routewatch/internal/config.New() in 4.542µs
[Fx] BEFORE RUN provide: git.eeqj.de/sneak/routewatch/internal/logger.New()
[Fx] RUN provide: git.eeqj.de/sneak/routewatch/internal/logger.New() in 4.042µs
[Fx] BEFORE RUN provide: fx.Annotate(git.eeqj.de/sneak/routewatch/internal/database.New(), fx.As([[database.Store]])
{"time":"2025-07-28T17:56:12.727719+02:00","level":"INFO","msg":"Opening database","source":"database.go:60","func":"database.New","path":"/Users/user/Library/Application Support/berlin.sneak.app.routewatch/db.sqlite"}
{"time":"2025-07-28T17:56:12.73045+02:00","level":"INFO","msg":"Running VACUUM to optimize database (this may take a moment)","source":"database.go:134","func":"database.(*Database).Initialize"}
{"time":"2025-07-28T17:56:20.24932+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"VACUUM","duration":7518623459}
[Fx] RUN provide: fx.Annotate(git.eeqj.de/sneak/routewatch/internal/database.New(), fx.As([[database.Store]]) in 7.521757833s
[Fx] BEFORE RUN provide: git.eeqj.de/sneak/routewatch/internal/metrics.New()
[Fx] RUN provide: git.eeqj.de/sneak/routewatch/internal/metrics.New() in 198.542µs
[Fx] BEFORE RUN provide: git.eeqj.de/sneak/routewatch/internal/streamer.New()
[Fx] RUN provide: git.eeqj.de/sneak/routewatch/internal/streamer.New() in 157.166µs
[Fx] BEFORE RUN provide: git.eeqj.de/sneak/routewatch/internal/server.New()
[Fx] RUN provide: git.eeqj.de/sneak/routewatch/internal/server.New() in 451.583µs
[Fx] BEFORE RUN provide: git.eeqj.de/sneak/routewatch/internal/routewatch.New()
[Fx] RUN provide: git.eeqj.de/sneak/routewatch/internal/routewatch.New() in 7.208µs
[Fx] BEFORE RUN provide: go.uber.org/fx.(*App).shutdowner-fm()
[Fx] RUN provide: go.uber.org/fx.(*App).shutdowner-fm() in 7.084µs
[Fx] HOOK OnStart git.eeqj.de/sneak/routewatch/internal/routewatch.CLIEntry.func1.1() executing (caller: git.eeqj.de/sneak/routewatch/internal/routewatch.CLIEntry.func1)
[Fx] HOOK OnStart git.eeqj.de/sneak/routewatch/internal/routewatch.CLIEntry.func1.1() called by git.eeqj.de/sneak/routewatch/internal/routewatch.CLIEntry.func1 ran successfully in 238.625µs
[Fx] RUNNING
{"time":"2025-07-28T17:56:20.251796+02:00","level":"INFO","msg":"Starting RouteWatch","source":"app.go:64","func":"routewatch.(*RouteWatch).Run"}
{"time":"2025-07-28T17:56:20.251981+02:00","level":"INFO","msg":"Using batched database handlers for improved performance","source":"app.go:76","func":"routewatch.(*RouteWatch).Run"}
{"time":"2025-07-28T17:56:20.253047+02:00","level":"INFO","msg":"Starting HTTP server","source":"server.go:52","func":"server.(*Server).Start","port":"8080"}
{"time":"2025-07-28T17:56:21.767563+02:00","level":"INFO","msg":"Connected to RIS Live stream","source":"streamer.go:343","func":"streamer.(*Streamer).stream"}
{"time":"2025-07-28T17:56:22.103028+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.103061+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.122922+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":19}
{"time":"2025-07-28T17:56:22.210144+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.210159+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.234274+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.2525+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:649"}
{"time":"2025-07-28T17:56:22.345773+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:190)","duration_ms":135}
{"time":"2025-07-28T17:56:22.345791+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.345781+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.361045+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":15}
{"time":"2025-07-28T17:56:22.36106+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:649"}
{"time":"2025-07-28T17:56:22.361504+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.36218+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:649)","duration_ms":1}
{"time":"2025-07-28T17:56:22.362193+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.36287+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:271)","duration_ms":0}
{"time":"2025-07-28T17:56:22.362878+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5001,"unique_prefixes":2864,"success":2864,"duration_ms":156}
{"time":"2025-07-28T17:56:22.362889+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.366083+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.379699+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":16}
{"time":"2025-07-28T17:56:22.379712+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.403914+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.467736+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.467725+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:190)","duration_ms":87}
{"time":"2025-07-28T17:56:22.467762+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.480013+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":12}
{"time":"2025-07-28T17:56:22.480032+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.480385+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:271)","duration_ms":0}
{"time":"2025-07-28T17:56:22.480392+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":3885,"success":3885,"duration_ms":117}
{"time":"2025-07-28T17:56:22.656024+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.656044+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.662796+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.674365+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.674366+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":18}
{"time":"2025-07-28T17:56:22.761129+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:190)","duration_ms":86}
{"time":"2025-07-28T17:56:22.761145+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.761149+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.761365+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:271)","duration_ms":0}
{"time":"2025-07-28T17:56:22.761371+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5006,"unique_prefixes":2657,"success":2657,"duration_ms":103}
{"time":"2025-07-28T17:56:22.764459+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.76447+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.782122+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":17}
{"time":"2025-07-28T17:56:22.816361+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.816378+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:22.848851+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.877168+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:22.877163+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:190)","duration_ms":60}
{"time":"2025-07-28T17:56:22.877198+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.896162+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":18}
{"time":"2025-07-28T17:56:22.896175+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:22.89696+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:271)","duration_ms":0}
{"time":"2025-07-28T17:56:22.896969+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":3729,"success":3729,"duration_ms":83}
{"time":"2025-07-28T17:56:23.251603+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:23.251622+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:23.26753+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":15}
2025/07/28 17:56:23 [akrotiri/pK9BrUC1pJ-000001] "GET http://127.0.0.1:8080/status HTTP/1.1" from 127.0.0.1:51351 - 200 14252B in 631.917µs
{"time":"2025-07-28T17:56:23.32644+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:23.326456+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:23.405999+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:190)","duration_ms":79}
{"time":"2025-07-28T17:56:23.406018+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:23.406022+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:271"}
{"time":"2025-07-28T17:56:23.406606+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:271)","duration_ms":0}
{"time":"2025-07-28T17:56:23.406615+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":2850,"success":2850,"duration_ms":84}
2025/07/28 17:56:23 [akrotiri/pK9BrUC1pJ-000003] "GET http://127.0.0.1:8080/favicon.ico HTTP/1.1" from 127.0.0.1:51352 - 404 19B in 20.167µs
{"time":"2025-07-28T17:56:23.556409+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:649"}
{"time":"2025-07-28T17:56:23.556423+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:649"}
{"time":"2025-07-28T17:56:23.689537+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:23.815501+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:23.893336+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:428","func":"streamer.(*Streamer).stream","peer":"80.249.210.89","peer_asn":"31042"}
2025/07/28 17:56:24 [akrotiri/pK9BrUC1pJ-000002] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:51351 - 200 3794B in 865.747083ms
2025/07/28 17:56:24 [akrotiri/pK9BrUC1pJ-000004] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:51352 - 200 3794B in 688.094875ms
{"time":"2025-07-28T17:56:24.735142+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:428","func":"streamer.(*Streamer).stream","peer":"27.111.229.239","peer_asn":"17639"}
2025/07/28 17:56:24 [akrotiri/pK9BrUC1pJ-000005] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:51351 - 200 3797B in 395.245083ms
2025/07/28 17:56:25 [akrotiri/pK9BrUC1pJ-000006] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:51351 - 200 3797B in 331.038875ms
2025/07/28 17:56:25 [akrotiri/pK9BrUC1pJ-000007] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:51351 - 200 3797B in 326.343334ms
{"time":"2025-07-28T17:56:26.007174+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:649)","duration_ms":2450}
{"time":"2025-07-28T17:56:26.007186+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}
{"time":"2025-07-28T17:56:26.009211+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:649"}
{"time":"2025-07-28T17:56:26.032407+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:171","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:341)","duration_ms":25}
{"time":"2025-07-28T17:56:26.032417+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:159","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:190"}
{"time":"2025-07-28T17:56:26.032858+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:153","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:341"}