The issue may have been running your pb66 branch rather than rsync_mods but with rsync turned on… will confirm shortly assuming logs stay in place.
I forked the repo before that code was added and I’m not planning on adding it just yet as I’m not confident about it’s implementation.
Have you checked your logs? ie syslog and/or daemon log as well as the L2R log. I think logrotate currently just gets output to syslog? (something else I might look to change for debugging purposes).
I don’t think it’s easy to compare notes when we are all running different things.
I’m running 2 setups currently, an Oct 18 emonSD converted to L2R (pb66/log2ram/rsync_mods rsync mode) and a basic Rasbian image with various bits and bobs but no emon stuff installed, that’s got L2R (pb66/log2ram/pb66 - cp mode) and neither have wiped the logs, as far as I’m aware.
Do yours comeback after a while? Is the folder structure retained? Do any softwares continue to create/add logs?
thanks @pb66, I think the problem is solved using your rsync_mods branch plus a reinstall, looking good so far
1 Like
so I now have on test:
- rsync_mods branch of log2ram
- emonhub with own logfile
- removed rsyslog.conf daemon modification
- logrotate all defaults (no specific emonhub log rotate, assuming 5mb internal rotation will work)
- logrotate run daily
This is the file, when written to /etc/rsyslog.d/10-emonhub.conf will catch emonhub log messages written to journald by the service logging and forwarded on to rsyslog (the default setup).
template(name="EmonhubMsg" type="string" string="%msg:::drop-last-lf%\n")
if ( $programname == "emonhub" or $programname == "emonhub.py" ) then {
action(type="omfile" file="/var/log/emonhub.log" template="EmonhubMsg")
stop
}
It should work without any modification to the service file (but the service file should not specify a log path).
sudo systemctl restart rsyslog.service
to start it.
[edit] This link was really useful in understanding the rsyslog script.
1 Like
I reminded Trysrtan of that only just yesterday, my memory might be bad but not that bad!
You are not talking about redirecting per se, you are talking about systemd routing the logfile. I am talking about redirection of stdout and errout as part of the command/script so as to avoid systemd/journald getting involved at all, just like the emonhub setup (with --logfile in the unit) and emoncms. Going back to how the logfiles were generated before everything migrated to systemd.
For example with a shell script you could add
exec 2>&1 1>/var/log/scriptname.log
just under the shebang, or alternatively for a python script
import sys
sys.stdout = open('/var/log/scriptname.log', 'a')
this will put stdout to a logfile directly and doesn’t need the missing systemd directive, plus it doesn’t just leave stdout to be mopped up by journald etc. Although I haven’t tested it, just clarifying what I meant ie NOT using unavailable functions, just common redirection.
I see no reason installing L2R would be problematic, all images have /var/log in tmpfs and if they are a RO OS we can just addsymlinks so the files actually end up in /data (RW partition rather than rootfs)
I think your getting confused there, the rotations are never in RAM with L2R+ (with my olddir mods). The only time you might need additional space in ram to perform the rotations would be if you are using copytruncate which I think we agreed was a bad idea. Avoiding using valuable RAM for rotated logs is precisely why I did the olddir mod to L2R.
I’m sure this is a misunderstanding too, the "Rather than “pulling out” I would favour “not putting in”, comment was aimed squarely at the systemd units that are just letting stdout go to syslog etc emoncms doesn’t use systemd, it’s not a service. I’m referring to service-runner and emoncms-mqtt etc (feedwriter logs direct to emoncms.log now doesn’t it?)
[edit] With regard to logs for emoncms services such as service-runner and emoncms-mqtt, can we please clarify what it is we want? IMO the way the init scripts used to work was spot on. The service start, stops and errors went to journald and the scripts general running logs went to script.log, this was great for debugging and it was consistent with everything else from emonhub and emoncms through to apache2, mosquitto, redis, mysql etc etc etc. Now it seems that we are trying to force all the data together into journald and then possibly filter it out again??? I hope I’m wrong as that seems really bizzare. Plus it is really confusing things.
I feel the move to use emonlogger was right and it IS consistent, what else doesn’t bother managing it’s own log files and expects systemd to do it? I’ve been arguing against emonhub doing that since it was changed to systemd and adding the --logfile arg back in resolves that, AFAIA that only leaves service-runner and maybe emoncms-mqtt that are “inconsistent” and not logging to a logfile directly?
There are comments made like agreeing that these services should have their logs in the /var/log/emoncms folder which make me think we’re on the same page and then there are comments about custom scripts to pull out the logs from the journal that confuse things again, why put them in to the one pot if you have to separate them again? Just don’t put them in! Plus even if we do separate them again, will it not bring the service start/stop/error messages that DO belong in journald out with them, no?
Yes I realised that and I’m suggesting that is a better to use the OS logging mechanisms. The redirection of output was removed with systemd, presumably for good reason. However I can see some benefit of creating your own, but I would prefer the rotation to be done outside of the script.
Yes and no. Will this keep all the emonhub logs you feel are necessary? As I write this I realise that the sort of concatenating I am doing could be done out of olddir with a postrotate command so yes your original suggestion works.
Ah, now that is an interesting differentiation. I wondered if my catch script for rsyslog would pick up the start stop but it does. (warning log is in reverse) - you can see the normal logging and then the entries when I restart the service.
Apr 24 18:36:46 emonpi emonhub.py[3916]: 2019-04-24 18:36:46,573 INFO MainThread Setting RFM2Pi group: 210 (210g)
Apr 24 18:36:45 emonpi emonhub.py[3916]: 2019-04-24 18:36:45,571 INFO MainThread Setting RFM2Pi frequency: 433 (4b)
Apr 24 18:36:45 emonpi emonhub.py[3916]: 2019-04-24 18:36:45,570 INFO MainThread RFM2Pi device firmware version & configuration: not available
Apr 24 18:36:43 emonpi emonhub.py[3916]: 2019-04-24 18:36:43,563 DEBUG MainThread Opening serial port: /dev/ttyAMA0 @ 38400 bits/s
Apr 24 18:36:43 emonpi emonhub.py[3916]: 2019-04-24 18:36:43,561 INFO MainThread Creating EmonHubJeeInterfacer 'RFM2Pi'
Apr 24 18:36:43 emonpi emonhub.py[3916]: 2019-04-24 18:36:43,560 INFO MainThread Logging level set to DEBUG
Apr 24 18:36:43 emonpi emonhub.py[3916]: 2019-04-24 18:36:43,560 INFO MainThread Opening hub...
Apr 24 18:36:43 emonpi emonhub.py[3916]: 2019-04-24 18:36:43,559 INFO MainThread EmonHub emonHub emon-pi variant v2.1.2
Apr 24 18:36:40 emonpi systemd[1]: Started emonHub service description.
Apr 24 18:36:40 emonpi systemd[1]: Stopped emonHub service description.
Apr 24 18:36:40 emonpi systemd[1]: Stopping emonHub service description...
Apr 24 18:36:37 emonpi emonhub.py[530]: 2019-04-24 18:36:37,051 INFO MQTT Publishing: emonhub/rx/5/values 79,0,79,236.73,0,0,0,0,0,0,0
Apr 24 18:36:37 emonpi emonhub.py[530]: 2019-04-24 18:36:37,049 DEBUG MQTT Publishing: emon/emonpi/pulsecount 0
Apr 24 18:36:37 emonpi emonhub.py[530]: 2019-04-24 18:36:37,047 DEBUG MQTT Publishing: emon/emonpi/t6 0
What happens if you restart the emonhub service? Where do those messages end up? In the Emonhub.log or output to journald?
I can see the logic of splitting the logging like that. Perhaps, if the running log messages went to stdout, and we could pick up all the other status & error from the various services into a specific emon-error.log?
I modified emoncms_mqtt to use the emoncms logger same as for feedwriter. For service-runner there is a logfile for each script that service runner runs, the log file is specified usually in the part of emoncms that sends the command to service-runner. I envisage changing the location of these logs to /var/log/emoncms/ e.g /var/log/emoncms/sync.log & /var/log/emoncms/update.log (instead of
/home/pi/data/emoncms-sync.log) - these logs dont touch the systemd logging system.
As for service-runner that is currently using systemd as far as Im aware, with logs of the form (Im open to a different configuration here):
pi@emonpi:/var/log $ journalctl -f -u service-runner
-- Logs begin at Wed 2019-04-24 18:17:23 BST. --
Apr 24 18:17:37 emonpi systemd[1]: Started Emoncms service-runner Input Script.
Apr 24 18:17:38 emonpi service-runner[649]: Starting service-runner
Apr 24 18:17:38 emonpi service-runner[649]: Connected to redis-server
Apr 24 19:13:42 emonpi service-runner[649]: Got flag: /opt/emon/modules/sync/emoncms-sync.sh>/opt/emon/data/emoncms-sync.log
Apr 24 19:13:42 emonpi service-runner[649]: STARTING: /opt/emon/modules/sync/emoncms-sync.sh > /opt/emon/data/emoncms-sync.log 2>&1
Apr 24 19:13:42 emonpi sudo[1692]: pi : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/php /opt/emon/modules/sync/sync_run.php
Apr 24 19:13:42 emonpi sudo[1692]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 24 19:13:44 emonpi sudo[1692]: pam_unix(sudo:session): session closed for user root
Apr 24 19:13:44 emonpi service-runner[649]: COMPLETE: /opt/emon/modules/sync/emoncms-sync.sh > /opt/emon/data/emoncms-sync.log 2>&1
Great, so service-runner is the only odd ball!
Which I think is not right, it certainly is not consistent, I get the scripts actioned BY service-runner will have (and should have) their logfiles defined in the command, but I do not think the connection and step by step confirmations of service-runner operation should be in journald (that should just be start/stop/error of the service unit not the service-runner operations) that should go to another log, either to emoncms.log (as per emoncms-mqtt and feedwriter) or it’s own /var/log/emoncms/service-runner.log. either way, it should not (IMO) just be left to stdout so that journald gets it (and we then filter it out again?)
Fantastic!
They have always gone to the system log, that’s why when we do debugging we ask for (for example) emonhub.log AND a sudo systemctl status emonhub, the latter tells us if it’s running etc, but it also gives us the last few entries of the journald to show when it was restarted or last stopped etc etc, this data will be lost in the depth of the emonhub.log or rotated out very fast if put with the general emonhub logs (either in journald or in emonhub.log).
This sounds like additional writes, when ever existing logs are concatenated with newer logs it is going to add to the writes, I like the aim to be tidier, but I do not think it is feasible, it’s complex and it’s costly, but either way, it would be done post rotation so it doesn’t change anything for the actual rotation, it can be added/removed at a later date.
I don’t know what you are asking there, the logrotation count will define how many logs are kept.
also what are you left with once you remove the timestamp, service and pId info from the service stop/start lines (assuming you are still doing that)?
2019-04-24 18:36:43,559 INFO MainThread EmonHub emonHub emon-pi variant v2.1.2
Started emonHub service description.
Stopped emonHub service description.
Stopping emonHub service description...
2019-04-24 18:36:37,051 INFO MQTT Publishing: emonhub/rx/5/values 79,0,79,236.73,0,0,0,0,0,0,0
2019-04-24 18:36:37,049 DEBUG MQTT Publishing: emon/emonpi/pulsecount 0
Where should it log to? If it should log to emonCMS’s log file, how does it determine which instance of emonCMS’s logs it should write to if there are more than one? If you’re going to standardise on a single /var/log/emoncms/ logging folder across installations/distributions etc. then it would certainly make sense for it to log its activity there into its own file.
It would probably be a simple matter to just add a --logfile option to the service-runner python script and write to that instead of stdout if it was provided. Then the log location could be supplied in the service unit file in the ExecStart directive as has been discussed previously.
2 Likes
I can see emonhub rotating its own log and agree that it would be best to do this with logrotate as we can then control the other aspects such as compression and move of rotated logs to @pb66’s log2ram rotated_logs folder
That is different things (I think). Either you let emonhub rotate the logs itself (embedded code in python script) or you let logrotate do it or logrotate, rotates the log rotated by the script 
.
Of course we are talking about the standard setup. Can be setup differently by the user.
Yes it is but gives a fuller picture over a period of time which could be useful but all the graphs above were doing this and it did not seem excessive over the L2R writes. We could try it and see. The tradeoff may be worthwhile. For me personally, emoncms is on a VM so I’m more interested in logs I can review, than disk writes (and that may be something to consider in the install scripts).
You have mentioned before about the usefulness of the emonhub logs in debugging. The question is, what is the minimum requirement (in terms of time).
Ok so that can continue (with a little config to pull out just our services log entries rather than having to wade through the syslog or daemon.log). Trouble with doing it via journald is that this information is not persistent and rotates out quickly so it would be good to pull that information out so we can persist it in one place.
That is what has happened here - this is a rsyslog extracted log file of just the emonhub message part. If we were extracting the system messages, I’d suggest pulling them out verbatim.
Thanks @borpin
I think it makes sense for logrotate to do it and for us to remove the inbuilt emonhub logrotation code.
1 Like
Of perhaps make it an option so it is backward compatible, but on new systems off by default.
Of course! I had over looked the multi-instance aspect, thanks @Greebo. I agree it’s own log in /var/log/emoncms would be ideal. Even if we did log service-runners messages to each respective emoncms, there would still be some instance neutral messages like handling the redis connection, so separate is the way to go I think. And just for the record, I wasn’t criticising service-runner, just highlighting service-runner wasn’t the same as the others (since the others have changed) and trying to determine what was actually wanted/needed. If service-runner needs to be different that’s great, it just shouldn’t be the template for consistency if it is in fact the “odd ball”.
Excellent, I didn’t labour the point yesterday as I was sure you would think that way once you had seen the rotation happen. The emonhub rotation is great as a safety net, but the files (IMO) are a bit large and emonhub only keep’s the 2 files in play so the history can be short despite the large files. Plus when emonhub rotates, that is a 5M chunk of ram lost until the next L2R+logrotation.
I think the emonhub logrotation config should rotate sooner (at 2 or 3M) and keep more than just 2 files, it will make handling the files easier and cover a longer period. length of retention has been debatewd a couple of times, this is a small detail that can be decided once we are fully up and running, I think it is a trivial decission, there is no point keeping just a couple of files and I don’t think anyone expects over a month under any circumstance, so the window isn’t that great and debating between 1 week or 2 will not effect the way it works or the size in ram or the write rate with any significance, the existing logs are just renamed (incremented +1) so usefulness vs size on disk are the only real factors.
Just in case emonhub does perform a rotation, the emonhub logrotation conf should also have a pre-rotation script to check and cater for the extra emonhub.log file in ram as part of the overall rotation if possible rather than a double rotation. But this should rarely if ever be called upon if the overall logrotation is effective.
hopefully i’ve explained this well enough above. There is no need to remove it from emonhub source. It is still a great safety net.
1 Like
ok great, happy with keeping it in as a safety net, does the size need to be increased >5MB, will logrotate catch it in time? will we otherwise need monit?
what should the logrotate.d config look like?
/var/log/emonhub/emonhub.log {
rotate 5
size 2M
missingok
copytruncate
notifempty
compress
}
Looking at the system service log entries, To pull them into a single log file all that is needed is a series of files in /etc/rsyslog.d named e.g. 10-rsyslog-emonhub.conf of the form
if ( $programname == "emonhub" or $programname == "emonhub.py" ) then {
action(type="omfile" file="/var/log/emoncms/emon-services.log")
stop
}
where the progname need to be correctly identified.
Each configuration file can be installed with the service as it is installed.
Assuming all normal output is going to a specific log entry, this should only capture the other system messages.