diff --git a/internal/database/database.go b/internal/database/database.go index ffd1731..b28cda7 100644 --- a/internal/database/database.go +++ b/internal/database/database.go @@ -10,6 +10,8 @@ import ( "net" "os" "path/filepath" + "runtime" + "sync" "time" "git.eeqj.de/sneak/routewatch/internal/config" @@ -42,9 +44,12 @@ var ( // Database manages the SQLite database connection and operations. type Database struct { - db *sql.DB - logger *logger.Logger - path string + db *sql.DB + logger *logger.Logger + path string + mu sync.Mutex + lockedAt time.Time + lockedBy string } // New creates a new database connection and initializes the schema. @@ -62,9 +67,10 @@ func New(cfg *config.Config, logger *logger.Logger) (*Database, error) { // Add connection parameters for go-sqlite3 // Enable WAL mode and other performance optimizations - // Use immediate transactions to prevent deadlocks when multiple writers compete + // Configure SQLite connection parameters + // Use _txlock=immediate to acquire locks upfront and respect busy_timeout dsn := fmt.Sprintf( - "file:%s?_busy_timeout=5000&_journal_mode=WAL&_synchronous=OFF&cache=shared&_txlock=immediate", + "file:%s?_busy_timeout=5000&_journal_mode=WAL&_synchronous=OFF&_txlock=immediate", dbPath, ) db, err := sql.Open("sqlite3", dsn) @@ -78,6 +84,7 @@ func New(cfg *config.Config, logger *logger.Logger) (*Database, error) { // Set connection pool parameters // Multiple connections for better concurrency + // Use multiple connections for read concurrency const maxConns = 10 db.SetMaxOpenConns(maxConns) db.SetMaxIdleConns(maxConns) @@ -137,6 +144,33 @@ func (d *Database) Close() error { return d.db.Close() } +// lock acquires the database mutex and logs debug information +func (d *Database) lock(operation string) { + // Get caller information + _, file, line, _ := runtime.Caller(1) + caller := fmt.Sprintf("%s:%d", filepath.Base(file), line) + + d.logger.Debug("Acquiring database lock", "operation", operation, "caller", caller) + + d.mu.Lock() + d.lockedAt = time.Now() + d.lockedBy = fmt.Sprintf("%s (%s)", operation, caller) + + d.logger.Debug("Database lock acquired", "operation", operation, "caller", caller) +} + +// unlock releases the database mutex and logs debug information including hold duration +func (d *Database) unlock() { + holdDuration := time.Since(d.lockedAt) + lockedBy := d.lockedBy + + d.lockedAt = time.Time{} + d.lockedBy = "" + d.mu.Unlock() + + d.logger.Debug("Database lock released", "held_by", lockedBy, "duration_ms", holdDuration.Milliseconds()) +} + // beginTx starts a new transaction with logging func (d *Database) beginTx() (*loggingTx, error) { tx, err := d.db.Begin() @@ -153,6 +187,9 @@ func (d *Database) UpsertLiveRouteBatch(routes []*LiveRoute) error { return nil } + d.lock("UpsertLiveRouteBatch") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return fmt.Errorf("failed to begin transaction: %w", err) @@ -231,6 +268,9 @@ func (d *Database) DeleteLiveRouteBatch(deletions []LiveRouteDeletion) error { return nil } + d.lock("DeleteLiveRouteBatch") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return fmt.Errorf("failed to begin transaction: %w", err) @@ -298,6 +338,9 @@ func (d *Database) GetOrCreateASNBatch(asns map[int]time.Time) error { return nil } + d.lock("GetOrCreateASNBatch") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return fmt.Errorf("failed to begin transaction: %w", err) @@ -384,6 +427,9 @@ func (d *Database) GetOrCreateASNBatch(asns map[int]time.Time) error { // GetOrCreateASN retrieves an existing ASN or creates a new one if it doesn't exist. func (d *Database) GetOrCreateASN(number int, timestamp time.Time) (*ASN, error) { + d.lock("GetOrCreateASN") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return nil, err @@ -455,6 +501,9 @@ func (d *Database) GetOrCreateASN(number int, timestamp time.Time) (*ASN, error) // GetOrCreatePrefix retrieves an existing prefix or creates a new one if it doesn't exist. func (d *Database) GetOrCreatePrefix(prefix string, timestamp time.Time) (*Prefix, error) { + d.lock("GetOrCreatePrefix") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return nil, err @@ -517,6 +566,9 @@ func (d *Database) GetOrCreatePrefix(prefix string, timestamp time.Time) (*Prefi // RecordAnnouncement inserts a new BGP announcement or withdrawal into the database. func (d *Database) RecordAnnouncement(announcement *Announcement) error { + d.lock("RecordAnnouncement") + defer d.unlock() + err := d.exec(` INSERT INTO announcements (id, prefix_id, asn_id, origin_asn_id, path, next_hop, timestamp, is_withdrawal) VALUES (?, ?, ?, ?, ?, ?, ?, ?)`, @@ -542,6 +594,9 @@ func (d *Database) RecordPeering(asA, asB int, timestamp time.Time) error { asA, asB = asB, asA } + d.lock("RecordPeering") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return err @@ -591,6 +646,9 @@ func (d *Database) UpdatePeerBatch(peers map[string]PeerUpdate) error { return nil } + d.lock("UpdatePeerBatch") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return fmt.Errorf("failed to begin transaction: %w", err) @@ -650,6 +708,9 @@ func (d *Database) UpdatePeerBatch(peers map[string]PeerUpdate) error { // UpdatePeer updates or creates a BGP peer record func (d *Database) UpdatePeer(peerIP string, peerASN int, messageType string, timestamp time.Time) error { + d.lock("UpdatePeer") + defer d.unlock() + tx, err := d.beginTx() if err != nil { return err @@ -762,6 +823,9 @@ func (d *Database) GetStats() (Stats, error) { // UpsertLiveRoute inserts or updates a live route func (d *Database) UpsertLiveRoute(route *LiveRoute) error { + d.lock("UpsertLiveRoute") + defer d.unlock() + query := ` INSERT INTO live_routes (id, prefix, mask_length, ip_version, origin_asn, peer_ip, as_path, next_hop, last_updated, v4_ip_start, v4_ip_end) @@ -811,6 +875,9 @@ func (d *Database) UpsertLiveRoute(route *LiveRoute) error { // DeleteLiveRoute deletes a live route // If originASN is 0, deletes all routes for the prefix/peer combination func (d *Database) DeleteLiveRoute(prefix string, originASN int, peerIP string) error { + d.lock("DeleteLiveRoute") + defer d.unlock() + var query string var err error diff --git a/log.txt b/log.txt index d5eedf8..9e53642 100644 --- a/log.txt +++ b/log.txt @@ -10,109 +10,111 @@ [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.375µs +[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 5.25µs +[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.875µs +[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:22:17.63026+02:00","level":"INFO","msg":"Opening database","source":"database.go:55","func":"database.New","path":"/Users/user/Library/Application Support/berlin.sneak.app.routewatch/db.sqlite"} -{"time":"2025-07-28T17:22:17.698316+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"PRAGMA wal_checkpoint(TRUNCATE)","duration":55405125} -{"time":"2025-07-28T17:22:17.698588+02:00","level":"INFO","msg":"Running VACUUM to optimize database (this may take a moment)","source":"database.go:123","func":"database.(*Database).Initialize"} -{"time":"2025-07-28T17:22:28.121045+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"VACUUM","duration":10422508542} -[Fx] RUN provide: fx.Annotate(git.eeqj.de/sneak/routewatch/internal/database.New(), fx.As([[database.Store]]) in 10.4910875s +{"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 31.917µs +[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 17.375µs +[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 56.75µs +[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 5.583µs +[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 8.542µs +[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 212.375µs +[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:22:28.121692+02:00","level":"INFO","msg":"Starting RouteWatch","source":"app.go:64","func":"routewatch.(*RouteWatch).Run"} -{"time":"2025-07-28T17:22:28.12173+02:00","level":"INFO","msg":"Using batched database handlers for improved performance","source":"app.go:76","func":"routewatch.(*RouteWatch).Run"} -{"time":"2025-07-28T17:22:28.12281+02:00","level":"INFO","msg":"Starting HTTP server","source":"server.go:52","func":"server.(*Server).Start","port":"8080"} -2025/07/28 17:22:28 [akrotiri/ufn7sJdwmP-000001] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62452 - 200 3655B in 351.613042ms -2025/07/28 17:22:29 [akrotiri/ufn7sJdwmP-000002] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62452 - 200 3655B in 348.4895ms -{"time":"2025-07-28T17:22:30.206712+02:00","level":"INFO","msg":"Connected to RIS Live stream","source":"streamer.go:343","func":"streamer.(*Streamer).stream"} -{"time":"2025-07-28T17:22:30.540837+02:00","level":"ERROR","msg":"Failed to upsert route batch","source":"prefixhandler.go:206","func":"routewatch.(*PrefixHandler).flushBatchLocked","error":"failed to upsert route 2400:cb00:492::/48: database table is locked","count":1153} -{"time":"2025-07-28T17:22:30.540883+02:00","level":"ERROR","msg":"Failed to delete route batch","source":"prefixhandler.go:214","func":"routewatch.(*PrefixHandler).flushBatchLocked","error":"failed to delete route 2a12:f680:a00:0:0:0:0:0/48: database table is locked","count":167} -{"time":"2025-07-28T17:22:30.540891+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5006,"unique_prefixes":1320,"success":0,"duration_ms":1} -{"time":"2025-07-28T17:22:30.606806+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"database table is locked: asns"} -{"time":"2025-07-28T17:22:30.606827+02:00","level":"ERROR","msg":"Failed to get database stats","source":"handlers.go:253","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1","error":"database table is locked: asns"} -2025/07/28 17:22:30 [akrotiri/ufn7sJdwmP-000003] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62452 - 500 31B in 111.958µs -{"time":"2025-07-28T17:22:30.64475+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:428","func":"streamer.(*Streamer).stream","peer":"196.60.8.170","peer_asn":"327781"} -{"time":"2025-07-28T17:22:30.723117+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 64114: database table is locked","count":1082} -{"time":"2025-07-28T17:22:30.804931+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":2389,"success":2389,"duration_ms":97} -{"time":"2025-07-28T17:22:30.958438+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:436","func":"streamer.(*Streamer).stream","peer":"80.81.192.113","peer_asn":"35320"} -{"time":"2025-07-28T17:22:30.975404+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:428","func":"streamer.(*Streamer).stream","peer":"80.81.194.92","peer_asn":"57111"} -{"time":"2025-07-28T17:22:31.009315+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5003,"unique_prefixes":1297,"success":1297,"duration_ms":48} -2025/07/28 17:22:31 [akrotiri/ufn7sJdwmP-000004] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62452 - 200 3704B in 316.55925ms -2025/07/28 17:22:32 [akrotiri/ufn7sJdwmP-000005] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62452 - 200 3704B in 324.432625ms -{"time":"2025-07-28T17:22:32.075815+02:00","level":"ERROR","msg":"Failed to upsert route batch","source":"prefixhandler.go:206","func":"routewatch.(*PrefixHandler).flushBatchLocked","error":"failed to upsert route 187.230.96.0/21: database table is locked","count":1647} -{"time":"2025-07-28T17:22:32.07592+02:00","level":"ERROR","msg":"Failed to delete route batch","source":"prefixhandler.go:214","func":"routewatch.(*PrefixHandler).flushBatchLocked","error":"failed to delete route 177.222.123.0/24: database table is locked","count":59} -{"time":"2025-07-28T17:22:32.07593+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":1706,"success":0,"duration_ms":1} -{"time":"2025-07-28T17:22:32.54004+02:00","level":"ERROR","msg":"Failed to upsert route batch","source":"prefixhandler.go:206","func":"routewatch.(*PrefixHandler).flushBatchLocked","error":"failed to upsert route 240a:a73c::/32: database table is locked","count":2368} -2025/07/28 17:22:32 [akrotiri/ufn7sJdwmP-000006] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62452 - 200 3714B in 331.647583ms -{"time":"2025-07-28T17:22:32.540103+02:00","level":"ERROR","msg":"Failed to delete route batch","source":"prefixhandler.go:214","func":"routewatch.(*PrefixHandler).flushBatchLocked","error":"failed to delete route 193.105.156.0/24: database table is locked","count":49} -{"time":"2025-07-28T17:22:32.540113+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":2417,"success":0,"duration_ms":84} -{"time":"2025-07-28T17:22:33.678988+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:248","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} -2025/07/28 17:22:33 [akrotiri/ufn7sJdwmP-000007] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62452 - 408 17B in 1.0011055s -{"time":"2025-07-28T17:22:34.195917+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:248","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000008] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62456 - 408 17B in 1.0002275s -{"time":"2025-07-28T17:22:34.612068+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":1934122250} -{"time":"2025-07-28T17:22:34.632137+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":952397291} -{"time":"2025-07-28T17:22:34.632194+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":1436454541} -{"time":"2025-07-28T17:22:34.644233+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":456752334} -{"time":"2025-07-28T17:22:34.644269+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":957002833} -{"time":"2025-07-28T17:22:34.67566+02:00","level":"ERROR","msg":"Failed to process peer batch","source":"peerhandler.go:151","func":"routewatch.(*PeerHandler).flushBatchLocked","error":"failed to update peer 45.65.244.1: database table is locked","count":584} -{"time":"2025-07-28T17:22:34.680773+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:248","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000009] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62457 - 408 17B in 1.00107975s -{"time":"2025-07-28T17:22:34.687737+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:248","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000010] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62458 - 408 17B in 1.000508709s -{"time":"2025-07-28T17:22:34.695679+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 212483: database table is locked","count":1301} -{"time":"2025-07-28T17:22:34.702799+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM bgp_peers","duration":70568666} -{"time":"2025-07-28T17:22:34.702978+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":506360791} -{"time":"2025-07-28T17:22:34.703075+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.703085+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.703093+02:00","level":"ERROR","msg":"Failed to get database stats","source":"handlers.go:253","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1","error":"failed to count live routes: database table is locked: live_routes"} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000011] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62459 - 500 67B in 515.656083ms -{"time":"2025-07-28T17:22:34.765476+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.772759+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.772775+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.772813+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.77282+02:00","level":"ERROR","msg":"Failed to get database stats","source":"handlers.go:253","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.772821+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.77286+02:00","level":"ERROR","msg":"Failed to get database stats","source":"handlers.go:253","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1","error":"failed to count live routes: database table is locked: live_routes"} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000015] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62464 - 500 67B in 84.775333ms -{"time":"2025-07-28T17:22:34.772863+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 262589: database table is locked","count":731} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000012] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62460 - 500 67B in 576.269417ms -{"time":"2025-07-28T17:22:34.773352+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":85404084} -{"time":"2025-07-28T17:22:34.773572+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.773578+02:00","level":"ERROR","msg":"Failed to get database stats","source":"handlers.go:253","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1","error":"failed to count live routes: database table is locked: live_routes"} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000013] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62462 - 500 67B in 92.172958ms -{"time":"2025-07-28T17:22:34.793081+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 9650: database table is locked","count":887} -{"time":"2025-07-28T17:22:34.793092+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:34.793104+02:00","level":"ERROR","msg":"Failed to get database stats","source":"handlers.go:253","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1","error":"failed to count live routes: database table is locked: live_routes"} -2025/07/28 17:22:34 [akrotiri/ufn7sJdwmP-000014] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62463 - 500 67B in 105.191ms -{"time":"2025-07-28T17:22:34.796443+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 3214: database table is locked","count":1265} -{"time":"2025-07-28T17:22:34.797288+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 55898: database table is locked","count":999} -{"time":"2025-07-28T17:22:34.798088+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 267463: database table is locked","count":1266} -{"time":"2025-07-28T17:22:34.800198+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 263478: database table is locked","count":1163} -{"time":"2025-07-28T17:22:34.801829+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 264974: database table is locked","count":1426} -{"time":"2025-07-28T17:22:34.812159+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 12956: database table is locked","count":1444} -{"time":"2025-07-28T17:22:34.873194+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5004,"unique_prefixes":2353,"success":2353,"duration_ms":1801} -{"time":"2025-07-28T17:22:34.979911+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5194,"unique_prefixes":2887,"success":2887,"duration_ms":106} -{"time":"2025-07-28T17:22:35.099026+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":3480,"success":3480,"duration_ms":118} -{"time":"2025-07-28T17:22:35.165997+02:00","level":"ERROR","msg":"Failed to process ASN batch","source":"ashandler.go:149","func":"routewatch.(*ASHandler).flushBatchLocked","error":"failed to update ASN 262360: database table is locked","count":1234} -{"time":"2025-07-28T17:22:35.166098+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5001,"unique_prefixes":3373,"success":3373,"duration_ms":66} -{"time":"2025-07-28T17:22:35.207606+02:00","level":"DEBUG","msg":"Database stats query failed","source":"handlers.go:237","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1.1","error":"failed to count live routes: database table is locked: live_routes"} -{"time":"2025-07-28T17:22:35.207649+02:00","level":"ERROR","msg":"Failed to get database stats","source":"handlers.go:253","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1","error":"failed to count live routes: database table is locked: live_routes"} -2025/07/28 17:22:35 [akrotiri/ufn7sJdwmP-000016] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:62459 - 500 67B in 20.740416ms -{"time":"2025-07-28T17:22:35.250142+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":4227,"success":4227,"duration_ms":83} -{"time":"2025-07-28T17:22:35.318116+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:221","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":5000,"unique_prefixes":3248,"success":3248,"duration_ms":67} +{"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"}