So what loglevel are you using? it should be DEBUG for debugging or WARNING for a less verbose output, INFO never really got off the ground. IMO those example lines you gave us should be DEBUG not INFO as they are only good for in-depth debugging, connecting to the broker or subscribing to a topic is INFO, but printing every value of every publish, is DEBUG IMO. But INFO just hasn’t really been utilised much, in practice there are essentially 2 levels, DEBUG = verbose and WARNING = quiet.
Ok, therefore as we know emonhub is publishing, that would suggest the serial data is being passed via MQTT to the Mosquitto broker so that bits ok. (you can check that by setting the emonhub log level to DEBUG)
If you have other inputs functioning ok then feedwriter and core emoncms parts are apparently ok.
I would say the issue lays with the MQTT input to emoncms. It failed when the log was full as it couldn’t place it’s log messages, plus it’s possibly the only service you haven’t restarted. It was this I had in mind when I mentioned duplicated inputs, but the charateristics of the mqtt input crashing due to a full log, may differ to what we have previously seen.
there is information to be found, it’s just that the changes from init.d to systemd, mqtt_input to emoncms_mqtt, the move to emoncms.log for the mqtt, feedwriter and service-runner etc etc all happening at different times but in rapid succession really doesn’t help us know what you might have and where to find stuff. Plus, at the very core of your issue is the fact the logging stopped, that alone may explain the absence of some logs, eg the emoncms mqtt input.
There is no emoncms_input service.
mqtt_input is running. I just restarted it in case. No difference - no wait, I spoke too soon. Everything’s updating now.
If you have the emoncms/config module installed (by default on emonSD) you can check the “emonhub” page, it’s near the top of the emonhub.conf.
Alternatively (I think) it’s also found at /home/pi/data/emonhub.conf and/or /etc/emonhub/emonhub.conf, the latter is the generic location for it, the former is where it was put due to the RO OS (which the latest image isn’t). It should have been symlinked so that the generic path was still valid, but I don’t think that was necessarily the case.
That is pretty much the case for all the OEM services (except pre-systemd emonhub)
Yeah! That’s 'bout the size of it, the issue is there is no room for new log messages, so it cannot leave that error message (even if it existed in code). The issue is that the services are not robust enough to manage that situation. emonhub (with it’s own log) is the exception to that rule, I have tested this thoroughly and emonhub doesn’t fail due to a full /var/log (or at least if it has it’s own direct log it doesn’t).
The content of your /var/log folder raises another question over logrotation. If the emonSD logrotation was in play, those .2.gz, .3.gz and .4.gz files wouldn’t be there. So I assume you’re on a daily “standard” logrotation. I do not recommend updating at the moment as you will not only pull in the emonhub service changes, but you will most likely lose the logrotation altogether as the “hourly fix” doesn’t seem to work at all! can you please post the output of the following
ls -la /etc/logrotate.conf
cat /etc/logrotate.conf
cat /etc/cron.{daily,hourly}/logrotate
and
ls -la /var/log/logrotate
ls -la /var/lib/logrotate/status
cat /var/lib/logrotate/status
Thanks. I’d forgotten that page was there. So the answer was INFO. I think I might hack those warnings about old data to be INFO and then turn the logging level down.
Yes, the latter. It continues running after the log space becomes available again so it could log a warning at that point. But then if it recognized that situation, it should also be smart enough to fix whatever actually broke and stopped it working!
It occurred to me that it might not be mqtt_input that really has a problem. It might be mosquitto that is broken, plus the combination being dumb enough to not spot that the input was disconnected when I restarted mosquitto and not reconnect. Either way, it’s pretty obvious there’s some poor logic in there somewhere.
I don’t think I’ve adjusted log rotation at all.
$ ls -la /etc/logrotate.conf
-rw-r--r-- 1 root root 599 May 5 2015 /etc/logrotate.conf
$ cat /etc/logrotate.conf
# see "man logrotate" for details
# rotate log files weekly
weekly
# keep 4 weeks worth of backlogs
rotate 4
# create new (empty) log files after rotating old ones
create
# uncomment this if you want your log files compressed
#compress
# packages drop log rotation information into this directory
include /etc/logrotate.d
# no packages own wtmp, or btmp -- we'll rotate them here
/var/log/wtmp {
missingok
monthly
create 0664 root utmp
rotate 1
}
/var/log/btmp {
missingok
monthly
create 0660 root utmp
rotate 1
}
# system-specific logs may be configured here
$ cat /etc/cron.{daily,hourly}/logrotate
#!/bin/sh
test -x /usr/sbin/logrotate || exit 0
/usr/sbin/logrotate /etc/logrotate.conf
cat: /etc/cron.hourly/logrotate: No such file or directory
I think you’ve got some crossed wires there. The config on the emonhub page is purely for emonhub. Those “old data” messages you refer to are from emoncms not emonhub and that loglevel is set in emoncms/settings.php and not accesible via the emoncms gui.
I’m pretty confident it is, we’ve had issues before, we also saw that the broker was ok as emonhub was able to publish to it, so the issue lay inbetween the working broker and the emoncms inputs, of which, the http ones were updating ok.
That’s good to hear, thanks for sharing that. I’m trying to get a handle on what it and isn’t going on with the emonSD without a valid build guide and it’s a very fluid moving target as the updates and updater are frequently changing.
From your outputs
You are using the original package installed logrotate.conf (dated 2015), this and some other observations confirms what I suspected, that the whole logrotation modification was missed on the oct 2018 image.
So this means you are getting daily checks and weekly rotations not based on size unless overriidden by a package specific conf in /etc/logrotate.d/
although there may not be a /var/log/logrotate/logrotate.status file, the logrotate folder is there in your /var/log printout above, it’s ownership is pi:pi, that tells me it was (most probably) created by /etc/rc.local.
I’ve just been looking at what the logrotation needs for a interim fix and this info is useful, thanks.
Hopefully that won’t always be the case, but either way, I can let you know what I find and recommend with logrotate so you can decide whether to manual adjust or update.
There are certainly similarities (i.e. logs filling up and stopping the system) but it doesn’t seem to be the same situation as me (different logs, different services etc)
You’re right that I hadn’t realized/remembered they were two different logs. It seems par for the course that the emoncms webUI would provide screen editing for an alien log (emonhub) but not for its own log
emoncms.log is set to WARN level, so I’ve hacked PHPTimeSeries.php to make those messages INFO instead of WARN. I suppose I need to restart that somehow for it to take effect? Also, emoncms.log doesn’t seem to get rotated. Where is that done? (possibly a multi-valued answer )
You’re quite right. Apologies for my mis-statement.
Mmmmmh! That’s odd, but I guess nothing surprises me much these days.
Where did you do the editing, just to confirm we’re on the same page?
I wasn’t aware of any php caching (server side), I have not needed to restart following code edits before now (aside from browser refresh, which shouldn’t apply here). You could try a sudo systemctl reload apache2, that will do a “graceful restart” which IIRC isn’t actually a restart, it just reloads everything, but AFAIA apache2 doesn’t cache and php caching isn’t installed (but php is not my strong point), perhaps there’s just a shared copy of a included script lingering in ram?
// 2019-05-16 djh Changed 'warn' to 'info' to stop nuisance logging of DataPoint uploads
$this->log->info("post_bulk_prepare() data in past, nothing saved. feedid=$feedid timestamp=$timestamp last=".$lastvalue_static_cache[$feedid]['time']." value=$value");
It does a graceful restart every morning as part of the logrotate. Graceful just means that apache allows its threads to run to completion (i.e. finish servicing a request) before terminating and restarting them. It rereads its configuration as well. So it’s a method of completely restarting but with no visible effects on clients.
May 18 06:25:03 emonpi systemd[1]: Reloading The Apache HTTP Server.
May 18 06:25:03 emonpi apachectl[20841]: AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 127.0.1.
May 18 06:25:03 emonpi systemd[1]: Reloaded The Apache HTTP Server.
Sadly the WARNings are still being logged. I’m out of my depth on PHP as well.
2019-05-18 11:01:35.817|WARN|PHPTimeSeries.php|post_bulk_prepare() data in past, nothing saved. feedid=50 timestamp=1558166400 last=1558170000 value=1
2019-05-18 11:01:35.818|WARN|PHPTimeSeries.php|post_bulk_prepare() data in past, nothing saved. feedid=50 timestamp=1558170000 last=1558170000 value=1
I reread this thread and had just been looking at the apache log and realized as I reread my explanation about graceful restarts that apache wouldn’t actually restart until all the threads finalised their requests. But emoncms keeps active requests with continual log entries showing it updating lists etc. So I shut down the browser window (on my openSUSE PC, note) that was displaying emoncms pages.
And lo and behold the WARN messages on the emonpi stopped!
So, obvious with hindsight, in order to unload PHP you need to stop accessing the web pages it is serving. Or I suppose a hard reset of apache would do the job.
)
Entirely by luck.