EmonHub still dying?

Emoncms
21

Hi @pb66.
I believe I ran the last update (from the web gui) at Oct 19 04:06 UTC.

That log directory looks like:

total 11592
-rw-r--r-- 1 emonhub emonhub 5119924 Oct 25 17:16 emonhub.log.2
-rw-r--r-- 1 emonhub emonhub 5119878 Oct 25 17:31 emonhub.log.1
-rw-r--r-- 1 emonhub emonhub 1628949 Oct 25 17:31 emonhub.log

As you can see, this doesn’t go very far back in time. And oddly, those last two files have the same date and time. If I wait a minute or two, they both seem to have their mod time updated. If I tail them, it looks like they are both receiving content. Perhaps that’s something you expect, but it seems unusual to me. Here is the tail of those last two files:

pi@emonpi(ro):emonhub$ tail -n 10 emonhub.log.1 emonhub.log    
==> emonhub.log.1 <==
2017-10-25 17:36:21,307 DEBUG    emoncmsorg 144282 adding frame to buffer => [1508860343.774333, 7, 0, 0, 25, 372, 122.99000000000001, 300, 300, 300, 300, 300, 300, 1, -59]
2017-10-25 17:36:21,307 DEBUG    emoncmsorg 144283 adding frame to buffer => [1508860345.086839, 9, 0, 3, 9, 42, 123.13000000000001, 300, 300, 300, 300, 300, 300, 1, 0, -58]
2017-10-25 17:36:21,308 DEBUG    emoncmsorg 144284 adding frame to buffer => [1508860346.106141, 8, 706, 698, 69, 378, 121.97, 300, 300, 300, 300, 300, 300, 1, -37]
2017-10-25 17:36:21,308 DEBUG    emoncmsorg 144285 adding frame to buffer => [1508860347.328397, 10, 69, 367, 19, 0, 120.17, 22.700000000000003, 300, 300, 300, 300, 300, 1, -46]
2017-10-25 17:36:21,309 DEBUG    emoncmsorg 144286 adding frame to buffer => [1508860347.949284, 9, 1, 3, 10, 43, 123.23, 300, 300, 300, 300, 300, 300, 1, 0, -59]
2017-10-25 17:36:21,309 DEBUG    emoncmsorg 144287 adding frame to buffer => [1508860348.677803, 7, 0, 0, 25, 372, 122.88, 300, 300, 300, 300, 300, 300, 1, -57]
2017-10-25 17:36:21,310 DEBUG    emoncmsorg 144288 adding frame to buffer => [1508860348.788598, 26, 20, 19.200000000000003, 76.9, 2.7, 1, -70]
2017-10-25 17:36:21,310 DEBUG    emoncmsorg 144289 adding frame to buffer => [1508860348.949267, 8, 683, 682, 69, 378, 121.92, 300, 300, 300, 300, 300, 300, 1, -37]
2017-10-25 17:36:21,311 DEBUG    emoncmsorg 144290 adding frame to buffer => [1508860350.476834, 22, 20, 0, 59.1, 2.6, -57]
2017-10-25 17:36:21,311 DEBUG    emoncmsorg 144291 adding frame to buffer => [1508860350.89303, 9, 0, 3, 9, 44, 123.3, 300, 300, 300, 300, 300, 300, 1, 0, -57]

