From e0a4c8642e6a0c61e5cd9bcba57a8ace5414714a Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 28 Jul 2025 19:27:55 +0200 Subject: [PATCH] Add context cancellation support to database operations - Add context-aware versions of all read operations in the database - Update handlers to use context from HTTP requests - Allows database queries to be cancelled when HTTP requests timeout - Prevents database operations from continuing after client disconnects --- internal/database/database.go | 76 +- internal/database/interface.go | 8 + internal/database/slowquery.go | 1 + internal/routewatch/app_integration_test.go | 35 + internal/server/handlers.go | 22 +- internal/streamer/streamer.go | 102 +- log.txt | 1152 +++++++++++++++++++ 7 files changed, 1347 insertions(+), 49 deletions(-) diff --git a/internal/database/database.go b/internal/database/database.go index 355239d..86668d9 100644 --- a/internal/database/database.go +++ b/internal/database/database.go @@ -2,6 +2,7 @@ package database import ( + "context" "database/sql" _ "embed" "encoding/json" @@ -747,41 +748,48 @@ func (d *Database) UpdatePeer(peerIP string, peerASN int, messageType string, ti // GetStats returns database statistics func (d *Database) GetStats() (Stats, error) { + return d.GetStatsContext(context.Background()) +} + +// GetStatsContext returns database statistics with context support +func (d *Database) GetStatsContext(ctx context.Context) (Stats, error) { var stats Stats // Count ASNs - err := d.queryRow("SELECT COUNT(*) FROM asns").Scan(&stats.ASNs) + err := d.db.QueryRowContext(ctx, "SELECT COUNT(*) FROM asns").Scan(&stats.ASNs) if err != nil { return stats, err } // Count prefixes - err = d.queryRow("SELECT COUNT(*) FROM prefixes").Scan(&stats.Prefixes) + err = d.db.QueryRowContext(ctx, "SELECT COUNT(*) FROM prefixes").Scan(&stats.Prefixes) if err != nil { return stats, err } // Count IPv4 and IPv6 prefixes const ipVersionV4 = 4 - err = d.queryRow("SELECT COUNT(*) FROM prefixes WHERE ip_version = ?", ipVersionV4).Scan(&stats.IPv4Prefixes) + err = d.db.QueryRowContext(ctx, + "SELECT COUNT(*) FROM prefixes WHERE ip_version = ?", ipVersionV4).Scan(&stats.IPv4Prefixes) if err != nil { return stats, err } const ipVersionV6 = 6 - err = d.queryRow("SELECT COUNT(*) FROM prefixes WHERE ip_version = ?", ipVersionV6).Scan(&stats.IPv6Prefixes) + err = d.db.QueryRowContext(ctx, + "SELECT COUNT(*) FROM prefixes WHERE ip_version = ?", ipVersionV6).Scan(&stats.IPv6Prefixes) if err != nil { return stats, err } // Count peerings - err = d.queryRow("SELECT COUNT(*) FROM peerings").Scan(&stats.Peerings) + err = d.db.QueryRowContext(ctx, "SELECT COUNT(*) FROM peerings").Scan(&stats.Peerings) if err != nil { return stats, err } // Count peers - err = d.queryRow("SELECT COUNT(*) FROM bgp_peers").Scan(&stats.Peers) + err = d.db.QueryRowContext(ctx, "SELECT COUNT(*) FROM bgp_peers").Scan(&stats.Peers) if err != nil { return stats, err } @@ -796,13 +804,13 @@ func (d *Database) GetStats() (Stats, error) { } // Get live routes count - err = d.db.QueryRow("SELECT COUNT(*) FROM live_routes").Scan(&stats.LiveRoutes) + err = d.db.QueryRowContext(ctx, "SELECT COUNT(*) FROM live_routes").Scan(&stats.LiveRoutes) if err != nil { return stats, fmt.Errorf("failed to count live routes: %w", err) } // Get prefix distribution - stats.IPv4PrefixDistribution, stats.IPv6PrefixDistribution, err = d.GetPrefixDistribution() + stats.IPv4PrefixDistribution, stats.IPv6PrefixDistribution, err = d.GetPrefixDistributionContext(ctx) if err != nil { // Log but don't fail d.logger.Warn("Failed to get prefix distribution", "error", err) @@ -886,6 +894,12 @@ func (d *Database) DeleteLiveRoute(prefix string, originASN int, peerIP string) // GetPrefixDistribution returns the distribution of unique prefixes by mask length func (d *Database) GetPrefixDistribution() (ipv4 []PrefixDistribution, ipv6 []PrefixDistribution, err error) { + return d.GetPrefixDistributionContext(context.Background()) +} + +// GetPrefixDistributionContext returns the distribution of unique prefixes by mask length with context support +func (d *Database) GetPrefixDistributionContext(ctx context.Context) ( + ipv4 []PrefixDistribution, ipv6 []PrefixDistribution, err error) { // IPv4 distribution - count unique prefixes, not routes query := ` SELECT mask_length, COUNT(DISTINCT prefix) as count @@ -894,7 +908,7 @@ func (d *Database) GetPrefixDistribution() (ipv4 []PrefixDistribution, ipv6 []Pr GROUP BY mask_length ORDER BY mask_length ` - rows, err := d.db.Query(query) + rows, err := d.db.QueryContext(ctx, query) if err != nil { return nil, nil, fmt.Errorf("failed to query IPv4 distribution: %w", err) } @@ -916,7 +930,7 @@ func (d *Database) GetPrefixDistribution() (ipv4 []PrefixDistribution, ipv6 []Pr GROUP BY mask_length ORDER BY mask_length ` - rows, err = d.db.Query(query) + rows, err = d.db.QueryContext(ctx, query) if err != nil { return nil, nil, fmt.Errorf("failed to query IPv6 distribution: %w", err) } @@ -935,14 +949,19 @@ func (d *Database) GetPrefixDistribution() (ipv4 []PrefixDistribution, ipv6 []Pr // GetLiveRouteCounts returns the count of IPv4 and IPv6 routes func (d *Database) GetLiveRouteCounts() (ipv4Count, ipv6Count int, err error) { + return d.GetLiveRouteCountsContext(context.Background()) +} + +// GetLiveRouteCountsContext returns the count of IPv4 and IPv6 routes with context support +func (d *Database) GetLiveRouteCountsContext(ctx context.Context) (ipv4Count, ipv6Count int, err error) { // Get IPv4 count - err = d.db.QueryRow("SELECT COUNT(*) FROM live_routes WHERE ip_version = 4").Scan(&ipv4Count) + err = d.db.QueryRowContext(ctx, "SELECT COUNT(*) FROM live_routes WHERE ip_version = 4").Scan(&ipv4Count) if err != nil { return 0, 0, fmt.Errorf("failed to count IPv4 routes: %w", err) } // Get IPv6 count - err = d.db.QueryRow("SELECT COUNT(*) FROM live_routes WHERE ip_version = 6").Scan(&ipv6Count) + err = d.db.QueryRowContext(ctx, "SELECT COUNT(*) FROM live_routes WHERE ip_version = 6").Scan(&ipv6Count) if err != nil { return 0, 0, fmt.Errorf("failed to count IPv6 routes: %w", err) } @@ -952,6 +971,11 @@ func (d *Database) GetLiveRouteCounts() (ipv4Count, ipv6Count int, err error) { // GetASInfoForIP returns AS information for the given IP address func (d *Database) GetASInfoForIP(ip string) (*ASInfo, error) { + return d.GetASInfoForIPContext(context.Background(), ip) +} + +// GetASInfoForIPContext returns AS information for the given IP address with context support +func (d *Database) GetASInfoForIPContext(ctx context.Context, ip string) (*ASInfo, error) { // Parse the IP to validate it parsedIP := net.ParseIP(ip) if parsedIP == nil { @@ -984,7 +1008,7 @@ func (d *Database) GetASInfoForIP(ip string) (*ASInfo, error) { var lastUpdated time.Time var handle, description sql.NullString - err := d.db.QueryRow(query, ipVersionV4, ipUint, ipUint).Scan( + err := d.db.QueryRowContext(ctx, query, ipVersionV4, ipUint, ipUint).Scan( &prefix, &maskLength, &originASN, &lastUpdated, &handle, &description) if err != nil { if err == sql.ErrNoRows { @@ -1015,7 +1039,7 @@ func (d *Database) GetASInfoForIP(ip string) (*ASInfo, error) { ORDER BY lr.mask_length DESC ` - rows, err := d.db.Query(query, ipVersionV6) + rows, err := d.db.QueryContext(ctx, query, ipVersionV6) if err != nil { return nil, fmt.Errorf("failed to query routes: %w", err) } @@ -1118,11 +1142,16 @@ func CalculateIPv4Range(cidr string) (start, end uint32, err error) { // GetASDetails returns detailed information about an AS including prefixes func (d *Database) GetASDetails(asn int) (*ASN, []LiveRoute, error) { + return d.GetASDetailsContext(context.Background(), asn) +} + +// GetASDetailsContext returns detailed information about an AS including prefixes with context support +func (d *Database) GetASDetailsContext(ctx context.Context, asn int) (*ASN, []LiveRoute, error) { // Get AS information var asnInfo ASN var idStr string var handle, description sql.NullString - err := d.db.QueryRow( + err := d.db.QueryRowContext(ctx, "SELECT id, number, handle, description, first_seen, last_seen FROM asns WHERE number = ?", asn, ).Scan(&idStr, &asnInfo.Number, &handle, &description, &asnInfo.FirstSeen, &asnInfo.LastSeen) @@ -1147,7 +1176,7 @@ func (d *Database) GetASDetails(asn int) (*ASN, []LiveRoute, error) { GROUP BY prefix, mask_length, ip_version ` - rows, err := d.db.Query(query, asn) + rows, err := d.db.QueryContext(ctx, query, asn) if err != nil { return &asnInfo, nil, fmt.Errorf("failed to query prefixes: %w", err) } @@ -1183,6 +1212,11 @@ func (d *Database) GetASDetails(asn int) (*ASN, []LiveRoute, error) { // GetPrefixDetails returns detailed information about a prefix func (d *Database) GetPrefixDetails(prefix string) ([]LiveRoute, error) { + return d.GetPrefixDetailsContext(context.Background(), prefix) +} + +// GetPrefixDetailsContext returns detailed information about a prefix with context support +func (d *Database) GetPrefixDetailsContext(ctx context.Context, prefix string) ([]LiveRoute, error) { query := ` SELECT lr.origin_asn, lr.peer_ip, lr.as_path, lr.next_hop, lr.last_updated, a.handle, a.description @@ -1192,7 +1226,7 @@ func (d *Database) GetPrefixDetails(prefix string) ([]LiveRoute, error) { ORDER BY lr.origin_asn, lr.peer_ip ` - rows, err := d.db.Query(query, prefix) + rows, err := d.db.QueryContext(ctx, query, prefix) if err != nil { return nil, fmt.Errorf("failed to query prefix details: %w", err) } @@ -1230,6 +1264,12 @@ func (d *Database) GetPrefixDetails(prefix string) ([]LiveRoute, error) { // GetRandomPrefixesByLength returns a random sample of prefixes with the specified mask length func (d *Database) GetRandomPrefixesByLength(maskLength, ipVersion, limit int) ([]LiveRoute, error) { + return d.GetRandomPrefixesByLengthContext(context.Background(), maskLength, ipVersion, limit) +} + +// GetRandomPrefixesByLengthContext returns a random sample of prefixes with context support +func (d *Database) GetRandomPrefixesByLengthContext( + ctx context.Context, maskLength, ipVersion, limit int) ([]LiveRoute, error) { // Select unique prefixes with their most recent route information query := ` WITH unique_prefixes AS ( @@ -1247,7 +1287,7 @@ func (d *Database) GetRandomPrefixesByLength(maskLength, ipVersion, limit int) ( WHERE lr.mask_length = ? AND lr.ip_version = ? ` - rows, err := d.db.Query(query, maskLength, ipVersion, limit, maskLength, ipVersion) + rows, err := d.db.QueryContext(ctx, query, maskLength, ipVersion, limit, maskLength, ipVersion) if err != nil { return nil, fmt.Errorf("failed to query random prefixes: %w", err) } diff --git a/internal/database/interface.go b/internal/database/interface.go index c23a77a..76118dc 100644 --- a/internal/database/interface.go +++ b/internal/database/interface.go @@ -1,6 +1,7 @@ package database import ( + "context" "time" ) @@ -35,6 +36,7 @@ type Store interface { // Statistics GetStats() (Stats, error) + GetStatsContext(ctx context.Context) (Stats, error) // Peer operations UpdatePeer(peerIP string, peerASN int, messageType string, timestamp time.Time) error @@ -46,15 +48,21 @@ type Store interface { DeleteLiveRoute(prefix string, originASN int, peerIP string) error DeleteLiveRouteBatch(deletions []LiveRouteDeletion) error GetPrefixDistribution() (ipv4 []PrefixDistribution, ipv6 []PrefixDistribution, err error) + GetPrefixDistributionContext(ctx context.Context) (ipv4 []PrefixDistribution, ipv6 []PrefixDistribution, err error) GetLiveRouteCounts() (ipv4Count, ipv6Count int, err error) + GetLiveRouteCountsContext(ctx context.Context) (ipv4Count, ipv6Count int, err error) // IP lookup operations GetASInfoForIP(ip string) (*ASInfo, error) + GetASInfoForIPContext(ctx context.Context, ip string) (*ASInfo, error) // AS and prefix detail operations GetASDetails(asn int) (*ASN, []LiveRoute, error) + GetASDetailsContext(ctx context.Context, asn int) (*ASN, []LiveRoute, error) GetPrefixDetails(prefix string) ([]LiveRoute, error) + GetPrefixDetailsContext(ctx context.Context, prefix string) ([]LiveRoute, error) GetRandomPrefixesByLength(maskLength, ipVersion, limit int) ([]LiveRoute, error) + GetRandomPrefixesByLengthContext(ctx context.Context, maskLength, ipVersion, limit int) ([]LiveRoute, error) // Lifecycle Close() error diff --git a/internal/database/slowquery.go b/internal/database/slowquery.go index 2565ca1..ae10a93 100644 --- a/internal/database/slowquery.go +++ b/internal/database/slowquery.go @@ -19,6 +19,7 @@ func logSlowQuery(logger *logger.Logger, query string, start time.Time) { } // queryRow wraps QueryRow with slow query logging +// nolint:unused // kept for consistency with other query wrappers func (d *Database) queryRow(query string, args ...interface{}) *sql.Row { start := time.Now() defer logSlowQuery(d.logger, query, start) diff --git a/internal/routewatch/app_integration_test.go b/internal/routewatch/app_integration_test.go index 6292065..54701e7 100644 --- a/internal/routewatch/app_integration_test.go +++ b/internal/routewatch/app_integration_test.go @@ -163,6 +163,11 @@ func (m *mockStore) GetStats() (database.Stats, error) { }, nil } +// GetStatsContext returns statistics about the mock store with context support +func (m *mockStore) GetStatsContext(ctx context.Context) (database.Stats, error) { + return m.GetStats() +} + // UpsertLiveRoute mock implementation func (m *mockStore) UpsertLiveRoute(route *database.LiveRoute) error { // Simple mock - just return nil @@ -181,12 +186,22 @@ func (m *mockStore) GetPrefixDistribution() (ipv4 []database.PrefixDistribution, return nil, nil, nil } +// GetPrefixDistributionContext mock implementation with context support +func (m *mockStore) GetPrefixDistributionContext(ctx context.Context) (ipv4 []database.PrefixDistribution, ipv6 []database.PrefixDistribution, err error) { + return m.GetPrefixDistribution() +} + // GetLiveRouteCounts mock implementation func (m *mockStore) GetLiveRouteCounts() (ipv4Count, ipv6Count int, err error) { // Return mock counts return m.RouteCount / 2, m.RouteCount / 2, nil } +// GetLiveRouteCountsContext mock implementation with context support +func (m *mockStore) GetLiveRouteCountsContext(ctx context.Context) (ipv4Count, ipv6Count int, err error) { + return m.GetLiveRouteCounts() +} + // GetASInfoForIP mock implementation func (m *mockStore) GetASInfoForIP(ip string) (*database.ASInfo, error) { // Simple mock - return a test AS @@ -201,6 +216,11 @@ func (m *mockStore) GetASInfoForIP(ip string) (*database.ASInfo, error) { }, nil } +// GetASInfoForIPContext mock implementation with context support +func (m *mockStore) GetASInfoForIPContext(ctx context.Context, ip string) (*database.ASInfo, error) { + return m.GetASInfoForIP(ip) +} + // GetASDetails mock implementation func (m *mockStore) GetASDetails(asn int) (*database.ASN, []database.LiveRoute, error) { m.mu.Lock() @@ -215,17 +235,32 @@ func (m *mockStore) GetASDetails(asn int) (*database.ASN, []database.LiveRoute, return nil, nil, database.ErrNoRoute } +// GetASDetailsContext mock implementation with context support +func (m *mockStore) GetASDetailsContext(ctx context.Context, asn int) (*database.ASN, []database.LiveRoute, error) { + return m.GetASDetails(asn) +} + // GetPrefixDetails mock implementation func (m *mockStore) GetPrefixDetails(prefix string) ([]database.LiveRoute, error) { // Return empty routes for now return []database.LiveRoute{}, nil } +// GetPrefixDetailsContext mock implementation with context support +func (m *mockStore) GetPrefixDetailsContext(ctx context.Context, prefix string) ([]database.LiveRoute, error) { + return m.GetPrefixDetails(prefix) +} + func (m *mockStore) GetRandomPrefixesByLength(maskLength, ipVersion, limit int) ([]database.LiveRoute, error) { // Return empty routes for now return []database.LiveRoute{}, nil } +// GetRandomPrefixesByLengthContext mock implementation with context support +func (m *mockStore) GetRandomPrefixesByLengthContext(ctx context.Context, maskLength, ipVersion, limit int) ([]database.LiveRoute, error) { + return m.GetRandomPrefixesByLength(maskLength, ipVersion, limit) +} + // UpsertLiveRouteBatch mock implementation func (m *mockStore) UpsertLiveRouteBatch(routes []*database.LiveRoute) error { m.mu.Lock() diff --git a/internal/server/handlers.go b/internal/server/handlers.go index d405ffc..b12233f 100644 --- a/internal/server/handlers.go +++ b/internal/server/handlers.go @@ -92,7 +92,7 @@ func (s *Server) handleStatusJSON() http.HandlerFunc { errChan := make(chan error) go func() { - dbStats, err := s.db.GetStats() + dbStats, err := s.db.GetStatsContext(ctx) if err != nil { s.logger.Debug("Database stats query failed", "error", err) errChan <- err @@ -126,7 +126,7 @@ func (s *Server) handleStatusJSON() http.HandlerFunc { const bitsPerMegabit = 1000000.0 // Get route counts from database - ipv4Routes, ipv6Routes, err := s.db.GetLiveRouteCounts() + ipv4Routes, ipv6Routes, err := s.db.GetLiveRouteCountsContext(ctx) if err != nil { s.logger.Warn("Failed to get live route counts", "error", err) // Continue with zero counts @@ -234,7 +234,7 @@ func (s *Server) handleStats() http.HandlerFunc { errChan := make(chan error) go func() { - dbStats, err := s.db.GetStats() + dbStats, err := s.db.GetStatsContext(ctx) if err != nil { s.logger.Debug("Database stats query failed", "error", err) errChan <- err @@ -267,7 +267,7 @@ func (s *Server) handleStats() http.HandlerFunc { const bitsPerMegabit = 1000000.0 // Get route counts from database - ipv4Routes, ipv6Routes, err := s.db.GetLiveRouteCounts() + ipv4Routes, ipv6Routes, err := s.db.GetLiveRouteCountsContext(ctx) if err != nil { s.logger.Warn("Failed to get live route counts", "error", err) // Continue with zero counts @@ -354,7 +354,7 @@ func (s *Server) handleIPLookup() http.HandlerFunc { } // Look up AS information for the IP - asInfo, err := s.db.GetASInfoForIP(ip) + asInfo, err := s.db.GetASInfoForIPContext(r.Context(), ip) if err != nil { // Check if it's an invalid IP error if errors.Is(err, database.ErrInvalidIP) { @@ -385,7 +385,7 @@ func (s *Server) handleASDetailJSON() http.HandlerFunc { return } - asInfo, prefixes, err := s.db.GetASDetails(asn) + asInfo, prefixes, err := s.db.GetASDetailsContext(r.Context(), asn) if err != nil { if errors.Is(err, database.ErrNoRoute) { writeJSONError(w, http.StatusNotFound, err.Error()) @@ -438,7 +438,7 @@ func (s *Server) handlePrefixDetailJSON() http.HandlerFunc { return } - routes, err := s.db.GetPrefixDetails(prefix) + routes, err := s.db.GetPrefixDetailsContext(r.Context(), prefix) if err != nil { if errors.Is(err, database.ErrNoRoute) { writeJSONError(w, http.StatusNotFound, err.Error()) @@ -480,7 +480,7 @@ func (s *Server) handleASDetail() http.HandlerFunc { return } - asInfo, prefixes, err := s.db.GetASDetails(asn) + asInfo, prefixes, err := s.db.GetASDetailsContext(r.Context(), asn) if err != nil { if errors.Is(err, database.ErrNoRoute) { http.Error(w, "AS not found", http.StatusNotFound) @@ -584,7 +584,7 @@ func (s *Server) handlePrefixDetail() http.HandlerFunc { return } - routes, err := s.db.GetPrefixDetails(prefix) + routes, err := s.db.GetPrefixDetailsContext(r.Context(), prefix) if err != nil { if errors.Is(err, database.ErrNoRoute) { http.Error(w, "Prefix not found", http.StatusNotFound) @@ -607,7 +607,7 @@ func (s *Server) handlePrefixDetail() http.HandlerFunc { for _, route := range routes { if _, exists := originMap[route.OriginASN]; !exists { // Get AS info from database - asInfo, _, _ := s.db.GetASDetails(route.OriginASN) + asInfo, _, _ := s.db.GetASDetailsContext(r.Context(), route.OriginASN) handle := "" description := "" if asInfo != nil { @@ -768,7 +768,7 @@ func (s *Server) handlePrefixLength() http.HandlerFunc { // Get random sample of prefixes const maxPrefixes = 500 - prefixes, err := s.db.GetRandomPrefixesByLength(maskLength, ipVersion, maxPrefixes) + prefixes, err := s.db.GetRandomPrefixesByLengthContext(r.Context(), maskLength, ipVersion, maxPrefixes) if err != nil { s.logger.Error("Failed to get prefixes by length", "error", err) http.Error(w, "Internal server error", http.StatusInternalServerError) diff --git a/internal/streamer/streamer.go b/internal/streamer/streamer.go index 47847d4..2f9c9dd 100644 --- a/internal/streamer/streamer.go +++ b/internal/streamer/streamer.go @@ -9,7 +9,6 @@ import ( "fmt" "math" "net/http" - "os" "sync" "sync/atomic" "time" @@ -20,9 +19,12 @@ import ( ) const ( - risLiveURL = "https://ris-live.ripe.net/v1/stream/?format=json" + risLiveURL = "https://ris-live.ripe.net/v1/stream/?format=json&" + + "client=https%3A%2F%2Fgit.eeqj.de%2Fsneak%2Froutewatch" metricsWindowSize = 60 // seconds for rolling average metricsUpdateRate = time.Second + minBackoffDelay = 5 * time.Second + maxBackoffDelay = 320 * time.Second metricsLogInterval = 10 * time.Second bytesPerKB = 1024 bytesPerMB = 1024 * 1024 @@ -135,9 +137,7 @@ func (s *Streamer) Start() error { } go func() { - if err := s.stream(ctx); err != nil { - s.logger.Error("Streaming error", "error", err) - } + s.streamWithReconnect(ctx) s.mu.Lock() s.running = false s.mu.Unlock() @@ -324,6 +324,72 @@ func (s *Streamer) updateMetrics(messageBytes int) { s.metrics.RecordMessage(int64(messageBytes)) } +// streamWithReconnect handles streaming with automatic reconnection and exponential backoff +func (s *Streamer) streamWithReconnect(ctx context.Context) { + backoffDelay := minBackoffDelay + consecutiveFailures := 0 + + for { + select { + case <-ctx.Done(): + s.logger.Info("Stream context cancelled, stopping reconnection attempts") + + return + default: + } + + // Attempt to stream + startTime := time.Now() + err := s.stream(ctx) + streamDuration := time.Since(startTime) + + if err == nil { + // Clean exit (context cancelled) + return + } + + // Log the error + s.logger.Error("Stream disconnected", + "error", err, + "consecutive_failures", consecutiveFailures+1, + "stream_duration", streamDuration) + s.metrics.SetConnected(false) + + // Check if context is cancelled + if ctx.Err() != nil { + return + } + + // If we streamed for more than 30 seconds, reset the backoff + // This indicates we had a successful connection that received data + if streamDuration > 30*time.Second { + s.logger.Info("Resetting backoff delay due to successful connection", + "stream_duration", streamDuration) + backoffDelay = minBackoffDelay + consecutiveFailures = 0 + } else { + // Increment consecutive failures + consecutiveFailures++ + } + + // Wait with exponential backoff + s.logger.Info("Waiting before reconnection attempt", + "delay_seconds", backoffDelay.Seconds(), + "consecutive_failures", consecutiveFailures) + + select { + case <-ctx.Done(): + return + case <-time.After(backoffDelay): + // Double the backoff delay for next time, up to max + backoffDelay *= 2 + if backoffDelay > maxBackoffDelay { + backoffDelay = maxBackoffDelay + } + } + } +} + func (s *Streamer) stream(ctx context.Context) error { req, err := http.NewRequestWithContext(ctx, "GET", risLiveURL, nil) if err != nil { @@ -394,10 +460,13 @@ func (s *Streamer) stream(ctx context.Context) error { // Parse the message first var wrapper ristypes.RISLiveMessage if err := json.Unmarshal(line, &wrapper); err != nil { - // Output the raw line and panic on parse failure - fmt.Fprintf(os.Stderr, "Failed to parse JSON: %v\n", err) - fmt.Fprintf(os.Stderr, "Raw line: %s\n", string(line)) - panic(fmt.Sprintf("JSON parse error: %v", err)) + // Log the error and return to trigger reconnection + s.logger.Error("Failed to parse JSON", + "error", err, + "line", string(line), + "line_length", len(line)) + + return fmt.Errorf("JSON parse error: %w", err) } // Check if it's a ris_message wrapper @@ -447,18 +516,11 @@ func (s *Streamer) stream(ctx context.Context) error { // Peer state changes - silently ignore continue default: - fmt.Fprintf( - os.Stderr, - "UNKNOWN MESSAGE TYPE: %s\nRAW MESSAGE: %s\n", - msg.Type, - string(line), - ) - panic( - fmt.Sprintf( - "Unknown RIS message type: %s", - msg.Type, - ), + s.logger.Error("Unknown message type", + "type", msg.Type, + "line", string(line), ) + panic(fmt.Sprintf("Unknown RIS message type: %s", msg.Type)) } // Dispatch to interested handlers diff --git a/log.txt b/log.txt index fe60ccf..a603a49 100644 --- a/log.txt +++ b/log.txt @@ -19,3 +19,1155 @@ {"time":"2025-07-28T19:07:04.003748+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-28T19:07:17.095001+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"PRAGMA wal_checkpoint(TRUNCATE)","duration":3246961625} {"time":"2025-07-28T19:07:17.096647+02:00","level":"INFO","msg":"Running VACUUM to optimize database (this may take a moment)","source":"database.go:124","func":"database.(*Database).Initialize"} +{"time":"2025-07-28T19:07:33.635837+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"VACUUM","duration":16501666209} +[Fx] RUN provide: fx.Annotate(git.eeqj.de/sneak/routewatch/internal/database.New(), fx.As([[database.Store]]) in 29.642112125s +[Fx] BEFORE RUN provide: git.eeqj.de/sneak/routewatch/internal/metrics.New() +[Fx] RUN provide: git.eeqj.de/sneak/routewatch/internal/metrics.New() in 479.791µ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 193.625µ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 367.708µ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 35.958µs +[Fx] BEFORE RUN provide: go.uber.org/fx.(*App).shutdowner-fm() +[Fx] RUN provide: go.uber.org/fx.(*App).shutdowner-fm() in 164µ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 2.307875ms +{"time":"2025-07-28T19:07:33.654701+02:00","level":"INFO","msg":"Starting RouteWatch","source":"app.go:64","func":"routewatch.(*RouteWatch).Run"} +[Fx] RUNNING +{"time":"2025-07-28T19:07:33.657587+02:00","level":"INFO","msg":"Using batched database handlers for improved performance","source":"app.go:76","func":"routewatch.(*RouteWatch).Run"} +{"time":"2025-07-28T19:07:33.662391+02:00","level":"INFO","msg":"Starting HTTP server","source":"server.go:52","func":"server.(*Server).Start","port":"8080"} +2025/07/28 19:07:34 [akrotiri/nRQLu4lSAJ-000001] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3678B in 603.583125ms +2025/07/28 19:07:35 [akrotiri/nRQLu4lSAJ-000002] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3678B in 904.373541ms +2025/07/28 19:07:35 [akrotiri/nRQLu4lSAJ-000004] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3678B in 671.252042ms +2025/07/28 19:07:35 [akrotiri/nRQLu4lSAJ-000003] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3678B in 675.69775ms +2025/07/28 19:07:35 [akrotiri/nRQLu4lSAJ-000006] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3678B in 576.927958ms +2025/07/28 19:07:35 [akrotiri/nRQLu4lSAJ-000005] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3678B in 666.532458ms +{"time":"2025-07-28T19:07:36.003396+02:00","level":"INFO","msg":"Connected to RIS Live stream","source":"streamer.go:347","func":"streamer.(*Streamer).stream"} +2025/07/28 19:07:36 [akrotiri/nRQLu4lSAJ-000007] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3645B in 717.908292ms +2025/07/28 19:07:36 [akrotiri/nRQLu4lSAJ-000008] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3645B in 712.154459ms +{"time":"2025-07-28T19:07:36.672986+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:36.673015+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:07:36 [akrotiri/nRQLu4lSAJ-000009] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3654B in 641.762417ms +{"time":"2025-07-28T19:07:36.864033+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:37 [akrotiri/nRQLu4lSAJ-000011] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3660B in 725.372708ms +2025/07/28 19:07:37 [akrotiri/nRQLu4lSAJ-000012] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3659B in 715.984959ms +2025/07/28 19:07:37 [akrotiri/nRQLu4lSAJ-000010] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3660B in 1.420152834s +{"time":"2025-07-28T19:07:37.659829+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:37 [akrotiri/nRQLu4lSAJ-000014] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59225 - 200 3659B in 784.538792ms +2025/07/28 19:07:37 [akrotiri/nRQLu4lSAJ-000013] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3659B in 788.29225ms +{"time":"2025-07-28T19:07:37.968576+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"196.60.8.170","peer_asn":"327781"} +2025/07/28 19:07:38 [akrotiri/nRQLu4lSAJ-000015] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3663B in 732.397208ms +2025/07/28 19:07:38 [akrotiri/nRQLu4lSAJ-000016] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3663B in 744.506042ms +{"time":"2025-07-28T19:07:38.791129+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"80.81.192.113","peer_asn":"35320"} +2025/07/28 19:07:38 [akrotiri/nRQLu4lSAJ-000017] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3664B in 694.515708ms +2025/07/28 19:07:38 [akrotiri/nRQLu4lSAJ-000018] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3664B in 695.887209ms +{"time":"2025-07-28T19:07:39.107277+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":2434} +{"time":"2025-07-28T19:07:39.107299+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:39.107283+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:39 [akrotiri/nRQLu4lSAJ-000020] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3695B in 641.376541ms +2025/07/28 19:07:39 [akrotiri/nRQLu4lSAJ-000019] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3695B in 674.089541ms +{"time":"2025-07-28T19:07:39.491167+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":383} +{"time":"2025-07-28T19:07:39.491176+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:39.492337+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:39.495165+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +{"time":"2025-07-28T19:07:39.495174+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:39.503819+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":8} +{"time":"2025-07-28T19:07:39.503828+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:39.50383+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":9561,"unique_prefixes":5394,"success":5394,"duration_ms":2840} +{"time":"2025-07-28T19:07:39.51176+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:39.770906+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":267} +{"time":"2025-07-28T19:07:39.771667+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:39.772244+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:39 [akrotiri/nRQLu4lSAJ-000021] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3750B in 679.232333ms +2025/07/28 19:07:39 [akrotiri/nRQLu4lSAJ-000022] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3750B in 688.925042ms +2025/07/28 19:07:40 [akrotiri/nRQLu4lSAJ-000023] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3750B in 669.686167ms +2025/07/28 19:07:40 [akrotiri/nRQLu4lSAJ-000024] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3750B in 758.231208ms +{"time":"2025-07-28T19:07:40.552627+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:40 [akrotiri/nRQLu4lSAJ-000025] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3753B in 701.078792ms +2025/07/28 19:07:40 [akrotiri/nRQLu4lSAJ-000026] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3753B in 704.207542ms +2025/07/28 19:07:41 [akrotiri/nRQLu4lSAJ-000027] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3754B in 651.290958ms +2025/07/28 19:07:41 [akrotiri/nRQLu4lSAJ-000028] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3754B in 705.348625ms +2025/07/28 19:07:41 [akrotiri/nRQLu4lSAJ-000029] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3754B in 706.697959ms +2025/07/28 19:07:41 [akrotiri/nRQLu4lSAJ-000030] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3754B in 714.660708ms +{"time":"2025-07-28T19:07:42.186146+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":2414} +{"time":"2025-07-28T19:07:42.186168+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:42.186182+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +2025/07/28 19:07:42 [akrotiri/nRQLu4lSAJ-000032] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3755B in 676.637458ms +2025/07/28 19:07:42 [akrotiri/nRQLu4lSAJ-000031] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3755B in 716.843834ms +{"time":"2025-07-28T19:07:42.572063+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:42.572057+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":385} +{"time":"2025-07-28T19:07:42.573153+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:42.575387+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +{"time":"2025-07-28T19:07:42.575395+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:42.589817+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":14} +{"time":"2025-07-28T19:07:42.589869+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":6536,"success":6536,"duration_ms":3084} +{"time":"2025-07-28T19:07:42.59+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:42.597213+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:42.636158+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":46} +{"time":"2025-07-28T19:07:42.636179+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:42.637205+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:42.840773+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:42 [akrotiri/nRQLu4lSAJ-000033] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3751B in 783.942166ms +2025/07/28 19:07:42 [akrotiri/nRQLu4lSAJ-000034] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3751B in 780.201292ms +2025/07/28 19:07:43 [akrotiri/nRQLu4lSAJ-000035] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3752B in 754.8965ms +2025/07/28 19:07:43 [akrotiri/nRQLu4lSAJ-000036] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3753B in 824.056ms +2025/07/28 19:07:43 [akrotiri/nRQLu4lSAJ-000038] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3753B in 758.55275ms +2025/07/28 19:07:43 [akrotiri/nRQLu4lSAJ-000037] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3753B in 769.920042ms +{"time":"2025-07-28T19:07:44.01219+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1375} +{"time":"2025-07-28T19:07:44.012208+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:44.012194+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:44.30494+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":292} +{"time":"2025-07-28T19:07:44.30497+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:44.307148+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:44.327733+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":22} +{"time":"2025-07-28T19:07:44.327834+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:44.343496+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":15} +{"time":"2025-07-28T19:07:44.343512+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":6936,"success":6936,"duration_ms":1751} +{"time":"2025-07-28T19:07:44.343524+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:44.350607+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:07:44 [akrotiri/nRQLu4lSAJ-000039] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3751B in 712.754583ms +2025/07/28 19:07:44 [akrotiri/nRQLu4lSAJ-000040] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3751B in 710.354792ms +{"time":"2025-07-28T19:07:44.385329+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":41} +{"time":"2025-07-28T19:07:44.385375+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:44.559466+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:44 [akrotiri/nRQLu4lSAJ-000041] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3748B in 702.279541ms +2025/07/28 19:07:44 [akrotiri/nRQLu4lSAJ-000042] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3748B in 701.294542ms +2025/07/28 19:07:45 [akrotiri/nRQLu4lSAJ-000043] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3748B in 695.041792ms +{"time":"2025-07-28T19:07:45.393845+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:45.393863+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1008} +{"time":"2025-07-28T19:07:45.393886+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:45.417963+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":24} +{"time":"2025-07-28T19:07:45.417978+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:45.434464+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":16} +{"time":"2025-07-28T19:07:45.434478+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20001,"unique_prefixes":5668,"success":5668,"duration_ms":1088} +2025/07/28 19:07:45 [akrotiri/nRQLu4lSAJ-000044] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3741B in 826.800833ms +{"time":"2025-07-28T19:07:45.709986+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:45.710032+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:45 [akrotiri/nRQLu4lSAJ-000046] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3743B in 694.81025ms +2025/07/28 19:07:45 [akrotiri/nRQLu4lSAJ-000045] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3743B in 702.424375ms +{"time":"2025-07-28T19:07:45.932774+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:45.936665+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:45.975087+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:45.975101+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":265} +{"time":"2025-07-28T19:07:46.002255+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":27} +{"time":"2025-07-28T19:07:46.002274+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:46.004553+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":10001041625,"total_messages":40448,"total_bytes":27830819,"total_mb":"26.54","messages_per_sec":"513.85","bits_per_sec":"2839908","mbps":"2.84","total_dropped":0} +{"time":"2025-07-28T19:07:46.004568+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":0,"queue_cap":100000,"processed":39967,"dropped":0,"avg_time":211514,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:07:46.004573+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":39967,"dropped":0,"avg_time":133450,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:07:46.004577+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":297,"queue_cap":100000,"processed":39669,"dropped":0,"avg_time":219636,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:07:46.00458+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":39967,"dropped":0,"avg_time":1615,"min_time":0,"max_time":1217875} +2025/07/28 19:07:46 [akrotiri/nRQLu4lSAJ-000048] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3746B in 684.118292ms +{"time":"2025-07-28T19:07:46.429834+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"193.239.118.249","peer_asn":"41255"} +2025/07/28 19:07:46 [akrotiri/nRQLu4lSAJ-000047] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3746B in 788.57475ms +{"time":"2025-07-28T19:07:46.787382+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":785} +{"time":"2025-07-28T19:07:46.787401+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:46.787405+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +2025/07/28 19:07:46 [akrotiri/nRQLu4lSAJ-000050] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3746B in 704.959625ms +2025/07/28 19:07:46 [akrotiri/nRQLu4lSAJ-000049] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3746B in 719.08ms +{"time":"2025-07-28T19:07:46.984448+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":197} +{"time":"2025-07-28T19:07:46.984466+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20085,"unique_prefixes":4980,"success":4980,"duration_ms":1052} +{"time":"2025-07-28T19:07:47.019767+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:47.019782+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:47.04221+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":22} +2025/07/28 19:07:47 [akrotiri/nRQLu4lSAJ-000052] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3743B in 687.238791ms +2025/07/28 19:07:47 [akrotiri/nRQLu4lSAJ-000051] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3743B in 745.021ms +2025/07/28 19:07:47 [akrotiri/nRQLu4lSAJ-000053] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3743B in 696.837417ms +2025/07/28 19:07:47 [akrotiri/nRQLu4lSAJ-000054] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3743B in 703.614834ms +{"time":"2025-07-28T19:07:48.165713+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"195.208.209.174","peer_asn":"25227"} +{"time":"2025-07-28T19:07:48.221125+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:48.221143+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:48.231799+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":10} +{"time":"2025-07-28T19:07:48.25413+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:48.254157+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:48.25997+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:48.326908+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":72} +{"time":"2025-07-28T19:07:48.327021+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:07:48 [akrotiri/nRQLu4lSAJ-000055] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3746B in 693.772708ms +2025/07/28 19:07:48 [akrotiri/nRQLu4lSAJ-000056] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3746B in 702.133083ms +2025/07/28 19:07:48 [akrotiri/nRQLu4lSAJ-000058] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3744B in 697.475208ms +2025/07/28 19:07:48 [akrotiri/nRQLu4lSAJ-000057] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3744B in 710.6995ms +{"time":"2025-07-28T19:07:49.296131+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:49.323427+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:49.323423+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":996} +{"time":"2025-07-28T19:07:49.323474+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +2025/07/28 19:07:49 [akrotiri/nRQLu4lSAJ-000059] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3750B in 688.046209ms +{"time":"2025-07-28T19:07:49.453644+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:49.453659+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":130} +{"time":"2025-07-28T19:07:49.458008+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":4} +{"time":"2025-07-28T19:07:49.458021+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20190,"unique_prefixes":6983,"success":6983,"duration_ms":1205} +2025/07/28 19:07:49 [akrotiri/nRQLu4lSAJ-000060] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3745B in 818.270792ms +2025/07/28 19:07:49 [akrotiri/nRQLu4lSAJ-000061] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3745B in 662.160042ms +2025/07/28 19:07:49 [akrotiri/nRQLu4lSAJ-000062] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3745B in 676.558541ms +{"time":"2025-07-28T19:07:50.06625+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:7f8::8b0e:0:1","peer_asn":"35598"} +{"time":"2025-07-28T19:07:50.070162+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"2001:7f8::8b0e:0:1","peer_asn":"35598"} +2025/07/28 19:07:50 [akrotiri/nRQLu4lSAJ-000063] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3745B in 677.152625ms +2025/07/28 19:07:50 [akrotiri/nRQLu4lSAJ-000064] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3745B in 669.689125ms +{"time":"2025-07-28T19:07:50.448121+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:50.448139+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:50.454422+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":6} +{"time":"2025-07-28T19:07:50.565058+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:50.565073+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:50.566553+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:50.606524+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":41} +{"time":"2025-07-28T19:07:50.606547+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:50.722444+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:7f8:4::73ab:1","peer_asn":"29611"} +2025/07/28 19:07:50 [akrotiri/nRQLu4lSAJ-000065] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3748B in 693.311792ms +2025/07/28 19:07:50 [akrotiri/nRQLu4lSAJ-000066] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3748B in 699.954ms +{"time":"2025-07-28T19:07:51.134236+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"80.81.194.190","peer_asn":"31042"} +2025/07/28 19:07:51 [akrotiri/nRQLu4lSAJ-000068] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3748B in 707.918916ms +2025/07/28 19:07:51 [akrotiri/nRQLu4lSAJ-000067] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3748B in 771.511292ms +{"time":"2025-07-28T19:07:51.461056+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:51.848782+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1242} +{"time":"2025-07-28T19:07:51.848848+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:51.848812+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:51.93417+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":85} +{"time":"2025-07-28T19:07:51.934198+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:51.94368+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":9} +{"time":"2025-07-28T19:07:51.943695+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20001,"unique_prefixes":8173,"success":8173,"duration_ms":1383} +{"time":"2025-07-28T19:07:52.06137+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"2001:7f8:1::a503:5598:1","peer_asn":"35598"} +{"time":"2025-07-28T19:07:52.065582+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:7f8:1::a503:5598:1","peer_asn":"35598"} +{"time":"2025-07-28T19:07:52.632916+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:52.632933+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:52.642619+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":9} +{"time":"2025-07-28T19:07:52.646434+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:52.646482+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:07:52 [akrotiri/nRQLu4lSAJ-000070] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3746B in 870.904125ms +2025/07/28 19:07:52 [akrotiri/nRQLu4lSAJ-000071] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3746B in 871.853125ms +2025/07/28 19:07:52 [akrotiri/nRQLu4lSAJ-000072] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3746B in 890.421666ms +{"time":"2025-07-28T19:07:52.769576+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:52 [akrotiri/nRQLu4lSAJ-000069] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3751B in 1.017418291s +{"time":"2025-07-28T19:07:52.958053+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"80.81.194.92","peer_asn":"57111"} +2025/07/28 19:07:53 [akrotiri/nRQLu4lSAJ-000073] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59225 - 200 3750B in 845.957791ms +2025/07/28 19:07:53 [akrotiri/nRQLu4lSAJ-000074] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59361 - 200 3750B in 843.555208ms +2025/07/28 19:07:53 [akrotiri/nRQLu4lSAJ-000075] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3750B in 805.870541ms +2025/07/28 19:07:53 [akrotiri/nRQLu4lSAJ-000076] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3750B in 825.081125ms +{"time":"2025-07-28T19:07:53.61985+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:53.870881+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1224} +{"time":"2025-07-28T19:07:53.870901+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:53.871004+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:53 [akrotiri/nRQLu4lSAJ-000077] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3755B in 763.138375ms +2025/07/28 19:07:53 [akrotiri/nRQLu4lSAJ-000078] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3755B in 761.375958ms +{"time":"2025-07-28T19:07:53.974506+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":103} +{"time":"2025-07-28T19:07:53.974544+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:53.975705+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:53.97694+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":2} +{"time":"2025-07-28T19:07:53.977005+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:53.992346+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":15} +{"time":"2025-07-28T19:07:53.992359+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:53.992363+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20060,"unique_prefixes":10445,"success":10445,"duration_ms":1363} +{"time":"2025-07-28T19:07:54.003621+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:54.049992+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:54.050057+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":57} +{"time":"2025-07-28T19:07:54.05159+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:54 [akrotiri/nRQLu4lSAJ-000079] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3748B in 782.620916ms +2025/07/28 19:07:54 [akrotiri/nRQLu4lSAJ-000080] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3748B in 775.60675ms +{"time":"2025-07-28T19:07:55.014494+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:55 [akrotiri/nRQLu4lSAJ-000081] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3750B in 828.106958ms +2025/07/28 19:07:55 [akrotiri/nRQLu4lSAJ-000082] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3753B in 831.940291ms +{"time":"2025-07-28T19:07:55.234058+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1184} +{"time":"2025-07-28T19:07:55.234075+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:55.234059+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:55.383518+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":149} +{"time":"2025-07-28T19:07:55.38354+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:55.385772+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:55.388237+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":4} +{"time":"2025-07-28T19:07:55.388261+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:55.392534+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":4} +{"time":"2025-07-28T19:07:55.392548+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20007,"unique_prefixes":10489,"success":10489,"duration_ms":1398} +{"time":"2025-07-28T19:07:55.392585+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:55.404466+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:55.478219+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":85} +{"time":"2025-07-28T19:07:55.47825+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:55.48057+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:55 [akrotiri/nRQLu4lSAJ-000084] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3750B in 810.51475ms +2025/07/28 19:07:55 [akrotiri/nRQLu4lSAJ-000083] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3750B in 825.17325ms +2025/07/28 19:07:55 [akrotiri/nRQLu4lSAJ-000086] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3750B in 758.836375ms +2025/07/28 19:07:55 [akrotiri/nRQLu4lSAJ-000085] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3750B in 766.820959ms +{"time":"2025-07-28T19:07:56.004642+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":20001042667,"total_messages":96768,"total_bytes":71476257,"total_mb":"68.17","messages_per_sec":"1184.63","bits_per_sec":"6946267","mbps":"6.95","total_dropped":0} +{"time":"2025-07-28T19:07:56.004665+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":5972,"queue_cap":100000,"processed":89786,"dropped":0,"avg_time":132996,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:07:56.00467+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":95759,"dropped":0,"avg_time":63838,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:07:56.004675+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":7170,"queue_cap":100000,"processed":88588,"dropped":0,"avg_time":170700,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:07:56.004678+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":95759,"dropped":0,"avg_time":1799,"min_time":0,"max_time":3326042} +2025/07/28 19:07:56 [akrotiri/nRQLu4lSAJ-000087] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3751B in 735.267334ms +{"time":"2025-07-28T19:07:56.456094+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:56 [akrotiri/nRQLu4lSAJ-000088] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3752B in 760.225458ms +{"time":"2025-07-28T19:07:56.563199+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1084} +{"time":"2025-07-28T19:07:56.563219+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:56.563236+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:56.67658+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":113} +{"time":"2025-07-28T19:07:56.676616+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:56.678673+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:56.679956+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +{"time":"2025-07-28T19:07:56.680035+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:56.68251+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":2} +{"time":"2025-07-28T19:07:56.682522+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":11375,"success":11375,"duration_ms":1288} +{"time":"2025-07-28T19:07:56.682552+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:56.697985+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:56.820378+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":137} +{"time":"2025-07-28T19:07:56.820402+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:56.82158+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:56 [akrotiri/nRQLu4lSAJ-000089] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3752B in 786.163708ms +2025/07/28 19:07:57 [akrotiri/nRQLu4lSAJ-000090] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3752B in 808.440625ms +{"time":"2025-07-28T19:07:57.325497+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"80.249.210.89","peer_asn":"31042"} +{"time":"2025-07-28T19:07:57.416999+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:57 [akrotiri/nRQLu4lSAJ-000091] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3759B in 781.648208ms +2025/07/28 19:07:57 [akrotiri/nRQLu4lSAJ-000092] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3759B in 777.83225ms +2025/07/28 19:07:58 [akrotiri/nRQLu4lSAJ-000093] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3759B in 731.82675ms +2025/07/28 19:07:58 [akrotiri/nRQLu4lSAJ-000094] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3759B in 740.918209ms +{"time":"2025-07-28T19:07:58.032601+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1212} +{"time":"2025-07-28T19:07:58.032625+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:58.032608+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:58.094801+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":62} +{"time":"2025-07-28T19:07:58.094816+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:58.096021+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:58.096984+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":2} +{"time":"2025-07-28T19:07:58.096997+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:58.098353+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":1} +{"time":"2025-07-28T19:07:58.098363+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20002,"unique_prefixes":12115,"success":12115,"duration_ms":1413} +{"time":"2025-07-28T19:07:58.098388+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:58.113012+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:58.199584+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:58.19958+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":101} +{"time":"2025-07-28T19:07:58.200716+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:58.472772+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:07:58 [akrotiri/nRQLu4lSAJ-000095] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3760B in 763.777959ms +2025/07/28 19:07:58 [akrotiri/nRQLu4lSAJ-000096] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3761B in 774.523041ms +{"time":"2025-07-28T19:07:58.635195+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"2602:fa91:0:cccc::20","peer_asn":"53427"} +2025/07/28 19:07:58 [akrotiri/nRQLu4lSAJ-000097] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3761B in 775.922417ms +2025/07/28 19:07:59 [akrotiri/nRQLu4lSAJ-000098] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3763B in 798.730542ms +{"time":"2025-07-28T19:07:59.277503+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:59.277472+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1077} +{"time":"2025-07-28T19:07:59.277617+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:59.43262+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":155} +{"time":"2025-07-28T19:07:59.433803+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:59.43381+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:07:59 [akrotiri/nRQLu4lSAJ-000099] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3763B in 746.758958ms +2025/07/28 19:07:59 [akrotiri/nRQLu4lSAJ-000100] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3763B in 746.649708ms +{"time":"2025-07-28T19:07:59.515959+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:59.515961+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":82} +{"time":"2025-07-28T19:07:59.517117+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:59.517871+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:07:59.51788+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":1} +{"time":"2025-07-28T19:07:59.519218+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:59.519238+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":1} +{"time":"2025-07-28T19:07:59.51926+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20036,"unique_prefixes":10966,"success":10966,"duration_ms":1419} +{"time":"2025-07-28T19:07:59.519737+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:59.529842+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:07:59.567245+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":48} +{"time":"2025-07-28T19:07:59.56728+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:07:59.5684+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:07:59.569388+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":2} +{"time":"2025-07-28T19:07:59.569429+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:07:59 [akrotiri/nRQLu4lSAJ-000101] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3761B in 764.993875ms +2025/07/28 19:08:00 [akrotiri/nRQLu4lSAJ-000102] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3761B in 774.816541ms +{"time":"2025-07-28T19:08:00.064229+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:00 [akrotiri/nRQLu4lSAJ-000103] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3765B in 748.079ms +2025/07/28 19:08:00 [akrotiri/nRQLu4lSAJ-000104] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3765B in 783.1225ms +{"time":"2025-07-28T19:08:00.620066+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1050} +{"time":"2025-07-28T19:08:00.620079+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:00.620085+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:00.704707+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":84} +{"time":"2025-07-28T19:08:00.704797+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:00.706413+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:00.706636+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":1} +{"time":"2025-07-28T19:08:00.706643+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:00.709913+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":3} +{"time":"2025-07-28T19:08:00.70992+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:00.709924+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20003,"unique_prefixes":10446,"success":10446,"duration_ms":1188} +{"time":"2025-07-28T19:08:00.720894+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:00.79123+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":81} +{"time":"2025-07-28T19:08:00.791254+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:00.792429+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:00 [akrotiri/nRQLu4lSAJ-000106] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3761B in 739.773042ms +2025/07/28 19:08:00 [akrotiri/nRQLu4lSAJ-000105] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3761B in 753.927583ms +2025/07/28 19:08:01 [akrotiri/nRQLu4lSAJ-000107] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3761B in 751.062375ms +2025/07/28 19:08:01 [akrotiri/nRQLu4lSAJ-000108] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3761B in 762.420375ms +{"time":"2025-07-28T19:08:01.565814+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:7f8::7942:0:1","peer_asn":"31042"} +{"time":"2025-07-28T19:08:01.587985+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:01 [akrotiri/nRQLu4lSAJ-000110] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3764B in 733.316541ms +2025/07/28 19:08:02 [akrotiri/nRQLu4lSAJ-000109] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3764B in 776.968625ms +{"time":"2025-07-28T19:08:02.073141+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1281} +{"time":"2025-07-28T19:08:02.073146+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:02.073185+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:02.125268+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":52} +{"time":"2025-07-28T19:08:02.125279+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:02.126945+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:02.128212+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":2} +{"time":"2025-07-28T19:08:02.128249+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:02.132224+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":3} +{"time":"2025-07-28T19:08:02.132232+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:02.132236+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20178,"unique_prefixes":12081,"success":12081,"duration_ms":1420} +{"time":"2025-07-28T19:08:02.146181+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:02.24666+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":114} +{"time":"2025-07-28T19:08:02.246673+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:02.247964+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:02 [akrotiri/nRQLu4lSAJ-000111] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3761B in 744.355667ms +2025/07/28 19:08:02 [akrotiri/nRQLu4lSAJ-000112] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3761B in 773.2495ms +2025/07/28 19:08:03 [akrotiri/nRQLu4lSAJ-000114] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3761B in 750.066916ms +2025/07/28 19:08:03 [akrotiri/nRQLu4lSAJ-000113] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3761B in 752.982917ms +2025/07/28 19:08:03 [akrotiri/nRQLu4lSAJ-000116] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3761B in 768.463791ms +2025/07/28 19:08:03 [akrotiri/nRQLu4lSAJ-000115] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3761B in 770.904166ms +{"time":"2025-07-28T19:08:03.641517+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1394} +{"time":"2025-07-28T19:08:03.641526+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:03.641538+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:03.753251+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":111} +{"time":"2025-07-28T19:08:03.753291+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:03.75591+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:03.759854+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":6} +{"time":"2025-07-28T19:08:03.759866+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":14843,"success":14843,"duration_ms":1625} +{"time":"2025-07-28T19:08:03.759886+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:03.772878+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:03.863427+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":103} +{"time":"2025-07-28T19:08:03.863431+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:03.865955+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:03 [akrotiri/nRQLu4lSAJ-000117] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3762B in 741.542208ms +2025/07/28 19:08:04 [akrotiri/nRQLu4lSAJ-000118] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3761B in 751.191208ms +{"time":"2025-07-28T19:08:04.092732+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"102.67.56.1","peer_asn":"328474"} +{"time":"2025-07-28T19:08:04.259315+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:04.385529+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"186.211.128.34","peer_asn":"14840"} +{"time":"2025-07-28T19:08:04.385629+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"186.211.128.34","peer_asn":"14840"} +2025/07/28 19:08:04 [akrotiri/nRQLu4lSAJ-000120] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3764B in 772.839292ms +2025/07/28 19:08:04 [akrotiri/nRQLu4lSAJ-000119] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3764B in 782.157667ms +{"time":"2025-07-28T19:08:04.954011+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:12f8::221:238","peer_asn":"262317"} +2025/07/28 19:08:05 [akrotiri/nRQLu4lSAJ-000122] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3763B in 783.544667ms +2025/07/28 19:08:05 [akrotiri/nRQLu4lSAJ-000121] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3763B in 789.895292ms +{"time":"2025-07-28T19:08:05.052625+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1189} +{"time":"2025-07-28T19:08:05.052643+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:05.052655+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:05.105556+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":52} +{"time":"2025-07-28T19:08:05.105565+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:05.106782+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:05.108567+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +{"time":"2025-07-28T19:08:05.108599+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:05.112153+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":3} +{"time":"2025-07-28T19:08:05.11217+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20078,"unique_prefixes":12394,"success":12394,"duration_ms":1350} +{"time":"2025-07-28T19:08:05.112171+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:05.127667+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:05.206908+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":94} +{"time":"2025-07-28T19:08:05.206916+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:05.208013+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:05 [akrotiri/nRQLu4lSAJ-000123] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3758B in 826.184708ms +2025/07/28 19:08:05 [akrotiri/nRQLu4lSAJ-000124] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3758B in 839.739833ms +{"time":"2025-07-28T19:08:05.816151+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:06.004191+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":30000484167,"total_messages":172032,"total_bytes":126005632,"total_mb":"120.17","messages_per_sec":"2165.68","bits_per_sec":"12786101","mbps":"12.79","total_dropped":0} +{"time":"2025-07-28T19:08:06.004226+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":10894,"queue_cap":100000,"processed":159687,"dropped":0,"avg_time":135667,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:08:06.004237+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":1441,"queue_cap":100000,"processed":169140,"dropped":0,"avg_time":60095,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:08:06.004315+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":19350,"queue_cap":100000,"processed":151231,"dropped":0,"avg_time":164230,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:08:06.004354+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":170582,"dropped":0,"avg_time":1814,"min_time":0,"max_time":3326042} +2025/07/28 19:08:06 [akrotiri/nRQLu4lSAJ-000125] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 200 3762B in 861.26525ms +2025/07/28 19:08:06 [akrotiri/nRQLu4lSAJ-000126] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3762B in 878.993083ms +2025/07/28 19:08:06 [akrotiri/nRQLu4lSAJ-000127] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 200 3763B in 826.930041ms +2025/07/28 19:08:06 [akrotiri/nRQLu4lSAJ-000128] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3763B in 838.380708ms +{"time":"2025-07-28T19:08:07.102186+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1895} +{"time":"2025-07-28T19:08:07.102203+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:07.102207+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:07.111804+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:07.111819+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":9} +{"time":"2025-07-28T19:08:07.111839+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20010,"unique_prefixes":12491,"success":12491,"duration_ms":1998} +{"time":"2025-07-28T19:08:07.135738+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:07.144036+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +{"time":"2025-07-28T19:08:07.144057+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:07 [akrotiri/nRQLu4lSAJ-000131] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59151 - 408 151B in 379.261416ms +2025/07/28 19:08:07 [akrotiri/nRQLu4lSAJ-000129] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59154 - 408 151B in 406.081625ms +{"time":"2025-07-28T19:08:07.155384+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:07.155547+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":43} +{"time":"2025-07-28T19:08:07.158127+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:07.15936+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +{"time":"2025-07-28T19:08:07.159375+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:07 [akrotiri/nRQLu4lSAJ-000130] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3760B in 957.286084ms +2025/07/28 19:08:07 [akrotiri/nRQLu4lSAJ-000132] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3760B in 939.063083ms +{"time":"2025-07-28T19:08:07.71021+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:08 [akrotiri/nRQLu4lSAJ-000134] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59361 - 200 3763B in 894.611167ms +2025/07/28 19:08:08 [akrotiri/nRQLu4lSAJ-000135] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59374 - 200 3763B in 888.741ms +{"time":"2025-07-28T19:08:08.16524+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"103.200.113.1","peer_asn":"131477"} +2025/07/28 19:08:08 [akrotiri/nRQLu4lSAJ-000136] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3763B in 854.105834ms +2025/07/28 19:08:08 [akrotiri/nRQLu4lSAJ-000137] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3763B in 855.303625ms +{"time":"2025-07-28T19:08:08.710087+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:08.710087+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1550} +{"time":"2025-07-28T19:08:08.710167+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:08.73078+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:08.730844+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":20} +{"time":"2025-07-28T19:08:08.732323+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:08.735035+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:08.735132+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":4} +{"time":"2025-07-28T19:08:08.749723+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:08.749739+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":14} +{"time":"2025-07-28T19:08:08.749769+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":10761,"success":10761,"duration_ms":1636} +{"time":"2025-07-28T19:08:08.762742+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:08.791185+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":41} +{"time":"2025-07-28T19:08:08.791219+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:08.792569+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:09 [akrotiri/nRQLu4lSAJ-000138] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59361 - 200 3760B in 903.582542ms +2025/07/28 19:08:09 [akrotiri/nRQLu4lSAJ-000139] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59374 - 200 3760B in 893.859041ms +2025/07/28 19:08:09 [akrotiri/nRQLu4lSAJ-000133] "GET http://127.0.0.1:8080/prefixlength/22 HTTP/1.1" from 127.0.0.1:59225 - 408 135B in 2.000398917s +2025/07/28 19:08:09 [akrotiri/nRQLu4lSAJ-000141] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3760B in 1.10750725s +2025/07/28 19:08:09 [akrotiri/nRQLu4lSAJ-000140] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3760B in 1.121125584s +{"time":"2025-07-28T19:08:10.062221+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:10.102263+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:10.102263+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1311} +{"time":"2025-07-28T19:08:10.102294+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:10.135009+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":32} +{"time":"2025-07-28T19:08:10.135276+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:10.137338+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:10.141868+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":6} +{"time":"2025-07-28T19:08:10.142041+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:10.153681+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:10.153838+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":11} +{"time":"2025-07-28T19:08:10.153852+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20001,"unique_prefixes":8531,"success":8531,"duration_ms":1401} +{"time":"2025-07-28T19:08:10.161405+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:10.204999+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":51} +{"time":"2025-07-28T19:08:10.205075+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:10.207641+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:10 [akrotiri/nRQLu4lSAJ-000143] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59374 - 200 3760B in 1.146915958s +2025/07/28 19:08:10 [akrotiri/nRQLu4lSAJ-000144] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59376 - 200 3760B in 1.159083416s +{"time":"2025-07-28T19:08:10.802585+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:10 [akrotiri/nRQLu4lSAJ-000145] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59377 - 408 17B in 1.001297458s +{"time":"2025-07-28T19:08:10.837049+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"2400:c3e0::2","peer_asn":"142271"} +{"time":"2025-07-28T19:08:10.91727+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":712} +{"time":"2025-07-28T19:08:10.917293+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:10.917298+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:10.933631+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:10.934167+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":16} +{"time":"2025-07-28T19:08:10.934218+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":2865,"success":2865,"duration_ms":777} +{"time":"2025-07-28T19:08:10.94409+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:10.980883+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":47} +{"time":"2025-07-28T19:08:10.981341+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:10.983384+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:11 [akrotiri/nRQLu4lSAJ-000146] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3759B in 1.203097334s +2025/07/28 19:08:11 [akrotiri/nRQLu4lSAJ-000142] "GET http://127.0.0.1:8080/prefixlength/22 HTTP/1.1" from 127.0.0.1:59361 - 408 135B in 2.000990667s +{"time":"2025-07-28T19:08:11.286307+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"198.32.160.113","peer_asn":"15547"} +2025/07/28 19:08:11 [akrotiri/nRQLu4lSAJ-000147] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3760B in 1.233922791s +2025/07/28 19:08:11 [akrotiri/nRQLu4lSAJ-000148] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59374 - 200 3760B in 1.187058833s +{"time":"2025-07-28T19:08:11.779192+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:11 [akrotiri/nRQLu4lSAJ-000149] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59376 - 408 17B in 1.0028745s +{"time":"2025-07-28T19:08:11.804012+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:11 [akrotiri/nRQLu4lSAJ-000150] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59379 - 408 17B in 1.000656708s +2025/07/28 19:08:12 [akrotiri/nRQLu4lSAJ-000151] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 200 3760B in 1.314775292s +{"time":"2025-07-28T19:08:12.521089+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1539} +{"time":"2025-07-28T19:08:12.521124+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:12.521133+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:12.556054+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:12.556099+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":34} +{"time":"2025-07-28T19:08:12.556128+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":3913,"success":3913,"duration_ms":1619} +{"time":"2025-07-28T19:08:12.617882+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":61} +{"time":"2025-07-28T19:08:12.620312+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:12.620326+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:12.733693+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":111} +{"time":"2025-07-28T19:08:12.73616+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:12.736186+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:12.775116+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":38} +2025/07/28 19:08:12 [akrotiri/nRQLu4lSAJ-000153] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 200 3753B in 1.267609459s +{"time":"2025-07-28T19:08:12.785153+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:12 [akrotiri/nRQLu4lSAJ-000155] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59381 - 408 17B in 1.003883s +{"time":"2025-07-28T19:08:12.806171+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:12 [akrotiri/nRQLu4lSAJ-000156] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59382 - 408 17B in 1.000950167s +{"time":"2025-07-28T19:08:12.849975+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:12.850003+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:12.880337+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":30} +2025/07/28 19:08:12 [akrotiri/nRQLu4lSAJ-000154] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59374 - 200 3753B in 1.345688208s +{"time":"2025-07-28T19:08:13.138476+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:13.138503+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:13 [akrotiri/nRQLu4lSAJ-000152] "GET http://127.0.0.1:8080/prefixlength/22 HTTP/1.1" from 127.0.0.1:59380 - 408 135B in 2.002604958s +{"time":"2025-07-28T19:08:13.410969+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:13 [akrotiri/nRQLu4lSAJ-000157] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59153 - 408 17B in 1.001096958s +{"time":"2025-07-28T19:08:13.646076+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":507} +{"time":"2025-07-28T19:08:13.646095+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:13.6461+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:13.652136+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":5} +{"time":"2025-07-28T19:08:13.652197+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":4767,"success":4767,"duration_ms":520} +{"time":"2025-07-28T19:08:13.785883+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:13 [akrotiri/nRQLu4lSAJ-000158] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59150 - 408 17B in 1.006791959s +{"time":"2025-07-28T19:08:13.787357+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:13 [akrotiri/nRQLu4lSAJ-000159] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59384 - 408 17B in 1.001558666s +{"time":"2025-07-28T19:08:13.807074+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:13 [akrotiri/nRQLu4lSAJ-000160] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59385 - 408 17B in 1.000131625s +{"time":"2025-07-28T19:08:13.957189+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:13 [akrotiri/nRQLu4lSAJ-000161] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59374 - 408 17B in 1.001823167s +{"time":"2025-07-28T19:08:14.183508+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:14 [akrotiri/nRQLu4lSAJ-000162] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59386 - 408 17B in 1.000910667s +{"time":"2025-07-28T19:08:14.261084+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:14.261113+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:14.323682+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":62} +{"time":"2025-07-28T19:08:14.506607+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:b18:10::3","peer_asn":"47787"} +{"time":"2025-07-28T19:08:14.667334+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:14.667368+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:14.790016+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:14 [akrotiri/nRQLu4lSAJ-000164] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59388 - 408 17B in 1.000692s +{"time":"2025-07-28T19:08:14.799135+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:14 [akrotiri/nRQLu4lSAJ-000165] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59389 - 408 17B in 1.008588417s +{"time":"2025-07-28T19:08:14.961095+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:14 [akrotiri/nRQLu4lSAJ-000167] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59391 - 408 17B in 1.001378458s +2025/07/28 19:08:15 [akrotiri/nRQLu4lSAJ-000166] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59390 - 200 3755B in 1.288205208s +2025/07/28 19:08:15 [akrotiri/nRQLu4lSAJ-000163] "GET http://127.0.0.1:8080/prefixlength/22 HTTP/1.1" from 127.0.0.1:59387 - 408 135B in 2.001762166s +{"time":"2025-07-28T19:08:15.186082+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:15 [akrotiri/nRQLu4lSAJ-000168] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59392 - 408 17B in 1.000421291s +{"time":"2025-07-28T19:08:15.291864+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM prefixes","duration":56013625} +{"time":"2025-07-28T19:08:15.440781+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":773} +{"time":"2025-07-28T19:08:15.4408+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:15.440804+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:15.442674+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":1} +{"time":"2025-07-28T19:08:15.442687+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":8234,"unique_prefixes":1663,"success":1663,"duration_ms":779} +{"time":"2025-07-28T19:08:15.660325+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:15.66036+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:15.792499+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:15 [akrotiri/nRQLu4lSAJ-000169] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59394 - 408 17B in 1.001657917s +{"time":"2025-07-28T19:08:15.801348+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:15 [akrotiri/nRQLu4lSAJ-000170] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59395 - 408 17B in 1.001492791s +{"time":"2025-07-28T19:08:15.839252+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:15.908511+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":248} +{"time":"2025-07-28T19:08:15.912469+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:15.967145+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:15 [akrotiri/nRQLu4lSAJ-000171] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59396 - 408 17B in 1.003547167s +{"time":"2025-07-28T19:08:16.008638+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":40004628500,"total_messages":210432,"total_bytes":152371437,"total_mb":"145.31","messages_per_sec":"2523.63","bits_per_sec":"14628534","mbps":"14.63","total_dropped":0} +{"time":"2025-07-28T19:08:16.017094+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":204,"queue_cap":100000,"processed":208259,"dropped":0,"avg_time":140660,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:08:16.01711+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":208464,"dropped":0,"avg_time":61546,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:08:16.017118+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":0,"queue_cap":100000,"processed":208464,"dropped":0,"avg_time":159871,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:08:16.017126+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":208464,"dropped":0,"avg_time":1898,"min_time":0,"max_time":10314750} +{"time":"2025-07-28T19:08:16.044008+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":131} +{"time":"2025-07-28T19:08:16.109469+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:16 [akrotiri/nRQLu4lSAJ-000172] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59390 - 408 17B in 1.00463425s +{"time":"2025-07-28T19:08:16.187409+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:16 [akrotiri/nRQLu4lSAJ-000173] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59397 - 408 17B in 1.001187916s +{"time":"2025-07-28T19:08:16.66975+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:16.669766+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:16.799905+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:16 [akrotiri/nRQLu4lSAJ-000175] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59399 - 408 17B in 1.006673667s +{"time":"2025-07-28T19:08:16.801779+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:de8:4::1:8403:1","peer_asn":"18403"} +{"time":"2025-07-28T19:08:16.802145+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:16 [akrotiri/nRQLu4lSAJ-000176] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59400 - 408 17B in 1.000122541s +{"time":"2025-07-28T19:08:16.968794+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:16 [akrotiri/nRQLu4lSAJ-000177] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59401 - 408 17B in 1.000725166s +2025/07/28 19:08:17 [akrotiri/nRQLu4lSAJ-000183] "GET http://127.0.0.1:8080/prefixlength/128 HTTP/1.1" from 127.0.0.1:59408 - 200 7442B in 1.795959ms +{"time":"2025-07-28T19:08:17.118767+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:17 [akrotiri/nRQLu4lSAJ-000178] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59402 - 408 17B in 1.008219917s +2025/07/28 19:08:17 [akrotiri/nRQLu4lSAJ-000174] "GET http://127.0.0.1:8080/prefixlength/22 HTTP/1.1" from 127.0.0.1:59398 - 200 191902B in 1.998639042s +{"time":"2025-07-28T19:08:17.1904+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:17 [akrotiri/nRQLu4lSAJ-000179] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59403 - 408 17B in 1.002409125s +{"time":"2025-07-28T19:08:17.272694+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:17.802801+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:17 [akrotiri/nRQLu4lSAJ-000180] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59405 - 408 17B in 1.000817958s +{"time":"2025-07-28T19:08:17.803362+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:43f8:6d0::60","peer_asn":"37468"} +{"time":"2025-07-28T19:08:17.806676+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:17 [akrotiri/nRQLu4lSAJ-000181] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59406 - 408 17B in 1.004242083s +{"time":"2025-07-28T19:08:17.976576+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:17 [akrotiri/nRQLu4lSAJ-000182] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59407 - 408 17B in 1.003798167s +{"time":"2025-07-28T19:08:17.998312+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM peerings","duration":66096000} +{"time":"2025-07-28T19:08:18.124502+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:18 [akrotiri/nRQLu4lSAJ-000184] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59408 - 408 17B in 1.004432s +{"time":"2025-07-28T19:08:18.178122+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM prefixes WHERE ip_version = ?","duration":131551500} +{"time":"2025-07-28T19:08:18.186574+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:18 [akrotiri/nRQLu4lSAJ-000185] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59398 - 408 17B in 1.000868167s +{"time":"2025-07-28T19:08:18.191922+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:18 [akrotiri/nRQLu4lSAJ-000186] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59409 - 408 17B in 1.000417083s +{"time":"2025-07-28T19:08:18.259671+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM bgp_peers","duration":64531292} +{"time":"2025-07-28T19:08:18.259997+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM prefixes","duration":65359084} +{"time":"2025-07-28T19:08:18.278504+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":85992417} +{"time":"2025-07-28T19:08:18.304314+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:18.32996+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1660} +{"time":"2025-07-28T19:08:18.329976+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:18.329981+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:18.330027+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM prefixes WHERE ip_version = ?","duration":70415625} +{"time":"2025-07-28T19:08:18.347879+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:18.348036+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":17} +{"time":"2025-07-28T19:08:18.348091+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":13654,"unique_prefixes":3860,"success":3860,"duration_ms":1684} +{"time":"2025-07-28T19:08:18.385798+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:18.386296+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":37} +{"time":"2025-07-28T19:08:18.40841+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:18.442814+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:18.485114+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":99} +{"time":"2025-07-28T19:08:18.48537+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:18.485416+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM prefixes WHERE ip_version = ?","duration":125381833} +{"time":"2025-07-28T19:08:18.575325+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":89} +{"time":"2025-07-28T19:08:18.575578+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:18.805812+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:18 [akrotiri/nRQLu4lSAJ-000187] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59410 - 408 17B in 1.00254275s +{"time":"2025-07-28T19:08:18.808577+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:18 [akrotiri/nRQLu4lSAJ-000188] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59411 - 408 17B in 1.024969375s +{"time":"2025-07-28T19:08:18.979246+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:18 [akrotiri/nRQLu4lSAJ-000189] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59412 - 408 17B in 1.001201917s +{"time":"2025-07-28T19:08:19.127074+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM prefixes","duration":143170791} +{"time":"2025-07-28T19:08:19.130041+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:19 [akrotiri/nRQLu4lSAJ-000190] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59413 - 408 17B in 1.004298s +{"time":"2025-07-28T19:08:19.19263+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +{"time":"2025-07-28T19:08:19.200033+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:19 [akrotiri/nRQLu4lSAJ-000191] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59414 - 408 17B in 1.011819916s +2025/07/28 19:08:19 [akrotiri/nRQLu4lSAJ-000192] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59415 - 408 17B in 1.007628375s +{"time":"2025-07-28T19:08:19.276227+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM bgp_peers","duration":89706875} +{"time":"2025-07-28T19:08:19.286193+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM asns","duration":84675625} +{"time":"2025-07-28T19:08:19.808954+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:19 [akrotiri/nRQLu4lSAJ-000193] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59417 - 408 17B in 1.001136459s +{"time":"2025-07-28T19:08:19.841998+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:19 [akrotiri/nRQLu4lSAJ-000194] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59418 - 408 17B in 1.007844417s +{"time":"2025-07-28T19:08:20.005451+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:20 [akrotiri/nRQLu4lSAJ-000195] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59419 - 408 17B in 1.024671542s +{"time":"2025-07-28T19:08:20.116723+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:20.132483+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:20 [akrotiri/nRQLu4lSAJ-000196] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59420 - 408 17B in 1.00057575s +{"time":"2025-07-28T19:08:20.202532+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:20 [akrotiri/nRQLu4lSAJ-000197] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59421 - 408 17B in 1.001289417s +{"time":"2025-07-28T19:08:20.202887+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:20 [akrotiri/nRQLu4lSAJ-000198] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59422 - 408 17B in 1.001543166s +{"time":"2025-07-28T19:08:20.543539+02:00","level":"DEBUG","msg":"Slow query","source":"slowquery.go:17","func":"database.logSlowQuery","query":"SELECT COUNT(*) FROM peerings","duration":187139125} +{"time":"2025-07-28T19:08:20.70497+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":2129} +{"time":"2025-07-28T19:08:20.705+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:20.705008+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:20.711695+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:20.71258+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":6} +{"time":"2025-07-28T19:08:20.712604+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20003,"unique_prefixes":9835,"success":9835,"duration_ms":2282} +{"time":"2025-07-28T19:08:20.7633+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":51} +{"time":"2025-07-28T19:08:20.811179+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:20 [akrotiri/nRQLu4lSAJ-000199] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59423 - 408 17B in 1.000767708s +{"time":"2025-07-28T19:08:20.843804+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:20 [akrotiri/nRQLu4lSAJ-000200] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59424 - 408 17B in 1.001282125s +{"time":"2025-07-28T19:08:21.009173+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:21 [akrotiri/nRQLu4lSAJ-000201] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59425 - 408 17B in 1.001428625s +{"time":"2025-07-28T19:08:21.135173+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:21 [akrotiri/nRQLu4lSAJ-000202] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59426 - 408 17B in 1.002054125s +{"time":"2025-07-28T19:08:21.204549+02:00","level":"ERROR","msg":"Database stats timeout","source":"handlers.go:250","func":"server.(*Server).setupRoutes.func1.(*Server).handleStats.1"} +2025/07/28 19:08:21 [akrotiri/nRQLu4lSAJ-000204] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59427 - 408 17B in 1.001135084s +2025/07/28 19:08:21 [akrotiri/nRQLu4lSAJ-000203] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3754B in 1.13904825s +{"time":"2025-07-28T19:08:21.641501+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:21.641516+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:21.717351+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":75} +2025/07/28 19:08:21 [akrotiri/nRQLu4lSAJ-000205] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 1.018510834s +2025/07/28 19:08:21 [akrotiri/nRQLu4lSAJ-000206] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 1.020566333s +{"time":"2025-07-28T19:08:22.048299+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:22.048315+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:22.077782+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:22.11331+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":64} +{"time":"2025-07-28T19:08:22.113265+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:22 [akrotiri/nRQLu4lSAJ-000207] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 1.1265015s +2025/07/28 19:08:22 [akrotiri/nRQLu4lSAJ-000208] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3756B in 1.06053575s +{"time":"2025-07-28T19:08:22.320431+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"196.60.8.60","peer_asn":"37468"} +2025/07/28 19:08:22 [akrotiri/nRQLu4lSAJ-000209] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3757B in 1.152573584s +2025/07/28 19:08:22 [akrotiri/nRQLu4lSAJ-000210] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3760B in 1.135201958s +2025/07/28 19:08:22 [akrotiri/nRQLu4lSAJ-000212] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3757B in 1.125838625s +2025/07/28 19:08:22 [akrotiri/nRQLu4lSAJ-000211] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3757B in 1.169336541s +{"time":"2025-07-28T19:08:23.122404+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"193.107.13.3","peer_asn":"47787"} +2025/07/28 19:08:23 [akrotiri/nRQLu4lSAJ-000213] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3757B in 1.109921584s +2025/07/28 19:08:23 [akrotiri/nRQLu4lSAJ-000214] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3757B in 1.117077583s +{"time":"2025-07-28T19:08:23.374575+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:23.385104+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1271} +{"time":"2025-07-28T19:08:23.385185+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:23.385241+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:23.426993+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":41} +{"time":"2025-07-28T19:08:23.427017+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +2025/07/28 19:08:23 [akrotiri/nRQLu4lSAJ-000215] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3757B in 1.101775792s +{"time":"2025-07-28T19:08:23.468659+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":41} +{"time":"2025-07-28T19:08:23.468676+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20005,"unique_prefixes":6645,"success":6645,"duration_ms":1399} +2025/07/28 19:08:23 [akrotiri/nRQLu4lSAJ-000216] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3754B in 1.089047958s +{"time":"2025-07-28T19:08:23.874899+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:23.874925+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:24 [akrotiri/nRQLu4lSAJ-000217] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 1.076448041s +2025/07/28 19:08:24 [akrotiri/nRQLu4lSAJ-000218] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 1.089797375s +2025/07/28 19:08:24 [akrotiri/nRQLu4lSAJ-000219] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 969.097417ms +{"time":"2025-07-28T19:08:24.327552+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:24 [akrotiri/nRQLu4lSAJ-000220] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3759B in 1.062289917s +2025/07/28 19:08:24 [akrotiri/nRQLu4lSAJ-000221] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3760B in 1.062829042s +2025/07/28 19:08:24 [akrotiri/nRQLu4lSAJ-000222] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3760B in 1.076154292s +{"time":"2025-07-28T19:08:24.664824+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:25 [akrotiri/nRQLu4lSAJ-000223] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3763B in 1.108321583s +2025/07/28 19:08:25 [akrotiri/nRQLu4lSAJ-000224] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3763B in 1.109602042s +2025/07/28 19:08:25 [akrotiri/nRQLu4lSAJ-000225] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3763B in 1.052190333s +{"time":"2025-07-28T19:08:25.335737+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1460} +{"time":"2025-07-28T19:08:25.335757+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:25.335804+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:25.344238+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":8} +{"time":"2025-07-28T19:08:25.344271+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:25 [akrotiri/nRQLu4lSAJ-000226] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3760B in 1.09577275s +{"time":"2025-07-28T19:08:25.48333+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":139} +{"time":"2025-07-28T19:08:25.483757+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:25.490088+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":6} +{"time":"2025-07-28T19:08:25.490105+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20013,"unique_prefixes":8865,"success":8865,"duration_ms":1629} +2025/07/28 19:08:25 [akrotiri/nRQLu4lSAJ-000227] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3754B in 1.064976958s +2025/07/28 19:08:25 [akrotiri/nRQLu4lSAJ-000228] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3754B in 1.1105515s +{"time":"2025-07-28T19:08:26.004312+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":50000442125,"total_messages":245593,"total_bytes":177028891,"total_mb":"168.83","messages_per_sec":"2661.85","bits_per_sec":"15336850","mbps":"15.34","total_dropped":0} +{"time":"2025-07-28T19:08:26.004347+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":0,"queue_cap":100000,"processed":243142,"dropped":0,"avg_time":133166,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:08:26.004358+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":243142,"dropped":0,"avg_time":58151,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:08:26.004366+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":0,"queue_cap":100000,"processed":243142,"dropped":0,"avg_time":165693,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:08:26.004373+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":243142,"dropped":0,"avg_time":2069,"min_time":0,"max_time":20882459} +2025/07/28 19:08:26 [akrotiri/nRQLu4lSAJ-000229] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 1.041385416s +2025/07/28 19:08:26 [akrotiri/nRQLu4lSAJ-000230] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 1.063147166s +{"time":"2025-07-28T19:08:26.29021+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:26.290227+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:26.336384+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":46} +2025/07/28 19:08:26 [akrotiri/nRQLu4lSAJ-000231] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 1.095675833s +{"time":"2025-07-28T19:08:26.39104+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"80.81.194.204","peer_asn":"48166"} +2025/07/28 19:08:26 [akrotiri/nRQLu4lSAJ-000232] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3753B in 963.227ms +{"time":"2025-07-28T19:08:26.552771+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:26.552788+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:26 [akrotiri/nRQLu4lSAJ-000233] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3755B in 999.683292ms +2025/07/28 19:08:26 [akrotiri/nRQLu4lSAJ-000234] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3756B in 1.023684542s +2025/07/28 19:08:27 [akrotiri/nRQLu4lSAJ-000235] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3757B in 1.087896542s +2025/07/28 19:08:27 [akrotiri/nRQLu4lSAJ-000236] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3757B in 1.071200959s +{"time":"2025-07-28T19:08:27.389095+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:27 [akrotiri/nRQLu4lSAJ-000237] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3758B in 1.094182709s +2025/07/28 19:08:27 [akrotiri/nRQLu4lSAJ-000238] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3758B in 1.073683959s +2025/07/28 19:08:27 [akrotiri/nRQLu4lSAJ-000239] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3759B in 1.098977792s +{"time":"2025-07-28T19:08:27.76415+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:27.764158+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1211} +{"time":"2025-07-28T19:08:27.764184+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:27.778124+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":13} +{"time":"2025-07-28T19:08:27.778143+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:27.787948+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":9} +{"time":"2025-07-28T19:08:27.787966+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":6135,"success":6135,"duration_ms":1243} +{"time":"2025-07-28T19:08:27.813536+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:27.813549+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:27 [akrotiri/nRQLu4lSAJ-000240] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3755B in 1.074659375s +{"time":"2025-07-28T19:08:27.871822+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":58} +{"time":"2025-07-28T19:08:28.277914+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"2001:12f8::121","peer_asn":"42473"} +{"time":"2025-07-28T19:08:28.282425+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:12f8::121","peer_asn":"42473"} +2025/07/28 19:08:28 [akrotiri/nRQLu4lSAJ-000241] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 1.061955042s +2025/07/28 19:08:28 [akrotiri/nRQLu4lSAJ-000242] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 1.080827333s +2025/07/28 19:08:28 [akrotiri/nRQLu4lSAJ-000243] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 1.051267292s +2025/07/28 19:08:28 [akrotiri/nRQLu4lSAJ-000244] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3754B in 1.018064334s +2025/07/28 19:08:28 [akrotiri/nRQLu4lSAJ-000245] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3753B in 982.598916ms +2025/07/28 19:08:28 [akrotiri/nRQLu4lSAJ-000246] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59428 - 200 3753B in 960.169333ms +{"time":"2025-07-28T19:08:28.828053+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:28.828081+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:28.947988+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":119} +2025/07/28 19:08:29 [akrotiri/nRQLu4lSAJ-000247] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3753B in 899.490792ms +2025/07/28 19:08:29 [akrotiri/nRQLu4lSAJ-000248] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3753B in 886.198958ms +{"time":"2025-07-28T19:08:29.38112+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:29.381147+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:29 [akrotiri/nRQLu4lSAJ-000249] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3755B in 864.334ms +2025/07/28 19:08:29 [akrotiri/nRQLu4lSAJ-000250] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59433 - 200 3755B in 871.581417ms +{"time":"2025-07-28T19:08:29.417747+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:29 [akrotiri/nRQLu4lSAJ-000251] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59434 - 200 3758B in 746.747542ms +{"time":"2025-07-28T19:08:29.790615+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":409} +{"time":"2025-07-28T19:08:29.79064+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:29.790622+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:29.793977+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +{"time":"2025-07-28T19:08:29.793999+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:29.83782+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":43} +{"time":"2025-07-28T19:08:29.837835+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20009,"unique_prefixes":9043,"success":9043,"duration_ms":466} +{"time":"2025-07-28T19:08:29.865667+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:29.865685+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:29.900598+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":34} +{"time":"2025-07-28T19:08:29.940564+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:29.940581+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:30 [akrotiri/nRQLu4lSAJ-000252] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3753B in 673.332625ms +{"time":"2025-07-28T19:08:30.330755+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":390} +{"time":"2025-07-28T19:08:30.330772+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:30.330776+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:30.369903+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":39} +{"time":"2025-07-28T19:08:30.369921+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20007,"unique_prefixes":17330,"success":17330,"duration_ms":443} +{"time":"2025-07-28T19:08:30.430228+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:30.43024+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:30.463905+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":33} +{"time":"2025-07-28T19:08:30.600148+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:30.600164+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:30 [akrotiri/nRQLu4lSAJ-000253] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 658.970167ms +{"time":"2025-07-28T19:08:30.650478+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:31.002825+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":402} +{"time":"2025-07-28T19:08:31.002851+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:31.002833+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:31.005408+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":2} +{"time":"2025-07-28T19:08:31.005445+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:31.007851+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":2} +{"time":"2025-07-28T19:08:31.00786+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":17577,"success":17577,"duration_ms":419} +2025/07/28 19:08:31 [akrotiri/nRQLu4lSAJ-000254] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3751B in 640.66375ms +{"time":"2025-07-28T19:08:31.131814+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:31.131826+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:31.209497+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":77} +{"time":"2025-07-28T19:08:31.394478+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:31.394493+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:31 [akrotiri/nRQLu4lSAJ-000255] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3755B in 648.955208ms +{"time":"2025-07-28T19:08:31.961427+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:32.052114+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:32 [akrotiri/nRQLu4lSAJ-000256] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3761B in 729.255584ms +2025/07/28 19:08:32 [akrotiri/nRQLu4lSAJ-000257] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3761B in 662.749375ms +{"time":"2025-07-28T19:08:32.742275+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1347} +{"time":"2025-07-28T19:08:32.742294+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:32.742311+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:32.921695+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":179} +{"time":"2025-07-28T19:08:32.921709+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:32.922853+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:32.923575+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":1} +{"time":"2025-07-28T19:08:32.923594+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:32.928459+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":4} +{"time":"2025-07-28T19:08:32.928466+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:32.928471+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":16497,"success":16497,"duration_ms":1543} +{"time":"2025-07-28T19:08:32.942775+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:32.985476+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":57} +{"time":"2025-07-28T19:08:32.985489+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:33 [akrotiri/nRQLu4lSAJ-000258] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 714.2415ms +{"time":"2025-07-28T19:08:33.653594+02:00","level":"DEBUG","msg":"System stats","source":"cli.go:40","func":"routewatch.logDebugStats","goroutines":83,"alloc_mb":97,"total_alloc_mb":1720,"sys_mb":137,"num_gc":49,"heap_alloc_mb":97,"heap_sys_mb":125,"heap_idle_mb":22,"heap_inuse_mb":102,"heap_released_mb":15,"stack_inuse_mb":2} +2025/07/28 19:08:33 [akrotiri/nRQLu4lSAJ-000259] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3755B in 690.170375ms +{"time":"2025-07-28T19:08:34.023451+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:34 [akrotiri/nRQLu4lSAJ-000260] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3757B in 639.157458ms +{"time":"2025-07-28T19:08:34.120439+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:34.563495+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1577} +{"time":"2025-07-28T19:08:34.563515+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:34.56352+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:34.645032+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":81} +{"time":"2025-07-28T19:08:34.645035+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:34.64928+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":4} +{"time":"2025-07-28T19:08:34.649303+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:34.65688+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":7} +{"time":"2025-07-28T19:08:34.656894+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20007,"unique_prefixes":17320,"success":17320,"duration_ms":1727} +{"time":"2025-07-28T19:08:34.664534+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:34.664547+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:34 [akrotiri/nRQLu4lSAJ-000261] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 736.743708ms +{"time":"2025-07-28T19:08:34.818992+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:35.035348+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"2001:7f8:1::a503:1042:1","peer_asn":"31042"} +2025/07/28 19:08:35 [akrotiri/nRQLu4lSAJ-000262] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3758B in 787.74675ms +{"time":"2025-07-28T19:08:35.647681+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:35.647681+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":983} +{"time":"2025-07-28T19:08:35.64773+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +2025/07/28 19:08:35 [akrotiri/nRQLu4lSAJ-000263] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3759B in 702.227791ms +{"time":"2025-07-28T19:08:35.791126+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:35.791122+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":143} +{"time":"2025-07-28T19:08:35.79726+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":6} +{"time":"2025-07-28T19:08:35.797272+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20005,"unique_prefixes":7951,"success":7951,"duration_ms":1139} +{"time":"2025-07-28T19:08:35.802998+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:35.803009+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:36.004086+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":60000166625,"total_messages":297984,"total_bytes":216255311,"total_mb":"206.24","messages_per_sec":"3040.71","bits_per_sec":"17698667","mbps":"17.70","total_dropped":0} +{"time":"2025-07-28T19:08:36.004107+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":0,"queue_cap":100000,"processed":295105,"dropped":0,"avg_time":119904,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:08:36.004112+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":295105,"dropped":0,"avg_time":56514,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:08:36.004115+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":961,"queue_cap":100000,"processed":294143,"dropped":0,"avg_time":160729,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:08:36.004118+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":295105,"dropped":0,"avg_time":2031,"min_time":0,"max_time":20882459} +{"time":"2025-07-28T19:08:36.203492+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:36.338531+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"217.29.66.232","peer_asn":"54104"} +{"time":"2025-07-28T19:08:36.341477+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +2025/07/28 19:08:36 [akrotiri/nRQLu4lSAJ-000264] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3759B in 860.047708ms +{"time":"2025-07-28T19:08:36.522808+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:36.52284+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":719} +{"time":"2025-07-28T19:08:36.522876+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:36.561225+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":38} +{"time":"2025-07-28T19:08:36.561266+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:36.56591+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":4} +{"time":"2025-07-28T19:08:36.565945+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:36.570159+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":4} +{"time":"2025-07-28T19:08:36.570169+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20001,"unique_prefixes":5742,"success":5742,"duration_ms":771} +2025/07/28 19:08:36 [akrotiri/nRQLu4lSAJ-000265] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3752B in 739.382417ms +{"time":"2025-07-28T19:08:37.417883+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:37.417898+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:37 [akrotiri/nRQLu4lSAJ-000266] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 623.284125ms +{"time":"2025-07-28T19:08:37.498092+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":80} +2025/07/28 19:08:37 [akrotiri/nRQLu4lSAJ-000267] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3753B in 622.882375ms +{"time":"2025-07-28T19:08:37.667058+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:37.667078+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:37.736365+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"195.208.208.187","peer_asn":"9002"} +2025/07/28 19:08:38 [akrotiri/nRQLu4lSAJ-000268] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 645.478791ms +{"time":"2025-07-28T19:08:38.324788+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":657} +{"time":"2025-07-28T19:08:38.324804+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:38.324808+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:38.415062+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":90} +{"time":"2025-07-28T19:08:38.415082+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":16418,"unique_prefixes":7199,"success":7199,"duration_ms":752} +{"time":"2025-07-28T19:08:38.519524+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:38.519537+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:38.563551+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":44} +{"time":"2025-07-28T19:08:38.619037+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:38.619054+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:38.625245+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":6} +2025/07/28 19:08:38 [akrotiri/nRQLu4lSAJ-000269] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3753B in 640.730292ms +2025/07/28 19:08:39 [akrotiri/nRQLu4lSAJ-000270] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 679.340083ms +2025/07/28 19:08:39 [akrotiri/nRQLu4lSAJ-000271] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 648.752416ms +{"time":"2025-07-28T19:08:39.665076+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:39.665087+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:40.021877+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":356} +{"time":"2025-07-28T19:08:40.021894+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:40.021901+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:40.075277+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:40.075856+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":53} +{"time":"2025-07-28T19:08:40.07587+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":12790,"unique_prefixes":3484,"success":3484,"duration_ms":413} +{"time":"2025-07-28T19:08:40.07588+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:40.10634+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":30} +2025/07/28 19:08:40 [akrotiri/nRQLu4lSAJ-000272] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 703.211584ms +{"time":"2025-07-28T19:08:40.62553+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"80.81.192.113","peer_asn":"35320"} +2025/07/28 19:08:40 [akrotiri/nRQLu4lSAJ-000273] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 663.594ms +{"time":"2025-07-28T19:08:40.871914+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:40.871926+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:40.905366+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:40.913924+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":41} +{"time":"2025-07-28T19:08:40.91393+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:40.917132+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +2025/07/28 19:08:41 [akrotiri/nRQLu4lSAJ-000274] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 646.394666ms +{"time":"2025-07-28T19:08:41.216624+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"196.60.8.170","peer_asn":"327781"} +2025/07/28 19:08:41 [akrotiri/nRQLu4lSAJ-000275] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 600.239208ms +{"time":"2025-07-28T19:08:41.668475+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:41.66849+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:42.115819+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:42 [akrotiri/nRQLu4lSAJ-000276] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3759B in 586.912ms +{"time":"2025-07-28T19:08:42.472822+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:42.472819+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":804} +{"time":"2025-07-28T19:08:42.472861+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:42.510436+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":37} +{"time":"2025-07-28T19:08:42.510447+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:42.513694+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":3} +{"time":"2025-07-28T19:08:42.513706+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":19350,"unique_prefixes":7616,"success":7616,"duration_ms":850} +2025/07/28 19:08:42 [akrotiri/nRQLu4lSAJ-000277] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 672.594416ms +{"time":"2025-07-28T19:08:42.89924+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:42.899255+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:42.918192+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:42.991005+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":91} +{"time":"2025-07-28T19:08:42.991014+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:42.994176+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +2025/07/28 19:08:43 [akrotiri/nRQLu4lSAJ-000278] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 619.220584ms +2025/07/28 19:08:43 [akrotiri/nRQLu4lSAJ-000279] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3752B in 592.1105ms +{"time":"2025-07-28T19:08:43.667804+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:43.667818+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:44 [akrotiri/nRQLu4lSAJ-000280] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3751B in 651.86725ms +{"time":"2025-07-28T19:08:44.465271+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":797} +{"time":"2025-07-28T19:08:44.465312+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:44.465316+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:44.467972+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:44.475088+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":9} +{"time":"2025-07-28T19:08:44.475096+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:44.4751+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":18694,"unique_prefixes":6390,"success":6390,"duration_ms":812} +{"time":"2025-07-28T19:08:44.599514+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":124} +2025/07/28 19:08:44 [akrotiri/nRQLu4lSAJ-000281] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3749B in 801.422083ms +2025/07/28 19:08:45 [akrotiri/nRQLu4lSAJ-000282] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3749B in 604.868ms +{"time":"2025-07-28T19:08:45.580503+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:45.580522+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:45.601613+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:45.608413+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:45 [akrotiri/nRQLu4lSAJ-000283] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3755B in 556.036542ms +{"time":"2025-07-28T19:08:45.61972+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":39} +{"time":"2025-07-28T19:08:45.619728+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:45.622759+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":3} +{"time":"2025-07-28T19:08:45.622778+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:46.004541+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":70000555625,"total_messages":342016,"total_bytes":247383573,"total_mb":"235.92","messages_per_sec":"3247.06","bits_per_sec":"18750228","mbps":"18.75","total_dropped":0} +{"time":"2025-07-28T19:08:46.004577+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":0,"queue_cap":100000,"processed":338648,"dropped":0,"avg_time":108108,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:08:46.004582+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":338648,"dropped":0,"avg_time":50285,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:08:46.004591+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":1218,"queue_cap":100000,"processed":337429,"dropped":0,"avg_time":148948,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:08:46.004595+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":338648,"dropped":0,"avg_time":1943,"min_time":0,"max_time":20882459} +2025/07/28 19:08:46 [akrotiri/nRQLu4lSAJ-000284] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3753B in 725.505083ms +{"time":"2025-07-28T19:08:46.740561+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":1117} +{"time":"2025-07-28T19:08:46.74058+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:46.740584+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:46.764025+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":23} +{"time":"2025-07-28T19:08:46.764041+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":20000,"unique_prefixes":10148,"success":10148,"duration_ms":1164} +2025/07/28 19:08:46 [akrotiri/nRQLu4lSAJ-000285] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3750B in 767.819125ms +2025/07/28 19:08:47 [akrotiri/nRQLu4lSAJ-000286] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3750B in 627.9065ms +{"time":"2025-07-28T19:08:47.191751+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:47.191762+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:47.265205+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":73} +{"time":"2025-07-28T19:08:47.659933+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:47.659959+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:47.665859+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":5} +2025/07/28 19:08:47 [akrotiri/nRQLu4lSAJ-000287] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3751B in 759.642167ms +2025/07/28 19:08:48 [akrotiri/nRQLu4lSAJ-000288] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3751B in 741.929583ms +{"time":"2025-07-28T19:08:48.655502+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:48.655522+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:48.668122+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:48.68021+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":24} +{"time":"2025-07-28T19:08:48.680245+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:49 [akrotiri/nRQLu4lSAJ-000289] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3758B in 1.008004166s +{"time":"2025-07-28T19:08:49.121517+02:00","level":"INFO","msg":"BGP session opened","source":"streamer.go:432","func":"streamer.(*Streamer).stream","peer":"195.208.209.174","peer_asn":"25227"} +2025/07/28 19:08:49 [akrotiri/nRQLu4lSAJ-000290] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3757B in 850.304916ms +{"time":"2025-07-28T19:08:49.676251+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":995} +{"time":"2025-07-28T19:08:49.676268+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:49.676272+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +2025/07/28 19:08:49 [akrotiri/nRQLu4lSAJ-000291] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3758B in 667.173666ms +{"time":"2025-07-28T19:08:49.830118+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":153} +{"time":"2025-07-28T19:08:49.830136+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":17606,"unique_prefixes":4260,"success":4260,"duration_ms":1167} +{"time":"2025-07-28T19:08:49.991001+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:49.991015+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:50.027158+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":36} +{"time":"2025-07-28T19:08:50.137902+02:00","level":"WARN","msg":"BGP notification","source":"streamer.go:440","func":"streamer.(*Streamer).stream","peer":"193.239.118.249","peer_asn":"41255"} +2025/07/28 19:08:50 [akrotiri/nRQLu4lSAJ-000292] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3755B in 632.136875ms +{"time":"2025-07-28T19:08:50.236264+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:50.236276+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:50.241092+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":4} +2025/07/28 19:08:50 [akrotiri/nRQLu4lSAJ-000293] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3755B in 630.333416ms +2025/07/28 19:08:51 [akrotiri/nRQLu4lSAJ-000294] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3755B in 645.829ms +{"time":"2025-07-28T19:08:51.665972+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +{"time":"2025-07-28T19:08:51.666134+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpsertLiveRouteBatch","caller":"database.go:180"} +2025/07/28 19:08:51 [akrotiri/nRQLu4lSAJ-000295] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3755B in 668.391125ms +{"time":"2025-07-28T19:08:52.041884+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpsertLiveRouteBatch (database.go:180)","duration_ms":375} +{"time":"2025-07-28T19:08:52.041917+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:52.041921+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"DeleteLiveRouteBatch","caller":"database.go:261"} +{"time":"2025-07-28T19:08:52.085899+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"DeleteLiveRouteBatch (database.go:261)","duration_ms":43} +{"time":"2025-07-28T19:08:52.085917+02:00","level":"DEBUG","msg":"Flushed prefix batch","source":"prefixhandler.go:223","func":"routewatch.(*PrefixHandler).flushBatchLocked","batch_size":12099,"unique_prefixes":1903,"success":1903,"duration_ms":422} +2025/07/28 19:08:52 [akrotiri/nRQLu4lSAJ-000296] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3755B in 629.8825ms +2025/07/28 19:08:52 [akrotiri/nRQLu4lSAJ-000297] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3755B in 595.469584ms +2025/07/28 19:08:53 [akrotiri/nRQLu4lSAJ-000298] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3755B in 578.853125ms +{"time":"2025-07-28T19:08:53.659722+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:53.659738+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"UpdatePeerBatch","caller":"database.go:639"} +{"time":"2025-07-28T19:08:53.659846+02:00","level":"DEBUG","msg":"Acquiring database lock","source":"database.go:143","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +{"time":"2025-07-28T19:08:53.66108+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"UpdatePeerBatch (database.go:639)","duration_ms":1} +{"time":"2025-07-28T19:08:53.66109+02:00","level":"DEBUG","msg":"Database lock acquired","source":"database.go:149","func":"database.(*Database).lock","operation":"GetOrCreateASNBatch","caller":"database.go:331"} +2025/07/28 19:08:53 [akrotiri/nRQLu4lSAJ-000299] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3755B in 578.871ms +{"time":"2025-07-28T19:08:53.67232+02:00","level":"DEBUG","msg":"Database lock released","source":"database.go:161","func":"database.(*Database).unlock","held_by":"GetOrCreateASNBatch (database.go:331)","duration_ms":11} +2025/07/28 19:08:54 [akrotiri/nRQLu4lSAJ-000300] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 588.576375ms +2025/07/28 19:08:54 [akrotiri/nRQLu4lSAJ-000301] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3753B in 573.700125ms +2025/07/28 19:08:55 [akrotiri/nRQLu4lSAJ-000302] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3753B in 623.384583ms +2025/07/28 19:08:55 [akrotiri/nRQLu4lSAJ-000303] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3753B in 667.114542ms +{"time":"2025-07-28T19:08:56.005092+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":80001029625,"total_messages":357547,"total_bytes":258343631,"total_mb":"246.38","messages_per_sec":"3119.43","bits_per_sec":"17999429","mbps":"18.00","total_dropped":0} +{"time":"2025-07-28T19:08:56.005113+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":103823,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:08:56.005117+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":48134,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:08:56.005121+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":148552,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:08:56.005124+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":1920,"min_time":0,"max_time":20882459} +2025/07/28 19:08:56 [akrotiri/nRQLu4lSAJ-000304] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3753B in 660.096375ms +2025/07/28 19:08:56 [akrotiri/nRQLu4lSAJ-000305] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3753B in 690.7415ms +2025/07/28 19:08:57 [akrotiri/nRQLu4lSAJ-000306] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3753B in 679.979ms +2025/07/28 19:08:57 [akrotiri/nRQLu4lSAJ-000307] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3753B in 589.36475ms +2025/07/28 19:08:58 [akrotiri/nRQLu4lSAJ-000308] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3753B in 577.09975ms +2025/07/28 19:08:58 [akrotiri/nRQLu4lSAJ-000309] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3753B in 583.525917ms +2025/07/28 19:08:59 [akrotiri/nRQLu4lSAJ-000310] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 576.991042ms +2025/07/28 19:08:59 [akrotiri/nRQLu4lSAJ-000311] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 594.249ms +2025/07/28 19:09:00 [akrotiri/nRQLu4lSAJ-000312] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 612.268ms +2025/07/28 19:09:00 [akrotiri/nRQLu4lSAJ-000313] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 593.98125ms +2025/07/28 19:09:01 [akrotiri/nRQLu4lSAJ-000314] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 614.519959ms +2025/07/28 19:09:01 [akrotiri/nRQLu4lSAJ-000315] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 607.626917ms +2025/07/28 19:09:02 [akrotiri/nRQLu4lSAJ-000316] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 600.766875ms +2025/07/28 19:09:02 [akrotiri/nRQLu4lSAJ-000317] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 599.535458ms +2025/07/28 19:09:03 [akrotiri/nRQLu4lSAJ-000318] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 582.233042ms +2025/07/28 19:09:03 [akrotiri/nRQLu4lSAJ-000319] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 582.717875ms +2025/07/28 19:09:04 [akrotiri/nRQLu4lSAJ-000320] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3755B in 586.526209ms +2025/07/28 19:09:04 [akrotiri/nRQLu4lSAJ-000321] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 574.299083ms +2025/07/28 19:09:05 [akrotiri/nRQLu4lSAJ-000322] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 571.166083ms +2025/07/28 19:09:05 [akrotiri/nRQLu4lSAJ-000323] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 575.013625ms +{"time":"2025-07-28T19:09:06.005175+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":90001031000,"total_messages":357547,"total_bytes":258343631,"total_mb":"246.38","messages_per_sec":"2640.54","bits_per_sec":"15236187","mbps":"15.24","total_dropped":0} +{"time":"2025-07-28T19:09:06.005194+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":103823,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:09:06.005199+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":48134,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:09:06.005203+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":148552,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:09:06.005206+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":1920,"min_time":0,"max_time":20882459} +2025/07/28 19:09:06 [akrotiri/nRQLu4lSAJ-000324] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 592.732292ms +2025/07/28 19:09:07 [akrotiri/nRQLu4lSAJ-000325] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 622.906708ms +2025/07/28 19:09:07 [akrotiri/nRQLu4lSAJ-000326] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 610.983083ms +2025/07/28 19:09:07 [akrotiri/nRQLu4lSAJ-000327] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 582.094333ms +2025/07/28 19:09:08 [akrotiri/nRQLu4lSAJ-000328] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 576.862875ms +2025/07/28 19:09:08 [akrotiri/nRQLu4lSAJ-000329] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 582.205209ms +2025/07/28 19:09:09 [akrotiri/nRQLu4lSAJ-000330] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 581.30425ms +2025/07/28 19:09:09 [akrotiri/nRQLu4lSAJ-000331] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 575.841083ms +2025/07/28 19:09:10 [akrotiri/nRQLu4lSAJ-000332] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 615.411584ms +2025/07/28 19:09:10 [akrotiri/nRQLu4lSAJ-000333] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 591.091375ms +2025/07/28 19:09:11 [akrotiri/nRQLu4lSAJ-000334] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 576.625791ms +2025/07/28 19:09:11 [akrotiri/nRQLu4lSAJ-000335] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 594.505666ms +2025/07/28 19:09:12 [akrotiri/nRQLu4lSAJ-000336] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 583.306917ms +2025/07/28 19:09:12 [akrotiri/nRQLu4lSAJ-000337] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 582.966709ms +2025/07/28 19:09:13 [akrotiri/nRQLu4lSAJ-000338] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3754B in 598.679292ms +2025/07/28 19:09:13 [akrotiri/nRQLu4lSAJ-000339] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 581.196667ms +2025/07/28 19:09:14 [akrotiri/nRQLu4lSAJ-000340] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 578.802541ms +2025/07/28 19:09:14 [akrotiri/nRQLu4lSAJ-000341] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 578.907333ms +2025/07/28 19:09:15 [akrotiri/nRQLu4lSAJ-000342] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 577.879417ms +2025/07/28 19:09:15 [akrotiri/nRQLu4lSAJ-000343] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 575.945417ms +{"time":"2025-07-28T19:09:16.005249+02:00","level":"INFO","msg":"Stream statistics","source":"streamer.go:271","func":"streamer.(*Streamer).logMetrics","uptime":100001037208,"total_messages":357547,"total_bytes":258343631,"total_mb":"246.38","messages_per_sec":"2235.17","bits_per_sec":"12897154","mbps":"12.90","total_dropped":0} +{"time":"2025-07-28T19:09:16.005286+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.ASHandler","index":0,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":103823,"min_time":0,"max_time":2800460167} +{"time":"2025-07-28T19:09:16.005293+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeerHandler","index":1,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":48134,"min_time":0,"max_time":2023266000} +{"time":"2025-07-28T19:09:16.005297+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PrefixHandler","index":2,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":148552,"min_time":0,"max_time":3084562375} +{"time":"2025-07-28T19:09:16.0053+02:00","level":"INFO","msg":"Handler statistics","source":"streamer.go:304","func":"streamer.(*Streamer).logMetrics","handler":"*routewatch.PeeringHandler","index":3,"queue_len":0,"queue_cap":100000,"processed":353961,"dropped":0,"avg_time":1920,"min_time":0,"max_time":20882459} +2025/07/28 19:09:16 [akrotiri/nRQLu4lSAJ-000344] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 589.83175ms +2025/07/28 19:09:16 [akrotiri/nRQLu4lSAJ-000345] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 590.129042ms +2025/07/28 19:09:17 [akrotiri/nRQLu4lSAJ-000346] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 572.234916ms +2025/07/28 19:09:17 [akrotiri/nRQLu4lSAJ-000347] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 603.296084ms +2025/07/28 19:09:18 [akrotiri/nRQLu4lSAJ-000348] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3756B in 580.68025ms +2025/07/28 19:09:18 [akrotiri/nRQLu4lSAJ-000349] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3756B in 578.744958ms +2025/07/28 19:09:19 [akrotiri/nRQLu4lSAJ-000350] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59432 - 200 3756B in 592.029ms +2025/07/28 19:09:19 [akrotiri/nRQLu4lSAJ-000351] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59431 - 200 3754B in 594.455667ms +2025/07/28 19:09:20 [akrotiri/nRQLu4lSAJ-000352] "GET http://127.0.0.1:8080/api/v1/stats HTTP/1.1" from 127.0.0.1:59430 - 200 3754B in 593.041041ms +Failed to parse JSON: unexpected end of JSON input +Raw line: {"type":"ris_message", +panic: JSON parse error: unexpected end of JSON input + +goroutine 44 [running]: +git.eeqj.de/sneak/routewatch/internal/streamer.(*Streamer).stream(0x140000cf340, {0x102d36a70, 0x140000d6050}) + /Users/user/dev/routewatch/internal/streamer/streamer.go:400 +0xd30 +git.eeqj.de/sneak/routewatch/internal/streamer.(*Streamer).Start.func1() + /Users/user/dev/routewatch/internal/streamer/streamer.go:138 +0x2c +created by git.eeqj.de/sneak/routewatch/internal/streamer.(*Streamer).Start in goroutine 22 + /Users/user/dev/routewatch/internal/streamer/streamer.go:137 +0x1f8