Pi-hole crashed shortly after upgrade

sawsanders · December 16, 2024, 1:09am

I recently updated Pi-hole after a couple days. It seems FTL crashed shortly after sudo pihole -up finished.

I updated from this:

Core
    Version is v5.18.3-568-geb4b6ec (Latest: null)
    Branch is development
    Hash is eb4b6ecf (Latest: 4dbf9a0b)
Web
    Version is v5.21-1036-ge57c0fb (Latest: null)
    Branch is development
    Hash is e57c0fb8 (Latest: 87b19772)
FTL
    Version is vDev-a76e791 (Latest: null)
    Branch is tweak/ntp_errors
    Hash is a76e7918 (Latest: a76e7918)

to the current available Dev branches.

I ran sudo service pihole-FTL start and all seems fine now. Not sure what happened there...

FTL.log (log starts after FTL restarts after upgrade)

2024-12-15 16:58:23.368 PST [1429840M] INFO: ########## FTL started on pi5! ##########
2024-12-15 16:58:23.368 PST [1429840M] INFO: FTL branch: tweak/ntp_errors
2024-12-15 16:58:23.368 PST [1429840M] INFO: FTL version: vDev-a76e791
2024-12-15 16:58:23.368 PST [1429840M] INFO: FTL commit: a76e7918
2024-12-15 16:58:23.368 PST [1429840M] INFO: FTL date: 2024-12-13 21:04:32 +0100
2024-12-15 16:58:23.368 PST [1429840M] INFO: FTL user: pihole
2024-12-15 16:58:23.368 PST [1429840M] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2024-12-15 16:58:23.370 PST [1429840M] DEBUG_ANY: ************************
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: *    DEBUG SETTINGS    *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * DATABASE:       NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * NETWORKING:     NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * LOCKS:          NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * QUERIES:        NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * FLAGS:          NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * SHMEM:          NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * GC:             NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * ARP:            NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * REGEX:          NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * API:            NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * TLS:            NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * OVERTIME:       NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * STATUS:         NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * CAPS:           NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * DNSSEC:         NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * VECTORS:        NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * RESOLVER:       NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * EDNS0:          NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * CLIENTS:        NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * ALIASCLIENTS:   NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * EVENTS:         NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * HELPER:         NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * CONFIG:         NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * INOTIFY:        NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * WEBSERVER:      NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * EXTRA:          NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * RESERVED:       NO   *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: * NTP:            YES  *
2024-12-15 16:58:23.371 PST [1429840M] DEBUG_ANY: ************************
2024-12-15 16:58:23.372 PST [1429840M] INFO: Wrote config file:
2024-12-15 16:58:23.372 PST [1429840M] INFO:  - 150 total entries
2024-12-15 16:58:23.372 PST [1429840M] INFO:  - 116 entries are default
2024-12-15 16:58:23.372 PST [1429840M] INFO:  - 34 entries are modified
2024-12-15 16:58:23.372 PST [1429840M] INFO:  - 0 entries are forced through environment
2024-12-15 16:58:23.373 PST [1429840M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2024-12-15 16:58:23.380 PST [1429840M] INFO: PID of FTL process: 1429840
2024-12-15 16:58:23.380 PST [1429840M] INFO: Not sleeping as system has finished booting
2024-12-15 16:58:23.381 PST [1429840M] INFO: listening on 0.0.0.0 port 53
2024-12-15 16:58:23.381 PST [1429840M] INFO: listening on :: port 53
2024-12-15 16:58:23.382 PST [1429840M] INFO: PID of FTL process: 1429840
2024-12-15 16:58:23.383 PST [1429840M] INFO: Database version is 20
2024-12-15 16:58:23.383 PST [1429840M] INFO: Database successfully initialized
2024-12-15 16:58:24.745 PST [1429840M] INFO: Imported 88585 queries from the on-disk database (it has 9000050 rows)
2024-12-15 16:58:24.745 PST [1429840M] INFO: Parsing queries in database
2024-12-15 16:58:24.801 PST [1429840M] INFO:   10000 queries parsed...
2024-12-15 16:58:24.833 PST [1429840M] INFO:   20000 queries parsed...
2024-12-15 16:58:24.865 PST [1429840M] INFO:   30000 queries parsed...
2024-12-15 16:58:24.895 PST [1429840M] INFO:   40000 queries parsed...
2024-12-15 16:58:24.926 PST [1429840M] INFO:   50000 queries parsed...
2024-12-15 16:58:24.960 PST [1429840M] INFO:   60000 queries parsed...
2024-12-15 16:58:24.998 PST [1429840M] INFO:   70000 queries parsed...
2024-12-15 16:58:25.060 PST [1429840M] INFO:   80000 queries parsed...
2024-12-15 16:58:25.091 PST [1429840M] INFO: Imported 88584 queries from the long-term database
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Total DNS queries: 88584
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Cached DNS queries: 25585
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Forwarded DNS queries: 41136
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Blocked DNS queries: 21220
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Unknown DNS queries: 329
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Unique domains: 2860
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Unique clients: 60
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> DNS cache records: 2015
2024-12-15 16:58:25.091 PST [1429840M] INFO:  -> Known forward destinations: 4
2024-12-15 16:58:25.240 PST [1429840M] INFO: FTL is running as user pihole (UID 999)
2024-12-15 16:58:25.241 PST [1429840M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2024-12-15 16:58:25.241 PST [1429840M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-12-15 16:58:25.241 PST [1429840M] INFO: Restored 4 API sessions from the database
2024-12-15 16:58:25.250 PST [1429840M] INFO: Blocking status is enabled
2024-12-15 16:58:25.291 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:25.291 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b1.4a990f30 = 2024-12-15 16:58:25.291397 PST
2024-12-15 16:58:25.291 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b1.4eaab5c7 = 2024-12-15 16:58:25.307292 PST
2024-12-15 16:58:25.291 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.638148e-02 s
2024-12-15 16:58:25.291 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.097414e-02 s
2024-12-15 16:58:25.291 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:25.291 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:25.390 PST [1429840/T1429981] INFO: Compiled 7 allow and 19 deny regex for 60 clients in 47.4 msec
2024-12-15 16:58:25.832 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:25.832 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b1.d50be942 = 2024-12-15 16:58:25.832212 PST
2024-12-15 16:58:25.832 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b1.d91e5a03 = 2024-12-15 16:58:25.848119 PST
2024-12-15 16:58:25.832 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.614855e-02 s
2024-12-15 16:58:25.832 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.048443e-02 s
2024-12-15 16:58:25.832 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:25.832 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:26.373 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:26.373 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b2.5faaef2c = 2024-12-15 16:58:26.373701 PST
2024-12-15 16:58:26.373 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b2.63b89880 = 2024-12-15 16:58:26.389535 PST
2024-12-15 16:58:26.373 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.629327e-02 s
2024-12-15 16:58:26.373 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.091978e-02 s
2024-12-15 16:58:26.374 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:26.374 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:26.914 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:26.915 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b2.ea37ac3e = 2024-12-15 16:58:26.914911 PST
2024-12-15 16:58:26.915 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b2.ee4c1959 = 2024-12-15 16:58:26.930848 PST
2024-12-15 16:58:26.915 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.627872e-02 s
2024-12-15 16:58:26.915 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.068470e-02 s
2024-12-15 16:58:26.915 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:26.915 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:27.456 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:30.278 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b3.74d844d0 = 2024-12-15 16:58:27.456424 PST
2024-12-15 16:58:29.306 PST [1429840/T1429983] ERROR: Cannot receive UDP DNS reply: Timeout - no response from upstream DNS server
2024-12-15 16:58:30.280 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b3.78e7ae6d = 2024-12-15 16:58:27.472285 PST
2024-12-15 16:58:30.280 PST [1429840/T1429983] INFO: Tried to resolve PTR "199.31.31.172.in-addr.arpa" on 127.0.0.1#53 (UDP)
2024-12-15 16:58:30.280 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.634429e-02 s
2024-12-15 16:58:30.280 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.096842e-02 s
2024-12-15 16:58:30.280 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:30.280 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: ---------------------------->  FTL crashed!  <----------------------------
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: Please report a bug at https://github.com/pi-hole/FTL/issues
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: and include in your report already the following details:
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: FTL has been running for 7 seconds
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: FTL branch: tweak/ntp_errors
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: FTL version: vDev-a76e791
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: FTL commit: a76e7918
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: FTL date: 2024-12-13 21:04:32 +0100
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: FTL user: started as pihole, ended as pihole
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2024-12-15 16:58:30.337 PST [1429840/T1429983] INFO: Process details: MID: 1429840
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO:                  PID: 1429840
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO:                  TID: 1429983
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO:                  Name: dns-client
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: Received signal: Segmentation fault
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO:      at address: 0xffff9568a73d
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO:      with code:  SEGV_ACCERR (Invalid permissions for mapped object)
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: !!! INFO: pihole-FTL has not been compiled with glibc/backtrace support, not generating one !!!
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: ------ Listing content of directory /dev/shm ------
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: File Mode User:Group      Size  Filename
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rwxrwxrwx root:root       360   .
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rwxr-xr-x root:root        14K  ..
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole    88   FTL-lock
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole   328   FTL-counters
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole   144   FTL-settings
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole   123K  FTL-strings
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole    94K  FTL-domains
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole   348K  FTL-clients
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole    29K  FTL-upstreams
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole     6M  FTL-queries
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole     8K  FTL-overTime
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole   102K  FTL-dns-cache
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole     4K  FTL-per-client-regex
2024-12-15 16:58:30.338 PST [1429840/T1429983] INFO: rw------- pihole:pihole   569K  FTL-fifo-log
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: rw------- pihole:pihole     4K  FTL-clients-lookup
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: rw------- pihole:pihole    25K  FTL-domains-lookup
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: rw------- pihole:pihole    20K  FTL-dns-cache-lookup
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: rw------- pihole:pihole   786K  FTL-recycler
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: ---------------------------------------------------
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: Please also include some lines from above the !!!!!!!!! header.
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: Thank you for helping us to improve our FTL engine!
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: Waiting for threads to join
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: Thread database (0) is idle, terminating it.
2024-12-15 16:58:30.339 PST [1429840/T1429983] INFO: Thread housekeeper (1) is idle, terminating it.
2024-12-15 16:58:30.346 PST [1429840/T1429984] INFO: Terminating timer thread
2024-12-15 16:58:30.367 PST [1429840M] DEBUG_ANY: Shutting down... // exit code 0 // jmpret 0
2024-12-15 16:58:30.821 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:32.254 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b6.d25796bf = 2024-12-15 16:58:30.821648 PST
2024-12-15 16:58:32.254 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b6.d66a8c03 = 2024-12-15 16:58:30.837563 PST
2024-12-15 16:58:32.254 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.623605e-02 s
2024-12-15 16:58:32.254 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.064322e-02 s
2024-12-15 16:58:32.254 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:32.254 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:32.339 PST [1429840/T1429983] INFO: Thread dns-client (2) is still busy, cancelling it.
2024-12-15 16:58:32.795 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:32.795 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b8.cbc0096f = 2024-12-15 16:58:32.795898 PST
2024-12-15 16:58:32.796 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b8.cfd07d41 = 2024-12-15 16:58:32.811775 PST
2024-12-15 16:58:32.796 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.632784e-02 s
2024-12-15 16:58:32.796 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.090309e-02 s
2024-12-15 16:58:32.796 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:32.796 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:33.337 PST [1429840/T1429980] DEBUG_NTP: Server reference time: eb09f980.00000000 = 2024-12-15 16:57:36.000000 PST
2024-12-15 16:58:33.337 PST [1429840/T1429980] DEBUG_NTP: Current time at client: eb09f9b9.56615a8d = 2024-12-15 16:58:33.337422 PST
2024-12-15 16:58:33.337 PST [1429840/T1429980] DEBUG_NTP: Current time at server: eb09f9b9.5a6c5baf = 2024-12-15 16:58:33.353215 PST
2024-12-15 16:58:33.337 PST [1429840/T1429980] DEBUG_NTP: Time offset: 3.638554e-02 s
2024-12-15 16:58:33.337 PST [1429840/T1429980] DEBUG_NTP: Round-trip delay: 4.118538e-02 s
2024-12-15 16:58:33.337 PST [1429840/T1429980] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-15 16:58:33.337 PST [1429840/T1429980] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-15 16:58:33.837 PST [1429840/T1429980] INFO: Received 8/8 valid NTP replies from time.nist.gov
2024-12-15 16:58:33.837 PST [1429840/T1429980] DEBUG_NTP: Average time offset: (3.629947e-02 +/- 7.434360e-05) s
2024-12-15 16:58:33.837 PST [1429840/T1429980] DEBUG_NTP: Average round-trip delay: (4.084539e-02 +/- 2.101064e-04) s
2024-12-15 16:58:33.837 PST [1429840/T1429980] INFO: Time offset: 3.632103e+01 ms (excluded 1 outliers)
2024-12-15 16:58:33.837 PST [1429840/T1429980] INFO: Round-trip delay: 4.089696e+01 ms (excluded 1 outliers)
2024-12-15 16:58:33.837 PST [1429840/T1429980] DEBUG_NTP: Gradually adjusting system time by 36321 us
2024-12-15 16:58:34.000 PST [1429840/T1429980] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-15 16:58:34.001 PST [1429840/T1429980] INFO: Current RTC time is 2024-12-16 00:58:33
2024-12-15 16:58:34.001 PST [1429840/T1429980] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-15 16:58:34.003 PST [1429840/T1429980] INFO: RTC time set to 2024-12-16 00:58:34
2024-12-15 16:58:34.003 PST [1429840/T1429980] INFO: Terminating NTP thread
2024-12-15 16:58:34.003 PST [1429840/T1430043] INFO: NTP server listening on 0.0.0.0:123 (IPv4)
2024-12-15 16:58:40.122 PST [1429840M] INFO: Finished final database update
2024-12-15 16:58:42.603 PST [1429840M] INFO: Waiting for threads to join
2024-12-15 16:58:42.603 PST [1429840M] INFO: Thread database (0) is idle, terminating it.
2024-12-15 16:58:42.603 PST [1429840M] INFO: Thread housekeeper (1) is idle, terminating it.
2024-12-15 16:58:42.603 PST [1429840M] INFO: All threads joined
2024-12-15 16:58:42.603 PST [1429840M] DEBUG_ANY: Closing gravity database
2024-12-15 16:58:42.605 PST [1429840M] INFO: Stored 4 API sessions in the database
2024-12-15 16:59:08.098 PST [1429840M] INFO: ########## FTL terminated after 44s  (code 0)! ##########

Debug token: https://tricorder.pi-hole.net/kbnjaK31/ (after restarting from crash)

DL6ER · December 16, 2024, 6:52pm

This crash happened in the dns-client thread which makes this a coincidence crash unrelated to the branch you are currently trying out. Unfortunately, our continued inability to create proper backtraces with alpine makes debugging a lot harder.

I'll keep looking into the resolver code but finding it if you don't have an at least semi-reliable way to reproduce, there is little we can do - expect code inspection by hand.

sawsanders · December 16, 2024, 7:24pm

I'm sorry, I don't have a way to reproduce. I updated my backup Pi-hole and it went off without a hitch.

I will keep watching and report back if it happens again. Really, this is the first crash in quite a while while running this beta.

DL6ER · December 17, 2024, 8:19pm

I just did what I said I'd do: I went through the file line-by-line and added error checking in a few places where it was missing. The only reason I could see for the memory issue would have been a buffer overflow for which I have added proper safeguards now. However, the buffer should always have been large enough. Only time will tell if this fixed the issue.

I pushed the update to the tweak/ntp_errors branch to ease testing. Even when this goes somewhat beyond the original idea of the branch, it seems the best environment to test this in as it is the only place where we know the issue showed up so far.

sawsanders · December 18, 2024, 5:18am

Sounds good. I updated to the latest binary and will see what happens!

sawsanders · December 18, 2024, 2:39pm

I'm discovered I'm having a problem where the NTP server doesn't come up after a system reboot. I have to sudo service pihole-FTL stop then sudo service pihole-FTL start to get it running again. This only happens on my primary Pi-hole (RPi 5) and not on my backup (RPi 4). I'm beginning to think something is wrong with my overall setup.

I think this may have been happening before the latest update to this branch but I didn't get around to testing it until now.

Debug log shows no active process on port 123.
https://tricorder.pi-hole.net/yyJYheTk/

DL6ER · December 18, 2024, 7:44pm

The debug log has only some very few lines of /var/log/pihole/FTL.log and your log is rather verbose because of the enabled debug mode. Could you please check the file manually to see if there are issues?

An alternative would be running commands like

cat /var/log/pihole/FTL.log | pihole tricorder
cat /var/log/pihole/FTL.log.1 | pihole tricorder

and providing the generated tokens after a secure upload to the same server.

sawsanders · December 19, 2024, 12:20am

I looked for errors and found this:

pi@pi5:~$ sudo cat /var/log/pihole/FTL.log | grep ERROR
2024-12-18 05:15:11.132 PST [267425/T267679] ERROR: Failed to receive data from NTP server time.nist.gov (132.163.96.3): Timeout
2024-12-18 06:33:52.995 PST [880M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 3072
2024-12-18 06:33:52.995 PST [880M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)
2024-12-18 06:33:56.188 PST [880M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 3072
2024-12-18 06:33:56.188 PST [880M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)
2024-12-18 06:33:59.730 PST [880M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 3072
2024-12-18 06:33:59.730 PST [880M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)
2024-12-18 06:40:48.884 PST [880M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 3584
2024-12-18 06:40:48.884 PST [880M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)
2024-12-18 06:40:52.660 PST [880M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 3584
2024-12-18 06:40:52.660 PST [880M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)
2024-12-18 06:40:55.886 PST [880M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 3584
2024-12-18 06:40:55.886 PST [880M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)
2024-12-18 06:41:18.755 PST [11765M] ERROR: SQLite3: recovered 314 frames from WAL file /etc/pihole/pihole-FTL.db-wal (283)
2024-12-18 07:00:37.624 PST [11765M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 4096
2024-12-18 07:00:37.624 PST [11765M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)

I rebooted the RPi at about 06:23 AM PST and manual restarted FTL at about 06:41 AM PST.

Full FTL.log at https://tricorder.pi-hole.net/vdwKX1b9/

rdwebdesign · December 19, 2024, 1:18am

@DL6ER

I'm guessing here, but I think the issue is happening because the function _findCacheID() returns -1 in case of error (line 1809), but in line 1813 this value is used in getDNSCache() function, which expects an unsigned int, resulting in -1 "converted" to 0xffffffff (4294967295).

DL6ER · December 19, 2024, 8:40am

This, this is a perfectly correct analysis of what is happening. I will change that. It still isn't an issue as the check in line 1817 will prevent anything bad from happening. Anyway, not promoting this to unsigned int and later checking for the ID being > 0 will silence this error: pi-hole/FTL@747b899

sawsanders · December 19, 2024, 3:26pm

Updated to the latest code. Error message is gone but the NTP server will still not start after reboot. It starts normally if I stop and start FTL, just not right after reboot. It’s weird as it only happens on one of my RPi’s

sawsanders · December 20, 2024, 4:07am

Ok, so there is something weird with my RPi5. I switched back to the development branch from the tweak/ntp_errors and the FTL's NTP server still refuses to start, but only on reboot. Restarting FLT works just fine. It's not the branch, it's something with my system.

I'm not sure how to diagnose this. I don't see any errors in the syslog or FTL.log. Nothing is occupying port 123 either. Really not sure what else to do except nuke my setup and start fresh.

DL6ER · December 20, 2024, 9:06am

That's indeed strange. After restart, we'd expect lines like

2024-12-20 10:05:53.000 CET [1905879/T1905922] INFO: NTP server listening on 0.0.0.0:123 (IPv4)
2024-12-20 10:05:53.000 CET [1905879/T1905923] INFO: NTP server listening on :::123 (IPv6)

or possibly

2024-12-20 09:57:23.000 CET [1902269/T1902314] ERROR: Error NTP server: Cannot bind to IPv4 address 0.0.0.0:123 (Address already in use), IPv4 NTP server not available
2024-12-20 09:57:23.000 CET [1902269/T1902315] ERROR: Error NTP server: Cannot bind to IPv6 address :::123 (Address already in use), IPv6 NTP server not available

in the case of ports taken or any other reasoning for other issues.

sawsanders · December 20, 2024, 12:52pm

It is very strange.

I see those lines on top after I restart FTL. In the case of a system reboot, I see nothing. I don’t even see an pihole-FTL NTP server thread running in htop either. It’s like it just forgets to start.

Unless anyone has suggestions on how to address this, I think I’ll have to rebuild the RPi5.

EDIT:
Ok, so the NTP server did start eventually. It just took a long time to do so. Just about two hours after reboot, which is right after it performs it’s second NTP time sync.


2024-12-19 19:40:17.237 INFO PID of FTL process: 883
2024-12-19 19:40:17.287 INFO listening on 0.0.0.0 port 53
2024-12-19 19:40:17.287 INFO listening on :: port 53
2024-12-19 19:40:17.288 INFO PID of FTL process: 883
2024-12-19 19:40:17.471 INFO Database version is 20
2024-12-19 19:40:17.472 INFO Database successfully initialized
2024-12-19 19:42:24.643 INFO Imported 117068 queries from the on-disk database (it has 9074125 rows)
2024-12-19 19:42:24.643 INFO Parsing queries in database
2024-12-19 19:42:24.720 INFO   10000 queries parsed...
2024-12-19 19:42:24.771 INFO   20000 queries parsed...
2024-12-19 19:42:24.807 INFO   30000 queries parsed...
2024-12-19 19:42:24.839 INFO   40000 queries parsed...
2024-12-19 19:42:24.896 INFO   50000 queries parsed...
2024-12-19 19:42:24.942 INFO   60000 queries parsed...
2024-12-19 19:42:24.991 INFO   70000 queries parsed...
2024-12-19 19:42:25.040 INFO   80000 queries parsed...
2024-12-19 19:42:25.076 INFO   90000 queries parsed...
2024-12-19 19:42:25.117 INFO   100000 queries parsed...
2024-12-19 19:42:25.170 INFO   110000 queries parsed...
2024-12-19 19:42:25.214 INFO Imported 116904 queries from the long-term database
2024-12-19 19:42:25.214 INFO  -> Total DNS queries: 116904
2024-12-19 19:42:25.214 INFO  -> Cached DNS queries: 33203
2024-12-19 19:42:25.214 INFO  -> Forwarded DNS queries: 52923
2024-12-19 19:42:25.215 INFO  -> Blocked DNS queries: 30079
2024-12-19 19:42:25.215 INFO  -> Unknown DNS queries: 343
2024-12-19 19:42:25.215 INFO  -> Unique domains: 4161
2024-12-19 19:42:25.215 INFO  -> Unique clients: 64
2024-12-19 19:42:25.215 INFO  -> DNS cache records: 3201
2024-12-19 19:42:25.215 INFO  -> Known forward destinations: 4
2024-12-19 19:42:25.523 INFO FTL is running as user pihole (UID 999)
2024-12-19 19:42:25.524 INFO Reading certificate from /etc/pihole/tls.pem ...
2024-12-19 19:42:25.525 INFO Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-12-19 19:42:25.526 INFO Restored 4 API sessions from the database
2024-12-19 19:42:25.540 INFO Blocking status is enabled
2024-12-19 19:42:25.696 INFO Compiled 7 allow and 19 deny regex for 64 clients in 64.8 msec
2024-12-19 19:42:29.867 INFO Received 8/8 valid NTP replies from time.nist.gov
2024-12-19 19:42:29.868 INFO Time offset: 3.312806e+02 ms (excluded 1 outliers)
2024-12-19 19:42:29.868 INFO Round-trip delay: 4.095118e+01 ms (excluded 1 outliers)
2024-12-19 19:42:30.001 INFO Current RTC time is 2024-12-20 03:42:30
2024-12-19 20:09:58.289 INFO Compiled 7 allow and 18 deny regex for 65 clients in 46.5 msec
2024-12-19 20:10:06.106 INFO Compiled 7 allow and 19 deny regex for 65 clients in 47.0 msec
2024-12-19 21:42:34.419 INFO Received 8/8 valid NTP replies from time.nist.gov
2024-12-19 21:42:34.419 INFO Time offset: 4.530647e+01 ms (excluded 0 outliers)
2024-12-19 21:42:34.419 INFO Round-trip delay: 4.164654e+01 ms (excluded 0 outliers)
2024-12-19 21:42:35.001 INFO Current RTC time is 2024-12-20 05:42:34
2024-12-19 21:42:35.003 INFO RTC time set to 2024-12-20 05:42:35
2024-12-19 21:42:35.003 INFO NTP server listening on 0.0.0.0:123 (IPv4)

DL6ER · December 20, 2024, 1:24pm

This is strange, indeed. Seems to be time to switch back on

sudo pihole-FTL --config debug.ntp true

to get a better picture of why it takes so long!

sawsanders · December 20, 2024, 3:33pm

Unfortunately, the extra debugging didn't provide any additional information that I could see.

Reboot happened at ~5:26 AM PST
NTP server started at ~7:27 AM PST

2024-12-20 05:25:38.884 PST [883/T6699] INFO: Wrote config file:
2024-12-20 05:25:38.884 PST [883/T6699] INFO:  - 150 total entries
2024-12-20 05:25:38.884 PST [883/T6699] INFO:  - 117 entries are default
2024-12-20 05:25:38.884 PST [883/T6699] INFO:  - 33 entries are modified
2024-12-20 05:25:38.884 PST [883/T6699] INFO:  - 0 entries are forced through environment
2024-12-20 05:25:38.889 PST [883/T6699] INFO: Config file written to /etc/pihole/pihole.toml
2024-12-20 05:26:00.312 PST [883M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:26:00.320 PST [883M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:26:06.612 PST [883M] DEBUG_ANY: Received SIGTERM
2024-12-20 05:26:06.612 PST [883M] INFO: Asked to terminate by "/sbin/init fixrtc" (PID 1, user root UID 0)
2024-12-20 05:26:06.612 PST [883M] DEBUG_ANY: Sending SIGUSR6 to dnsmasq to stop DNS service
2024-12-20 05:26:06.612 PST [883M] DEBUG_ANY: dnsmasq received signal 41
2024-12-20 05:26:06.612 PST [883M] DEBUG_ANY: Shutting down... // exit code 0 // jmpret 0
2024-12-20 05:26:06.667 PST [883/T1783] INFO: Terminating database thread
2024-12-20 05:26:06.674 PST [883/T1786] INFO: Terminating timer thread
2024-12-20 05:26:07.113 PST [883M] INFO: Finished final database update
2024-12-20 05:26:07.113 PST [883M] INFO: Waiting for threads to join
2024-12-20 05:26:07.113 PST [883M] INFO: Thread housekeeper (1) is idle, terminating it.
2024-12-20 05:26:07.113 PST [883M] INFO: Thread dns-client (2) is idle, terminating it.
2024-12-20 05:26:07.113 PST [883M] INFO: Thread ntp-client (4) is idle, terminating it.
2024-12-20 05:26:07.113 PST [883M] INFO: All threads joined
2024-12-20 05:26:07.114 PST [883M] DEBUG_ANY: Closing gravity database
2024-12-20 05:26:07.121 PST [883M] INFO: Stored 4 API sessions in the database
2024-12-20 05:26:08.223 PST [883M] INFO: ########## FTL terminated after 9h 45m 51s  (code 0)! ##########
2024-12-20 05:26:36.841 PST [921M] INFO: ########## FTL started on pi5! ##########
2024-12-20 05:26:36.843 PST [921M] INFO: FTL branch: development
2024-12-20 05:26:36.843 PST [921M] INFO: FTL version: vDev-91ea8d4
2024-12-20 05:26:36.843 PST [921M] INFO: FTL commit: 91ea8d49
2024-12-20 05:26:36.844 PST [921M] INFO: FTL date: 2024-12-10 19:38:42 +0100
2024-12-20 05:26:36.844 PST [921M] INFO: FTL user: pihole
2024-12-20 05:26:36.844 PST [921M] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: ************************
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: *    DEBUG SETTINGS    *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * DATABASE:       NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * NETWORKING:     NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * LOCKS:          NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * QUERIES:        NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * FLAGS:          NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * SHMEM:          NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * GC:             NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * ARP:            NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * REGEX:          NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * API:            NO   *
2024-12-20 05:26:36.846 PST [921M] DEBUG_ANY: * TLS:            NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * OVERTIME:       NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * STATUS:         NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * CAPS:           NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * DNSSEC:         NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * VECTORS:        NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * RESOLVER:       NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * EDNS0:          NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * CLIENTS:        NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * ALIASCLIENTS:   NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * EVENTS:         NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * HELPER:         NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * CONFIG:         NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * INOTIFY:        NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * WEBSERVER:      NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * EXTRA:          NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * RESERVED:       NO   *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: * NTP:            YES  *
2024-12-20 05:26:36.847 PST [921M] DEBUG_ANY: ************************
2024-12-20 05:26:36.859 PST [921M] INFO: Wrote config file:
2024-12-20 05:26:36.859 PST [921M] INFO:  - 150 total entries
2024-12-20 05:26:36.859 PST [921M] INFO:  - 117 entries are default
2024-12-20 05:26:36.859 PST [921M] INFO:  - 33 entries are modified
2024-12-20 05:26:36.859 PST [921M] INFO:  - 0 entries are forced through environment
2024-12-20 05:26:36.913 PST [921M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2024-12-20 05:26:36.921 PST [921M] INFO: PID of FTL process: 921
2024-12-20 05:26:37.004 PST [921M] INFO: listening on 0.0.0.0 port 53
2024-12-20 05:26:37.023 PST [921M] INFO: listening on :: port 53
2024-12-20 05:26:37.024 PST [921M] INFO: PID of FTL process: 921
2024-12-20 05:26:37.331 PST [921M] INFO: Database version is 20
2024-12-20 05:26:37.332 PST [921M] INFO: Database successfully initialized
2024-12-20 05:27:19.932 PST [921M] INFO: Imported 117359 queries from the on-disk database (it has 9072984 rows)
2024-12-20 05:27:19.932 PST [921M] INFO: Parsing queries in database
2024-12-20 05:27:20.004 PST [921M] INFO:   10000 queries parsed...
2024-12-20 05:27:20.050 PST [921M] INFO:   20000 queries parsed...
2024-12-20 05:27:20.096 PST [921M] INFO:   30000 queries parsed...
2024-12-20 05:27:20.136 PST [921M] INFO:   40000 queries parsed...
2024-12-20 05:27:20.172 PST [921M] INFO:   50000 queries parsed...
2024-12-20 05:27:20.218 PST [921M] INFO:   60000 queries parsed...
2024-12-20 05:27:20.287 PST [921M] INFO:   70000 queries parsed...
2024-12-20 05:27:20.342 PST [921M] INFO:   80000 queries parsed...
2024-12-20 05:27:20.405 PST [921M] INFO:   90000 queries parsed...
2024-12-20 05:27:20.447 PST [921M] INFO:   100000 queries parsed...
2024-12-20 05:27:20.481 PST [921M] INFO:   110000 queries parsed...
2024-12-20 05:27:20.513 PST [921M] INFO: Imported 117289 queries from the long-term database
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Total DNS queries: 117289
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Cached DNS queries: 32161
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Forwarded DNS queries: 52814
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Blocked DNS queries: 31622
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Unknown DNS queries: 340
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Unique domains: 4304
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Unique clients: 63
2024-12-20 05:27:20.513 PST [921M] INFO:  -> DNS cache records: 3050
2024-12-20 05:27:20.513 PST [921M] INFO:  -> Known forward destinations: 4
2024-12-20 05:27:20.842 PST [921M] INFO: FTL is running as user pihole (UID 999)
2024-12-20 05:27:20.842 PST [921M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2024-12-20 05:27:20.843 PST [921M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-12-20 05:27:20.844 PST [921M] INFO: Restored 4 API sessions from the database
2024-12-20 05:27:20.855 PST [921M] INFO: Blocking status is enabled
2024-12-20 05:27:20.892 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:20.892 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef38.e484a515 = 2024-12-20 05:27:20.892648 PST
2024-12-20 05:27:20.892 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3a.172d3d36 = 2024-12-20 05:27:22.090534 PST
2024-12-20 05:27:20.892 PST [921/T1448] DEBUG_NTP: Time offset: 1.218270e+00 s
2024-12-20 05:27:20.892 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.077005e-02 s
2024-12-20 05:27:20.892 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:20.892 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:21.056 PST [921/T1449] INFO: Compiled 7 allow and 19 deny regex for 63 clients in 70.5 msec
2024-12-20 05:27:21.433 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:21.434 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef39.6f179bfd = 2024-12-20 05:27:21.433953 PST
2024-12-20 05:27:21.434 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3a.a1c571fa = 2024-12-20 05:27:22.631919 PST
2024-12-20 05:27:21.434 PST [921/T1448] DEBUG_NTP: Time offset: 1.218461e+00 s
2024-12-20 05:27:21.434 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.099083e-02 s
2024-12-20 05:27:21.434 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:21.434 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:21.975 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:21.975 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef39.f99a9542 = 2024-12-20 05:27:21.975014 PST
2024-12-20 05:27:21.975 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3b.2c3c1469 = 2024-12-20 05:27:23.172791 PST
2024-12-20 05:27:21.975 PST [921/T1448] DEBUG_NTP: Time offset: 1.218138e+00 s
2024-12-20 05:27:21.975 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.072237e-02 s
2024-12-20 05:27:21.975 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:21.975 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:22.515 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:22.516 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef3a.841669ce = 2024-12-20 05:27:22.515966 PST
2024-12-20 05:27:22.516 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3b.b6bfc1ae = 2024-12-20 05:27:23.713863 PST
2024-12-20 05:27:22.516 PST [921/T1448] DEBUG_NTP: Time offset: 1.218204e+00 s
2024-12-20 05:27:22.516 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.061413e-02 s
2024-12-20 05:27:22.516 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:22.516 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:23.057 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:23.057 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef3b.0ea22b38 = 2024-12-20 05:27:23.057161 PST
2024-12-20 05:27:23.057 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3c.415065a2 = 2024-12-20 05:27:24.255133 PST
2024-12-20 05:27:23.057 PST [921/T1448] DEBUG_NTP: Time offset: 1.218425e+00 s
2024-12-20 05:27:23.057 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.090691e-02 s
2024-12-20 05:27:23.057 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:23.057 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:23.598 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:23.598 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef3b.99223183 = 2024-12-20 05:27:23.598177 PST
2024-12-20 05:27:23.598 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3c.cbd0570e = 2024-12-20 05:27:24.796147 PST
2024-12-20 05:27:23.598 PST [921/T1448] DEBUG_NTP: Time offset: 1.218328e+00 s
2024-12-20 05:27:23.598 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.071617e-02 s
2024-12-20 05:27:23.598 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:23.598 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:24.139 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:24.139 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef3c.23b65668 = 2024-12-20 05:27:24.139500 PST
2024-12-20 05:27:24.139 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3d.5656dfd3 = 2024-12-20 05:27:25.337263 PST
2024-12-20 05:27:24.139 PST [921/T1448] DEBUG_NTP: Time offset: 1.218236e+00 s
2024-12-20 05:27:24.139 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.094839e-02 s
2024-12-20 05:27:24.139 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:24.139 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:24.681 PST [921/T1448] DEBUG_NTP: Server reference time: eb0fef00.00000000 = 2024-12-20 05:26:24.000000 PST
2024-12-20 05:27:24.681 PST [921/T1448] DEBUG_NTP: Current time at client: eb0fef3c.ae555c52 = 2024-12-20 05:27:24.680989 PST
2024-12-20 05:27:24.681 PST [921/T1448] DEBUG_NTP: Current time at server: eb0fef3d.e0f6ce8a = 2024-12-20 05:27:25.878765 PST
2024-12-20 05:27:24.681 PST [921/T1448] DEBUG_NTP: Time offset: 1.218349e+00 s
2024-12-20 05:27:24.681 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.114628e-02 s
2024-12-20 05:27:24.681 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 05:27:24.681 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 05:27:25.181 PST [921/T1448] INFO: Received 8/8 valid NTP replies from time.nist.gov
2024-12-20 05:27:25.181 PST [921/T1448] DEBUG_NTP: Average time offset: (1.218301e+00 +/- 1.031042e-04) s
2024-12-20 05:27:25.181 PST [921/T1448] DEBUG_NTP: Average round-trip delay: (4.085189e-02 +/- 1.645945e-04) s
2024-12-20 05:27:25.181 PST [921/T1448] INFO: Time offset: 1.218301e+03 ms (excluded 0 outliers)
2024-12-20 05:27:25.181 PST [921/T1448] INFO: Round-trip delay: 4.085189e+01 ms (excluded 0 outliers)
2024-12-20 05:27:25.181 PST [921/T1448] DEBUG_NTP: Stepping system time by 1.218301e+00 s
2024-12-20 05:27:27.001 PST [921/T1448] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 05:27:27.002 PST [921/T1448] INFO: Current RTC time is 2024-12-20 13:27:26
2024-12-20 05:27:27.002 PST [921/T1448] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 05:27:27.005 PST [921/T1448] INFO: RTC time set to 2024-12-20 13:27:27
2024-12-20 05:28:00.676 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:28:00.689 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:29:00.295 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:29:00.314 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:30:01.955 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:30:01.966 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:31:00.278 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:31:00.287 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:32:00.372 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:32:00.382 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:33:00.388 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:33:00.398 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:34:00.379 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:34:00.389 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:35:00.350 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:35:00.359 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:36:00.329 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:36:00.338 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:37:00.301 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:37:00.310 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:38:00.297 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:38:00.304 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:39:00.363 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:39:00.375 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:40:00.722 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:40:00.732 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:41:00.325 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:41:00.332 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:42:00.307 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:42:00.314 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:43:00.327 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:43:00.334 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:44:00.304 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:44:00.311 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:45:00.315 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:45:00.322 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:46:00.337 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:46:00.346 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:47:00.339 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:47:00.351 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:48:00.319 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:48:00.326 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:49:00.326 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:49:00.333 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:50:00.717 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:50:00.724 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:51:00.308 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:51:00.318 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:52:00.289 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:52:00.298 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:53:02.070 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:53:02.080 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:54:00.351 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:54:00.360 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:55:00.363 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:55:00.373 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:56:00.372 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:56:00.382 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:57:00.392 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:57:00.402 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:58:00.385 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:58:00.395 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:59:00.359 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 05:59:00.379 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:00:00.705 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:00:00.716 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:01:00.367 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:01:00.377 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:02:00.404 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:02:00.414 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:03:00.282 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:03:00.292 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:04:00.285 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:04:00.294 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:05:00.314 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:05:00.325 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:06:00.380 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:06:00.390 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:07:00.381 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:07:00.392 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:08:00.380 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:08:00.391 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:09:00.386 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:09:00.396 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:10:00.859 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:10:00.870 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:10:13.412 PST [9093/F921] DEBUG_ANY: Reopening Gravity database for this fork
2024-12-20 06:10:13.418 PST [9093/F921] DEBUG_ANY: Closing gravity database
2024-12-20 06:10:13.423 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:11:00.355 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:11:00.362 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:12:00.313 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:12:00.320 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:13:00.279 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:13:00.286 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:14:00.335 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:14:00.343 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:15:00.320 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:15:00.327 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:16:00.294 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:16:00.302 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:17:00.353 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:17:00.360 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:18:00.316 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:18:00.323 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:19:00.308 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:19:00.315 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:20:00.656 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:20:00.667 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:21:00.325 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:21:00.332 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:22:03.367 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:22:03.374 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:23:00.319 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:23:00.326 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:24:00.304 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:24:00.311 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:25:00.364 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:25:00.372 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:26:00.308 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:26:00.316 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:27:02.923 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:27:02.930 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:28:00.288 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:28:00.295 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:29:00.368 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:29:00.375 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:30:00.725 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:30:00.736 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:31:00.307 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:31:00.315 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:32:00.286 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:32:00.293 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:33:00.338 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:33:00.345 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:34:00.292 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:34:00.299 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:35:00.345 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:35:00.353 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:36:00.325 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:36:00.332 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:37:00.300 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:37:00.307 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:38:00.314 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:38:00.322 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:39:00.271 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:39:00.279 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:40:00.712 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:40:00.720 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:41:00.325 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:41:00.326 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:42:00.357 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:42:00.364 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:43:00.337 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:43:00.344 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:44:00.323 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:44:00.331 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:45:00.298 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:45:00.306 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:46:00.256 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:46:00.263 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:47:00.328 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:47:00.336 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:47:45.449 PST [15868/F921] DEBUG_ANY: Reopening Gravity database for this fork
2024-12-20 06:47:45.458 PST [15868/F921] DEBUG_ANY: Closing gravity database
2024-12-20 06:47:45.464 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:48:00.353 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:48:00.360 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:49:00.705 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:49:00.715 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:50:00.283 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:50:00.291 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:51:00.403 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:51:00.411 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:52:00.264 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:52:00.272 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:53:00.470 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:53:00.477 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:53:59.114 PST [921M] ERROR: Trying to access dns_cache ID 4294967295, but maximum is 5632
2024-12-20 06:53:59.114 PST [921M] ERROR: found in FTL_CNAME() (src/dnsmasq_interface.c:1813)
2024-12-20 06:54:00.346 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:54:00.353 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:55:00.323 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:55:00.331 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:56:00.303 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:56:00.310 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:57:01.179 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:57:01.189 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:58:01.784 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:58:01.795 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:59:01.528 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 06:59:01.543 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:00:07.427 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:00:07.437 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:01:00.856 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:01:00.867 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:02:02.744 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:02:02.744 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:03:05.502 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:03:05.521 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:04:00.956 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:04:00.964 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:05:00.330 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:05:00.338 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:06:00.292 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:06:00.300 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:07:00.271 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:07:00.278 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:08:00.344 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:08:00.352 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:09:00.334 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:09:00.346 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:10:00.839 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:10:00.847 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:11:00.334 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:11:00.341 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:12:00.295 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:12:00.302 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:13:00.276 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:13:00.284 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:14:00.337 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:14:00.345 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:15:00.313 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:15:00.321 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:16:00.284 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:16:00.292 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:17:00.349 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:17:00.356 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:18:00.310 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:18:00.318 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:19:00.291 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:19:00.301 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:20:00.636 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:20:00.644 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:21:00.299 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:21:00.306 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:22:00.257 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:22:00.265 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:23:01.343 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:23:01.354 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:24:01.677 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:24:01.685 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:25:03.515 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:25:03.523 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:26:01.678 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:26:01.686 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:27:00.339 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:27:00.347 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:27:27.114 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:27.114 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b5f.1d43393a = 2024-12-20 07:27:27.114306 PST
2024-12-20 07:27:27.114 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b5f.23a521d1 = 2024-12-20 07:27:27.139238 PST
2024-12-20 07:27:27.114 PST [921/T1448] DEBUG_NTP: Time offset: 4.518533e-02 s
2024-12-20 07:27:27.114 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.050779e-02 s
2024-12-20 07:27:27.114 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:27.114 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:27.655 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:27.655 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b5f.a7d0aed9 = 2024-12-20 07:27:27.655527 PST
2024-12-20 07:27:27.655 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b5f.ae317e5a = 2024-12-20 07:27:27.680442 PST
2024-12-20 07:27:27.655 PST [921/T1448] DEBUG_NTP: Time offset: 4.533839e-02 s
2024-12-20 07:27:27.655 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.084730e-02 s
2024-12-20 07:27:27.655 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:27.655 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:28.196 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:28.196 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b60.32617c1b = 2024-12-20 07:27:28.196799 PST
2024-12-20 07:27:28.200 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b60.38c35ec6 = 2024-12-20 07:27:28.221731 PST
2024-12-20 07:27:28.200 PST [921/T1448] DEBUG_NTP: Time offset: 4.538202e-02 s
2024-12-20 07:27:28.200 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.090214e-02 s
2024-12-20 07:27:28.200 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:28.200 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:28.741 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:28.741 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b60.bdc6f36e = 2024-12-20 07:27:28.741316 PST
2024-12-20 07:27:28.741 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b60.c4388baf = 2024-12-20 07:27:28.766487 PST
2024-12-20 07:27:28.741 PST [921/T1448] DEBUG_NTP: Time offset: 4.560995e-02 s
2024-12-20 07:27:28.741 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.087830e-02 s
2024-12-20 07:27:28.741 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:28.741 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:29.282 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:29.282 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b61.48398a65 = 2024-12-20 07:27:29.282127 PST
2024-12-20 07:27:29.282 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b61.4ea0c731 = 2024-12-20 07:27:29.307140 PST
2024-12-20 07:27:29.282 PST [921/T1448] DEBUG_NTP: Time offset: 4.523683e-02 s
2024-12-20 07:27:29.282 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.044771e-02 s
2024-12-20 07:27:29.282 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:29.282 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:29.823 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:29.823 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b61.d2b97fe8 = 2024-12-20 07:27:29.823142 PST
2024-12-20 07:27:29.823 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b61.d91ba4c3 = 2024-12-20 07:27:29.848078 PST
2024-12-20 07:27:29.823 PST [921/T1448] DEBUG_NTP: Time offset: 4.523277e-02 s
2024-12-20 07:27:29.823 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.059505e-02 s
2024-12-20 07:27:29.823 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:29.823 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:30.364 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:30.364 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b62.5d35eb74 = 2024-12-20 07:27:30.364103 PST
2024-12-20 07:27:30.364 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b62.63a1306b = 2024-12-20 07:27:30.389178 PST
2024-12-20 07:27:30.364 PST [921/T1448] DEBUG_NTP: Time offset: 4.536486e-02 s
2024-12-20 07:27:30.364 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.058075e-02 s
2024-12-20 07:27:30.364 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:30.364 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:30.905 PST [921/T1448] DEBUG_NTP: Server reference time: eb100b00.00000000 = 2024-12-20 07:25:52.000000 PST
2024-12-20 07:27:30.905 PST [921/T1448] DEBUG_NTP: Current time at client: eb100b62.e7b506dd = 2024-12-20 07:27:30.905105 PST
2024-12-20 07:27:30.905 PST [921/T1448] DEBUG_NTP: Current time at server: eb100b62.ee1d4bd5 = 2024-12-20 07:27:30.930134 PST
2024-12-20 07:27:30.905 PST [921/T1448] DEBUG_NTP: Time offset: 4.534554e-02 s
2024-12-20 07:27:30.905 PST [921/T1448] DEBUG_NTP: Round-trip delay: 4.063463e-02 s
2024-12-20 07:27:30.905 PST [921/T1448] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 07:27:30.905 PST [921/T1448] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 07:27:31.405 PST [921/T1448] INFO: Received 8/8 valid NTP replies from time.nist.gov
2024-12-20 07:27:31.405 PST [921/T1448] DEBUG_NTP: Average time offset: (4.533696e-02 +/- 1.231274e-04) s
2024-12-20 07:27:31.405 PST [921/T1448] DEBUG_NTP: Average round-trip delay: (4.067421e-02 +/- 1.655013e-04) s
2024-12-20 07:27:31.405 PST [921/T1448] INFO: Time offset: 4.529796e+01 ms (excluded 1 outliers)
2024-12-20 07:27:31.405 PST [921/T1448] INFO: Round-trip delay: 4.064505e+01 ms (excluded 1 outliers)
2024-12-20 07:27:31.405 PST [921/T1448] DEBUG_NTP: Gradually adjusting system time by 45297 us
2024-12-20 07:27:32.000 PST [921/T1448] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 07:27:32.001 PST [921/T1448] INFO: Current RTC time is 2024-12-20 15:27:31
2024-12-20 07:27:32.001 PST [921/T1448] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 07:27:32.003 PST [921/T1448] INFO: RTC time set to 2024-12-20 15:27:32
2024-12-20 07:27:32.003 PST [921/T24381] INFO: NTP server listening on 0.0.0.0:123 (IPv4)
2024-12-20 07:28:00.303 PST [921M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 07:28:00.310 PST [921M] DEBUG_ANY: dnsmasq received signal 17

DL6ER · December 20, 2024, 3:58pm

The code starts the NTP server only after the first successful NTP sync. Successful in this context means the quality of the local clock has to be high enough. This isn't the case at 05:27 because the time offset from local to remote was larger than 1 second:

Two hours later, the time offset was much smaller (0.05 seconds) so FTL knew that the clock remained sufficiently stable within the past two hours so it may be used as local time source:

We could add some logging why the NTP server was not started if you would consider this helpful. I'm not sure if we should make this an INFO or hide it behind DEBUG_NTP though (I lean towards the latter TBH but it's unclear it it'd be seen then).

sawsanders · December 20, 2024, 4:32pm

So if the device doesn't have a RTC, and the time is way off, the server won't start until the second time sync, right? If you have network devices that depend on Pi-hole for time, wouldn't it make sense to start the server after the first sync? Or maybe I should increase the frequency of time syncs to decrease the time the NTP server is unavailable...

I also find it strange that the RPi5, which has a RTC, is far enough off to cause this to happen, while my RPi4, without a RTC, doesn't exhibit this behavior.

I think this would have been very helpful to me trying to self diagnose why the NTP server never started. I think having the message only show with DEBUG_NTP active would be sufficient.

At any rate, I'm glad I understand what is happening now and won't have to nuke my setup.

DL6ER · December 20, 2024, 7:01pm

Yes, dynamically decreasing the re-sync from two hours to something like ten seconds seems a good idea. But we also limit this to be done at most three times so we don't spam upstream servers too much. I will also add the debug message.

The key is "far enough". We consider a deviation of at most 0.1 seconds accurate enough. Note that, however, the RTC is only accurate within a second so relying on an RTC alone (without NTP) is expected to give you sufficient deviations.

sawsanders · December 21, 2024, 12:53am

Awesome! Thank you!

I updated and rebooted. However, now I see it getting the time from upstream, trying to set the clock, reporting the RTC is accurate, reporting the time is inaccurate, and trying again until it times out.

2024-12-20 16:45:21.540 PST [884M] INFO: ########## FTL started on pi5! ##########
2024-12-20 16:45:21.566 PST [884M] INFO: FTL branch: tweak/ntp_errors
2024-12-20 16:45:21.566 PST [884M] INFO: FTL version: vDev-c002dc2
2024-12-20 16:45:21.566 PST [884M] INFO: FTL commit: c002dc2c
2024-12-20 16:45:21.566 PST [884M] INFO: FTL date: 2024-12-20 20:03:02 +0100
2024-12-20 16:45:21.566 PST [884M] INFO: FTL user: pihole
2024-12-20 16:45:21.566 PST [884M] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: ************************
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: *    DEBUG SETTINGS    *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * DATABASE:       NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * NETWORKING:     NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * LOCKS:          NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * QUERIES:        NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * FLAGS:          NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * SHMEM:          NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * GC:             NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * ARP:            NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * REGEX:          NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * API:            NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * TLS:            NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * OVERTIME:       NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * STATUS:         NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * CAPS:           NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * DNSSEC:         NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * VECTORS:        NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * RESOLVER:       NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * EDNS0:          NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * CLIENTS:        NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * ALIASCLIENTS:   NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * EVENTS:         NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * HELPER:         NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * CONFIG:         NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * INOTIFY:        NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * WEBSERVER:      NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * EXTRA:          NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * RESERVED:       NO   *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: * NTP:            YES  *
2024-12-20 16:45:21.569 PST [884M] DEBUG_ANY: ************************
2024-12-20 16:45:21.578 PST [884M] INFO: Wrote config file:
2024-12-20 16:45:21.578 PST [884M] INFO:  - 150 total entries
2024-12-20 16:45:21.578 PST [884M] INFO:  - 117 entries are default
2024-12-20 16:45:21.578 PST [884M] INFO:  - 33 entries are modified
2024-12-20 16:45:21.578 PST [884M] INFO:  - 0 entries are forced through environment
2024-12-20 16:45:21.703 PST [884M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2024-12-20 16:45:21.713 PST [884M] INFO: PID of FTL process: 884
2024-12-20 16:45:21.790 PST [884M] INFO: listening on 0.0.0.0 port 53
2024-12-20 16:45:21.790 PST [884M] INFO: listening on :: port 53
2024-12-20 16:45:21.791 PST [884M] INFO: PID of FTL process: 884
2024-12-20 16:45:21.974 PST [884M] INFO: Database version is 20
2024-12-20 16:45:21.975 PST [884M] INFO: Database successfully initialized
2024-12-20 16:47:17.601 PST [884M] INFO: Imported 106226 queries from the on-disk database (it has 9069726 rows)
2024-12-20 16:47:17.601 PST [884M] INFO: Parsing queries in database
2024-12-20 16:47:17.688 PST [884M] INFO:   10000 queries parsed...
2024-12-20 16:47:17.744 PST [884M] INFO:   20000 queries parsed...
2024-12-20 16:47:17.789 PST [884M] INFO:   30000 queries parsed...
2024-12-20 16:47:17.846 PST [884M] INFO:   40000 queries parsed...
2024-12-20 16:47:17.885 PST [884M] INFO:   50000 queries parsed...
2024-12-20 16:47:17.923 PST [884M] INFO:   60000 queries parsed...
2024-12-20 16:47:17.966 PST [884M] INFO:   70000 queries parsed...
2024-12-20 16:47:18.009 PST [884M] INFO:   80000 queries parsed...
2024-12-20 16:47:18.046 PST [884M] INFO:   90000 queries parsed...
2024-12-20 16:47:18.083 PST [884M] INFO:   100000 queries parsed...
2024-12-20 16:47:18.105 PST [884M] INFO: Imported 106058 queries from the long-term database
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Total DNS queries: 106058
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Cached DNS queries: 29114
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Forwarded DNS queries: 46973
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Blocked DNS queries: 29230
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Unknown DNS queries: 324
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Unique domains: 3853
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Unique clients: 70
2024-12-20 16:47:18.105 PST [884M] INFO:  -> DNS cache records: 2790
2024-12-20 16:47:18.105 PST [884M] INFO:  -> Known forward destinations: 4
2024-12-20 16:47:18.411 PST [884M] INFO: FTL is running as user pihole (UID 999)
2024-12-20 16:47:18.412 PST [884M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2024-12-20 16:47:18.413 PST [884M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-12-20 16:47:18.414 PST [884M] INFO: Restored 4 API sessions from the database
2024-12-20 16:47:18.424 PST [884M] INFO: Blocking status is enabled
2024-12-20 16:47:18.472 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:18.472 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e96.78fa0514 = 2024-12-20 16:47:18.472564 PST
2024-12-20 16:47:18.472 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e96.9edbfa74 = 2024-12-20 16:47:18.620544 PST
2024-12-20 16:47:18.472 PST [884/T1551] DEBUG_NTP: Time offset: 1.734722e-01 s
2024-12-20 16:47:18.472 PST [884/T1551] DEBUG_NTP: Round-trip delay: 5.098677e-02 s
2024-12-20 16:47:18.472 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:18.472 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:18.595 PST [884/T1552] INFO: Compiled 7 allow and 19 deny regex for 70 clients in 76.0 msec
2024-12-20 16:47:19.033 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:19.033 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e97.08a569b1 = 2024-12-20 16:47:19.033773 PST
2024-12-20 16:47:19.034 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e97.2d84686b = 2024-12-20 16:47:19.177801 PST
2024-12-20 16:47:19.034 PST [884/T1551] DEBUG_NTP: Time offset: 1.744812e-01 s
2024-12-20 16:47:19.034 PST [884/T1551] DEBUG_NTP: Round-trip delay: 6.090689e-02 s
2024-12-20 16:47:19.034 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:19.034 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:19.575 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:19.575 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e97.934c5da6 = 2024-12-20 16:47:19.575383 PST
2024-12-20 16:47:19.575 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e97.bbc69ab2 = 2024-12-20 16:47:19.733499 PST
2024-12-20 16:47:19.575 PST [884/T1551] DEBUG_NTP: Time offset: 1.786220e-01 s
2024-12-20 16:47:19.576 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.101419e-02 s
2024-12-20 16:47:19.576 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:19.576 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:20.116 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:20.116 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e98.1ded06fe = 2024-12-20 16:47:20.116897 PST
2024-12-20 16:47:20.117 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e98.46772d6f = 2024-12-20 16:47:20.275256 PST
2024-12-20 16:47:20.117 PST [884/T1551] DEBUG_NTP: Time offset: 1.786683e-01 s
2024-12-20 16:47:20.117 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.062033e-02 s
2024-12-20 16:47:20.117 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:20.117 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:20.659 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:20.659 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e98.a8e0c9d9 = 2024-12-20 16:47:20.659679 PST
2024-12-20 16:47:20.659 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e98.d106e4b6 = 2024-12-20 16:47:20.816511 PST
2024-12-20 16:47:20.659 PST [884/T1551] DEBUG_NTP: Time offset: 1.780663e-01 s
2024-12-20 16:47:20.659 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.246902e-02 s
2024-12-20 16:47:20.659 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:20.659 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:21.201 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:21.201 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e99.339bbadc = 2024-12-20 16:47:21.201594 PST
2024-12-20 16:47:21.201 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e99.5c2d414e = 2024-12-20 16:47:21.360065 PST
2024-12-20 16:47:21.201 PST [884/T1551] DEBUG_NTP: Time offset: 1.790888e-01 s
2024-12-20 16:47:21.201 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.123640e-02 s
2024-12-20 16:47:21.201 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:21.201 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:21.742 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:21.742 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e99.be2131a8 = 2024-12-20 16:47:21.742693 PST
2024-12-20 16:47:21.742 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e99.e6a5bd65 = 2024-12-20 16:47:21.900966 PST
2024-12-20 16:47:21.742 PST [884/T1551] DEBUG_NTP: Time offset: 1.786413e-01 s
2024-12-20 16:47:21.742 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.073715e-02 s
2024-12-20 16:47:21.742 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:21.742 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:22.283 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:22.283 PST [884/T1551] DEBUG_NTP: Current time at client: eb108e9a.489e55c0 = 2024-12-20 16:47:22.283665 PST
2024-12-20 16:47:22.283 PST [884/T1551] DEBUG_NTP: Current time at server: eb108e9a.712dce62 = 2024-12-20 16:47:22.442105 PST
2024-12-20 16:47:22.283 PST [884/T1551] DEBUG_NTP: Time offset: 1.787627e-01 s
2024-12-20 16:47:22.283 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.064703e-02 s
2024-12-20 16:47:22.283 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:22.283 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:22.783 PST [884/T1551] INFO: Received 8/8 valid NTP replies from time.nist.gov
2024-12-20 16:47:22.784 PST [884/T1551] DEBUG_NTP: Average time offset: (1.774753e-01 +/- 2.052368e-03) s
2024-12-20 16:47:22.784 PST [884/T1551] DEBUG_NTP: Average round-trip delay: (4.482722e-02 +/- 6.904623e-03) s
2024-12-20 16:47:22.784 PST [884/T1551] INFO: Time offset: 1.779031e+02 ms (excluded 1 outliers)
2024-12-20 16:47:22.784 PST [884/T1551] INFO: Round-trip delay: 4.253013e+01 ms (excluded 1 outliers)
2024-12-20 16:47:22.784 PST [884/T1551] DEBUG_NTP: Gradually adjusting system time by 177903 us
2024-12-20 16:47:23.000 PST [884/T1551] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 16:47:23.001 PST [884/T1551] INFO: Current RTC time is 2024-12-21 00:47:23
2024-12-20 16:47:23.001 PST [884/T1551] DEBUG_NTP: RTC time is already correct
2024-12-20 16:47:23.001 PST [884/T1551] DEBUG_NTP: Local time is too inaccurate, retrying before launching NTP server
2024-12-20 16:47:33.057 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:33.057 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea5.0e9f16b1 = 2024-12-20 16:47:33.057114 PST
2024-12-20 16:47:33.057 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea5.35e387b9 = 2024-12-20 16:47:33.210503 PST
2024-12-20 16:47:33.057 PST [884/T1551] DEBUG_NTP: Time offset: 1.736963e-01 s
2024-12-20 16:47:33.057 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.061651e-02 s
2024-12-20 16:47:33.057 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:33.057 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:33.602 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:33.602 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea5.9a3065f9 = 2024-12-20 16:47:33.602300 PST
2024-12-20 16:47:33.602 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea5.c0db59fa = 2024-12-20 16:47:33.753347 PST
2024-12-20 16:47:33.602 PST [884/T1551] DEBUG_NTP: Time offset: 1.726742e-01 s
2024-12-20 16:47:33.602 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.325676e-02 s
2024-12-20 16:47:33.602 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:33.602 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:34.143 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:34.143 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea6.24b74ddf = 2024-12-20 16:47:34.143421 PST
2024-12-20 16:47:34.143 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea6.4bdd8477 = 2024-12-20 16:47:34.296348 PST
2024-12-20 16:47:34.143 PST [884/T1551] DEBUG_NTP: Time offset: 1.732645e-01 s
2024-12-20 16:47:34.143 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.067516e-02 s
2024-12-20 16:47:34.143 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:34.143 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:34.684 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:34.684 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea6.af48d3ae = 2024-12-20 16:47:34.684704 PST
2024-12-20 16:47:34.684 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea6.d658d588 = 2024-12-20 16:47:34.837293 PST
2024-12-20 16:47:34.684 PST [884/T1551] DEBUG_NTP: Time offset: 1.730227e-01 s
2024-12-20 16:47:34.684 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.086876e-02 s
2024-12-20 16:47:34.684 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:34.684 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:35.225 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:35.225 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea7.39c58255 = 2024-12-20 16:47:35.225669 PST
2024-12-20 16:47:35.225 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea7.60c51679 = 2024-12-20 16:47:35.378007 PST
2024-12-20 16:47:35.225 PST [884/T1551] DEBUG_NTP: Time offset: 1.726635e-01 s
2024-12-20 16:47:35.225 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.065180e-02 s
2024-12-20 16:47:35.225 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:35.225 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:35.766 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:35.767 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea7.c4581494 = 2024-12-20 16:47:35.766968 PST
2024-12-20 16:47:35.767 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea7.eb4a3310 = 2024-12-20 16:47:35.919100 PST
2024-12-20 16:47:35.767 PST [884/T1551] DEBUG_NTP: Time offset: 1.726215e-01 s
2024-12-20 16:47:35.767 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.097986e-02 s
2024-12-20 16:47:35.767 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:35.767 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:36.307 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:36.308 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea8.4ed5f138 = 2024-12-20 16:47:36.307951 PST
2024-12-20 16:47:36.308 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea8.75b6905b = 2024-12-20 16:47:36.459816 PST
2024-12-20 16:47:36.308 PST [884/T1551] DEBUG_NTP: Time offset: 1.721771e-01 s
2024-12-20 16:47:36.308 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.062414e-02 s
2024-12-20 16:47:36.308 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:36.308 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:36.849 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:36.849 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ea8.d99157ab = 2024-12-20 16:47:36.849873 PST
2024-12-20 16:47:36.850 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ea9.0034e00f = 2024-12-20 16:47:37.000806 PST
2024-12-20 16:47:36.850 PST [884/T1551] DEBUG_NTP: Time offset: 1.717305e-01 s
2024-12-20 16:47:36.850 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.159546e-02 s
2024-12-20 16:47:36.850 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:36.850 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:37.350 PST [884/T1551] INFO: Received 8/8 valid NTP replies from time.nist.gov
2024-12-20 16:47:37.350 PST [884/T1551] DEBUG_NTP: Average time offset: (1.727313e-01 +/- 5.732676e-04) s
2024-12-20 16:47:37.350 PST [884/T1551] DEBUG_NTP: Average round-trip delay: (4.115856e-02 +/- 8.499366e-04) s
2024-12-20 16:47:37.350 PST [884/T1551] INFO: Time offset: 1.727394e+02 ms (excluded 1 outliers)
2024-12-20 16:47:37.350 PST [884/T1551] INFO: Round-trip delay: 4.085881e+01 ms (excluded 1 outliers)
2024-12-20 16:47:37.350 PST [884/T1551] DEBUG_NTP: Gradually adjusting system time by 172739 us
2024-12-20 16:47:38.000 PST [884/T1551] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 16:47:38.001 PST [884/T1551] INFO: Current RTC time is 2024-12-21 00:47:38
2024-12-20 16:47:38.001 PST [884/T1551] DEBUG_NTP: RTC time is already correct
2024-12-20 16:47:38.001 PST [884/T1551] DEBUG_NTP: Local time is too inaccurate, retrying before launching NTP server
2024-12-20 16:47:48.059 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:48.059 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb4.0f3d3a1d = 2024-12-20 16:47:48.059527 PST
2024-12-20 16:47:48.059 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb4.34a39dc3 = 2024-12-20 16:47:48.205621 PST
2024-12-20 16:47:48.059 PST [884/T1551] DEBUG_NTP: Time offset: 1.666358e-01 s
2024-12-20 16:47:48.059 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.108381e-02 s
2024-12-20 16:47:48.059 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:48.059 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:48.600 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:48.600 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb4.99bf37b8 = 2024-12-20 16:47:48.600573 PST
2024-12-20 16:47:48.600 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb4.bf0dd051 = 2024-12-20 16:47:48.746304 PST
2024-12-20 16:47:48.600 PST [884/T1551] DEBUG_NTP: Time offset: 1.660948e-01 s
2024-12-20 16:47:48.600 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.072857e-02 s
2024-12-20 16:47:48.600 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:48.600 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:49.141 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:49.141 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb5.243dbc23 = 2024-12-20 16:47:49.141566 PST
2024-12-20 16:47:49.141 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb5.497f784e = 2024-12-20 16:47:49.287101 PST
2024-12-20 16:47:49.141 PST [884/T1551] DEBUG_NTP: Time offset: 1.658709e-01 s
2024-12-20 16:47:49.141 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.067373e-02 s
2024-12-20 16:47:49.141 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:49.141 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:49.683 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:49.683 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb5.aef8f041 = 2024-12-20 16:47:49.683485 PST
2024-12-20 16:47:49.683 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb5.d41959b2 = 2024-12-20 16:47:49.828511 PST
2024-12-20 16:47:49.683 PST [884/T1551] DEBUG_NTP: Time offset: 1.658161e-01 s
2024-12-20 16:47:49.683 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.158068e-02 s
2024-12-20 16:47:49.683 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:49.683 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:50.224 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:50.224 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb6.39900820 = 2024-12-20 16:47:50.224853 PST
2024-12-20 16:47:50.224 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb6.5eac4d54 = 2024-12-20 16:47:50.369816 PST
2024-12-20 16:47:50.224 PST [884/T1551] DEBUG_NTP: Time offset: 1.654832e-01 s
2024-12-20 16:47:50.225 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.104090e-02 s
2024-12-20 16:47:50.225 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:50.225 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:50.766 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:50.766 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb6.c4203e63 = 2024-12-20 16:47:50.766116 PST
2024-12-20 16:47:50.766 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb6.e918a658 = 2024-12-20 16:47:50.910532 PST
2024-12-20 16:47:50.766 PST [884/T1551] DEBUG_NTP: Time offset: 1.648326e-01 s
2024-12-20 16:47:50.766 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.083443e-02 s
2024-12-20 16:47:50.766 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:50.766 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:51.307 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:51.307 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb7.4ea24cc6 = 2024-12-20 16:47:51.307163 PST
2024-12-20 16:47:51.307 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb7.739e617f = 2024-12-20 16:47:51.451635 PST
2024-12-20 16:47:51.307 PST [884/T1551] DEBUG_NTP: Time offset: 1.648002e-01 s
2024-12-20 16:47:51.307 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.065800e-02 s
2024-12-20 16:47:51.307 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:51.307 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:51.848 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:47:51.848 PST [884/T1551] DEBUG_NTP: Current time at client: eb108eb7.d931fcd2 = 2024-12-20 16:47:51.848418 PST
2024-12-20 16:47:51.848 PST [884/T1551] DEBUG_NTP: Current time at server: eb108eb7.fe182111 = 2024-12-20 16:47:51.992555 PST
2024-12-20 16:47:51.848 PST [884/T1551] DEBUG_NTP: Time offset: 1.645544e-01 s
2024-12-20 16:47:51.848 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.083586e-02 s
2024-12-20 16:47:51.848 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:47:51.848 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:47:52.348 PST [884/T1551] INFO: Received 8/8 valid NTP replies from time.nist.gov
2024-12-20 16:47:52.348 PST [884/T1551] DEBUG_NTP: Average time offset: (1.655110e-01 +/- 6.809846e-04) s
2024-12-20 16:47:52.348 PST [884/T1551] DEBUG_NTP: Average round-trip delay: (4.092950e-02 +/- 2.866978e-04) s
2024-12-20 16:47:52.348 PST [884/T1551] INFO: Time offset: 1.654674e+02 ms (excluded 1 outliers)
2024-12-20 16:47:52.348 PST [884/T1551] INFO: Round-trip delay: 4.083647e+01 ms (excluded 1 outliers)
2024-12-20 16:47:52.348 PST [884/T1551] DEBUG_NTP: Gradually adjusting system time by 165467 us
2024-12-20 16:47:53.000 PST [884/T1551] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 16:47:53.003 PST [884/T1551] INFO: Current RTC time is 2024-12-21 00:47:53
2024-12-20 16:47:53.003 PST [884/T1551] DEBUG_NTP: RTC time is already correct
2024-12-20 16:47:53.003 PST [884/T1551] DEBUG_NTP: Local time is too inaccurate, retrying before launching NTP server
2024-12-20 16:48:00.815 PST [884M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 16:48:00.830 PST [884M] DEBUG_ANY: dnsmasq received signal 17
2024-12-20 16:48:03.049 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:03.049 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec3.0cbdec5f = 2024-12-20 16:48:03.049772 PST
2024-12-20 16:48:03.049 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec3.30368b4e = 2024-12-20 16:48:03.188332 PST
2024-12-20 16:48:03.049 PST [884/T1551] DEBUG_NTP: Time offset: 1.588612e-01 s
2024-12-20 16:48:03.049 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.060459e-02 s
2024-12-20 16:48:03.049 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:03.049 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:03.591 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:03.591 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec3.974d37c1 = 2024-12-20 16:48:03.591021 PST
2024-12-20 16:48:03.591 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec3.bab48e78 = 2024-12-20 16:48:03.729317 PST
2024-12-20 16:48:03.591 PST [884/T1551] DEBUG_NTP: Time offset: 1.587472e-01 s
2024-12-20 16:48:03.591 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.090309e-02 s
2024-12-20 16:48:03.591 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:03.591 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:04.131 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:04.132 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec4.21c8fb86 = 2024-12-20 16:48:04.131972 PST
2024-12-20 16:48:04.132 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec4.4524e990 = 2024-12-20 16:48:04.270094 PST
2024-12-20 16:48:04.132 PST [884/T1551] DEBUG_NTP: Time offset: 1.584275e-01 s
2024-12-20 16:48:04.132 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.061174e-02 s
2024-12-20 16:48:04.132 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:04.132 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:04.673 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:04.673 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec4.ac49dbec = 2024-12-20 16:48:04.673001 PST
2024-12-20 16:48:04.673 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec4.cf9254c5 = 2024-12-20 16:48:04.810826 PST
2024-12-20 16:48:04.673 PST [884/T1551] DEBUG_NTP: Time offset: 1.581664e-01 s
2024-12-20 16:48:04.673 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.068279e-02 s
2024-12-20 16:48:04.673 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:04.673 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:05.214 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:05.214 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec5.36d97b30 = 2024-12-20 16:48:05.214255 PST
2024-12-20 16:48:05.214 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec5.5a1d62cd = 2024-12-20 16:48:05.352010 PST
2024-12-20 16:48:05.214 PST [884/T1551] DEBUG_NTP: Time offset: 1.581836e-01 s
2024-12-20 16:48:05.214 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.085732e-02 s
2024-12-20 16:48:05.214 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:05.214 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:05.755 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:05.755 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec5.c16909ae = 2024-12-20 16:48:05.755508 PST
2024-12-20 16:48:05.755 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec5.e48f6ab4 = 2024-12-20 16:48:05.892813 PST
2024-12-20 16:48:05.755 PST [884/T1551] DEBUG_NTP: Time offset: 1.577420e-01 s
2024-12-20 16:48:05.755 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.087543e-02 s
2024-12-20 16:48:05.755 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:05.755 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:06.296 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:06.296 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec6.4bff4773 = 2024-12-20 16:48:06.296863 PST
2024-12-20 16:48:06.297 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec6.6f0db012 = 2024-12-20 16:48:06.433802 PST
2024-12-20 16:48:06.297 PST [884/T1551] DEBUG_NTP: Time offset: 1.574442e-01 s
2024-12-20 16:48:06.297 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.101133e-02 s
2024-12-20 16:48:06.297 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:06.297 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:06.838 PST [884/T1551] DEBUG_NTP: Server reference time: eb108e80.00000000 = 2024-12-20 16:46:56.000000 PST
2024-12-20 16:48:06.838 PST [884/T1551] DEBUG_NTP: Current time at client: eb108ec6.d68a82a5 = 2024-12-20 16:48:06.838050 PST
2024-12-20 16:48:06.838 PST [884/T1551] DEBUG_NTP: Current time at server: eb108ec6.f98f1dc8 = 2024-12-20 16:48:06.974840 PST
2024-12-20 16:48:06.838 PST [884/T1551] DEBUG_NTP: Time offset: 1.571989e-01 s
2024-12-20 16:48:06.838 PST [884/T1551] DEBUG_NTP: Round-trip delay: 4.081917e-02 s
2024-12-20 16:48:06.838 PST [884/T1551] DEBUG_NTP: Root delay: 2.441406e-04 s
2024-12-20 16:48:06.838 PST [884/T1551] DEBUG_NTP: Root dispersion: 4.882812e-04 s
2024-12-20 16:48:07.338 PST [884/T1551] INFO: Received 8/8 valid NTP replies from time.nist.gov
2024-12-20 16:48:07.338 PST [884/T1551] DEBUG_NTP: Average time offset: (1.580964e-01 +/- 5.575504e-04) s
2024-12-20 16:48:07.338 PST [884/T1551] DEBUG_NTP: Average round-trip delay: (4.079568e-02 +/- 1.377706e-04) s
2024-12-20 16:48:07.338 PST [884/T1551] INFO: Time offset: 1.580964e+02 ms (excluded 0 outliers)
2024-12-20 16:48:07.338 PST [884/T1551] INFO: Round-trip delay: 4.079568e+01 ms (excluded 0 outliers)
2024-12-20 16:48:07.338 PST [884/T1551] DEBUG_NTP: Gradually adjusting system time by 158096 us
2024-12-20 16:48:08.000 PST [884/T1551] DEBUG_NTP: Successfully opened RTC at "/dev/rtc0"
2024-12-20 16:48:08.001 PST [884/T1551] INFO: Current RTC time is 2024-12-21 00:48:08
2024-12-20 16:48:08.001 PST [884/T1551] DEBUG_NTP: RTC time is already correct
2024-12-20 16:48:08.001 PST [884/T1551] DEBUG_NTP: Local time is too inaccurate, retrying before launching NTP server