==> emonhub.log <==
2017-10-25 17:36:30,887 DEBUG    emoncmsorg 169117 adding frame to buffer => [1508883376.274161, 9, 0, 2, 9, 0, 122.56, 300, 300, 300, 300, 300, 300, 1, 0, -57]
2017-10-25 17:36:30,888 DEBUG    emoncmsorg 169118 adding frame to buffer => [1508883377.106166, 26, 20, 19.3, 77.80000000000001, 2.7, 1, -66]
2017-10-25 17:36:30,888 DEBUG    MQTT       Publishing: emon/TX07SubP/temp4 300
2017-10-25 17:36:30,888 DEBUG    emoncmsorg 169119 adding frame to buffer => [1508883377.621924, 8, 7, 5, 25, 362, 121.81, 300, 300, 300, 300, 300, 300, 1, -37]
2017-10-25 17:36:30,889 DEBUG    emoncmsorg 169120 adding frame to buffer => [1508883379.24569, 9, 1, 3, 9, 0, 122.98, 300, 300, 300, 300, 300, 300, 1, 0, -60]
2017-10-25 17:36:30,890 DEBUG    MQTT       Publishing: emon/TX07SubP/temp5 300
2017-10-25 17:36:30,890 DEBUG    emoncmsorg 169121 adding frame to buffer => [1508883379.662594, 10, 26, 354, 20, 32, 120.67, 19.5, 300, 300, 300, 300, 300, 1, -45]
2017-10-25 17:36:30,891 DEBUG    MQTT       Publishing: emon/TX07SubP/temp6 300
2017-10-25 17:36:30,892 DEBUG    emoncmsorg 169122 adding frame to buffer => [1508883380.382204, 7, 0, 0, 26, 355, 122.99000000000001, 300, 300, 300, 300, 300, 300, 1, -58]
2017-10-25 17:36:30,893 DEBUG    emoncmsorg 169123 adding frame to buffer => [1508883380.496704, 8, 7, 4, 25, 362, 121.92, 300, 300, 300, 300, 300, 300, 1, -37]
pi@emonpi(ro):emonhub$

I hope this helps.

I’ll try to promptly capture these logs if this reoccurs.

22

I will have to take a closer look at a later date, I don’t know the characteristics of the logrotate is configured and need to read up or do some tests. I would guess the same time and date is due to that being when the file was rotated out.

Of greater concern would be if more than one file was being written to. But looking at the file size it might be that emonhub is rotating the files out every few mins and that keeps the times recent and so it just looks like both file are being written to.

23

My experience with logrotate suggests that if one process had a file handle to the log file open when the rotate occurred, it ends up writing to the .1 file until it (eventually?) releases that open file handle and reconnects to the (new) log file. The newer log is updated because another thread or process opened the file after the rotate. – I’m not saying that’s what happened, but in my past experience, that’s typically the (rare) cause.

If it’s unexpected that two entities would be logging directly to the file like this, let me know what to look for to find those two.

J.

25

It happened again. The log pane is again black. I’ve included with this posting three attachments. The first contains a variety of observations and questions. The latter two are the non-empty log files.

I’ve not taken any corrective action (no restarts, no reboots), so I can look around further as you direct me to.

emonhub_problem_info.txt (18.9 KB)
emonhub.log.1.txt (4.6 MB)
emonhub.log.2.txt (4.9 MB)

I have one other comment to add here that was not in the log file. If it’s logging so rapidly and logrotate runs every 60 minutes and emonhub.log file is growing 25MB every minute, perhaps the disk did fill up, causing unrecoverable problems for emonhub and the subsequent logrotate (at 17min past the hour) removed a very large emonhub.log.2 file removing evidence that the /var/log disk filled up.

I hope this helps.

J.

26

Hello @jasonnet

Could you try updating emonhub, we commited a fix for the log file issue yesterday evening, see here for more detail: emonTxV3 stops and requires reboot (emonhub) - #23 by pb66

you can update emonhub to the latest version with a standard emonpi update

27

Yes, a very brief look at the logs confirms it is the same issue with runaway logging seen in the emonTxV3 stops and requires reboot thread. Please update as @TrystanLea suggests and

Even without logrotate, emonhub has inbuilt log file rotation at 5mb so a log file cannot grow much beyond 5mb x2, but with the current logrotate application settings allowing up to 3 files you could theoretically end up with up to 3x 5mb files if the rotates collide a certain way.

However it might be possible the data being buffered in ram could begin to choke the system if left long enough, the bugfix prevents data being buffered in the emoncmsorg senddata = 0 is set in emonhub.conf. so if the emoncmsorg interfacer isn’t being used or fully configured, senddata = 0 should be set so it doesn’t get bloated with unsent data.

28

10 posts were split to a new topic: Update EmonPi Button or Update EmonBase Button?