Invalid readings after a while

[snarkbe]

After some time running gclog, the reported data is wrong:

Jun 09 00:30:15 pihole gclog[942]: CPM: 20 (= 1156/59), Timestamp: Sat Jun  8 22:29:15 2019
Jun 09 00:31:15 pihole gclog[942]: CPM: 21 (= 1247/59), Timestamp: Sat Jun  8 22:30:15 2019
Jun 09 00:32:15 pihole gclog[942]: CPM: 25 (= 1455/59), Timestamp: Sat Jun  8 22:31:15 2019
Jun 09 00:33:15 pihole gclog[942]: CPM: 27 (= 1604/59), Timestamp: Sat Jun  8 22:32:15 2019
Jun 09 00:34:15 pihole gclog[942]: CPM: 221 (= 12845/58), Timestamp: Sat Jun  8 22:33:15 2019
Jun 09 00:35:16 pihole gclog[942]: CPM: 7142 (= 428544/60), Timestamp: Sat Jun  8 22:34:16 2019
Jun 09 00:36:16 pihole gclog[942]: CPM: 7515 (= 443392/59), Timestamp: Sat Jun  8 22:35:16 2019
Jun 09 00:37:16 pihole gclog[942]: CPM: 6665 (= 399872/60), Timestamp: Sat Jun  8 22:36:16 2019
Jun 09 00:38:17 pihole gclog[942]: CPM: 4800 (= 288000/60), Timestamp: Sat Jun  8 22:37:17 2019

When that happens, the only solution is to stop/kill gclog and restart it. No idea about what triggers this.

Jun 09 10:04:43 pihole gclog[942]: CPM: 7526 (= 451584/60), Timestamp: Sun Jun  9 08:03:43 2019
Jun 09 10:05:44 pihole gclog[942]: CPM: 8333 (= 499968/60), Timestamp: Sun Jun  9 08:04:44 2019
Jun 09 10:06:20 pihole gclog[942]: [DEBUG] Main loop exited. Cleaning up...
Jun 09 10:06:41 pihole gclog[6126]: [DEBUG] Entering main loop...
Jun 09 10:07:41 pihole gclog[6126]: CPM: 29 (= 1755/61), Timestamp: Sun Jun  9 08:06:41 2019
Jun 09 10:08:42 pihole gclog[6126]: CPM: 28 (= 1629/59), Timestamp: Sun Jun  9 08:07:42 2019
Jun 09 10:09:42 pihole gclog[6126]: CPM: 25 (= 1491/60), Timestamp: Sun Jun  9 08:08:42 2019

I'm running gclog 0.2.5 on a Raspberry Pi.

[stelas]

Sorry for the late reply...
Seems to be a kind of overflow. I'm trying to reconstruct this. How long runs the daemon before it occurs?

[snarkbe]

It depends. There is no clear run time before it fails. Sometimes after a few days, sometimes after a few occurences.

[snarkbe]

It failed again :

Jun 18 07:30:19 pihole gclog[968]: [DEBUG] Entering main loop...
Jun 18 07:31:19 pihole gclog[968]: CPM: 28 (= 1697/61), Timestamp: Tue Jun 18 05:30:19 2019
...
Jun 21 02:13:46 pihole gclog[968]: CPM: 26 (= 1550/60), Timestamp: Fri Jun 21 00:12:46 2019
Jun 21 02:14:47 pihole gclog[968]: CPM: 25 (= 1519/60), Timestamp: Fri Jun 21 00:13:47 2019
Jun 21 02:15:47 pihole gclog[968]: CPM: 2035 (= 118005/58), Timestamp: Fri Jun 21 00:14:47 2019
Jun 21 02:16:47 pihole gclog[968]: CPM: 7129 (= 420608/59), Timestamp: Fri Jun 21 00:15:47 2019
....

[stelas]

Improved the awkward type conversion in gqgeiger cpm function. It's running here for a few days. Can you try commit 41a8771?

[snarkbe]

Thanks! Latest version compiled and running.

I removed also the cronjob that restarted gclog every night at 3:00. Note it would not prevent always the wrong readings. Sometimes it would fail after just a couple hours running.

I'll let you know about this version.

[snarkbe]

the process stopped logging after some time. No more entries in journalctl:

Jul 08 00:12:37 pihole gclog[22765]: CPM: 33 (= 1975/60), Timestamp: Sun Jul  7 22:11:37 2019
Jul 08 00:13:37 pihole gclog[22765]: CPM: 30 (= 1797/59), Timestamp: Sun Jul  7 22:12:37 2019

The process is however still running:

pi@pihole:~ $ ps -ef | grep gclog
root     22765     1  0 Jul05 ?        00:00:37 /usr/bin/gclog -v -c /etc/gclog.conf

I cannot stop the process with killall. I had to use a kill -9

[theY4Kman]

I finally dug into the abrupt logging cessation today — I was luckily able to catch it hanging just a few seconds after starting. It turned out to be hanging during the recv for a radmon upload. Since the pause is during a blocking syscall, I guess it won't process the SIGTERM, and it just waits forever. Gotta kill -9, and your process is mine.

I patched it in my fork by adding send/receive timeouts to the socket (configurable with the upload_timeout setting, defaulting to 1 second), and by performing uploads in a background thread: theY4Kman@38659c1

---

Update: it's been pretty stable since making that change