emonSD next steps: emonhub logging

[borpin (Brian Orpin)]

Continuing the discussion from emonSD next steps: log2ram:

So going back to your point @pb66 about a dedicated emonhub log, it is remarkably simple to do.

In the service file add (under [service])

SyslogIdentifier=emonhub
SyslogFacility=local2

modify the /etc/rsyslog.conf so that local2 is logged to an emonhub.log file and not logged to syslog (it is already in the journal).

local2.*                        /var/log/emonhub.log
*.*;auth,authpriv.none,daemon.none,local2.none          -/var/log/syslog

[edit] and the following also amended to include a local2.none else the messages log fills with emonhub log entries;

*.=info;*.=notice;*.=warn;\
        auth,authpriv.none;\
        cron,daemon.none;\
        mail,news.none,local2.none      -/var/log/messages

How were these files being managed before?

[edit]You could actually remove the daemon.none directive so service logging does go to the daemon.log file but I don’t actually think that is a good idea.

[pb66 (Paul)]

From my perspective you’re missing 2 vital points, one is that I’m not interested in “fiddling” here there and everywhere, previously, it just worked!!! and secondly, The main reason I’m opposed to the changes made to emonhub inid.d and log is that it was dependable (not broken, didn’t need fixing) and robust, and known to be so. I’m not interested in adapting the hastily made changes to “look like” the old dependable emonhub.log. I want it to be known to be reliable, that is, I do not want systemd and/or journalctl interfering with a simple Python script writing it’s own logfiles directly to /var/log.

I would rather put emonhub back to how it was using the init.d script than make the changes you suggest, it’s probably not much work and that way I know what I’m getting and I know it’s been solid for the last 5years.

Just to reiterate, I don’t use emonSD, my emonhub uses init.d and writes it’s log directly to /var/log. That’s how it will remain for now, I have no reason or desire to change it. What I will say though, is the changes made to emonhub logging on the emonSD make me less likely to use the emonSD image and possibly less likely to offer assistance here on the forum if I have no confidence in what I suspect or say, I simply won’t say it.

[borpin (Brian Orpin)]

@pb66

What I will say though, is the changes made to emonhub logging on the emonSD make me less likely to use the emonSD image and possibly less likely to offer assistance here on the forum if I have no confidence in what I suspect or say, I simply won’t say it.

Fair enough. Just thought you might be interested in restoring the reliable logging and I think that is probably in touching distance. Actually I’d suggest improving it so there could be say 7 days of logs to help with issues not noticed immediately but hey ho.

[pb66 (Paul)]

@borpin

Just thought you might be interested in restoring the reliable logging

But is it reliable? I guess we would find out over the coming months and years (as opposed to being absolutely sure right now).

@borpin

Actually I’d suggest improving it so there could be say 7 days of logs to help with issues not noticed immediately but hey ho.

Old init’d emonhub logging to L2R with olddir set will keep the past 4 weeks data automatically (using default logrotate.conf) and just the last 5-10mb is kept in /var/log for easy access. (providing you are not creating more than 10M per day in new emonhub.logs)

[edit - just checked one of my emonhub installs and have over 10 days worth in just the 2x <5mb files, the biggest enemy of historic log data in emonSD is the lack of retention across boots and the hourly 1M rotations, both can be resolved by L2R]

[borpin (Brian Orpin)]

Hi @pb66, I’ve been running a journald to syslog log of emonhub messages today but the logs are growing really quickly - is this normal? This is just a basic EmonPi setup.

First entry

Apr 19 13:30:46 emonpi emonhub[1646]: 2019-04-19 13:30:46,998

Last entry of a file 20Mb in size

Apr 19 21:07:09 emonpi emonhub[1646]: 2019-04-19 21:07:09,030

168663 lines of emonhub logs. A sample (I’ll upload more if it helps)

Apr 19 21:06:58 emonpi emonhub[1646]: 2019-04-19 21:06:58,967 DEBUG    emoncmsorg Buffer size: 10
Apr 19 21:07:01 emonpi emonhub[1646]: 2019-04-19 21:07:01,118 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 2 84 64 127 8 242 138 20 143 200 32 52 40 16 40 2 96 205 156 217 109 (-91)
Apr 19 21:07:01 emonpi emonhub[1646]: 2019-04-19 21:07:01,327 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 1 213 16 127 8 242 138 20 143 200 32 52 40 16 40 2 96 205 156 217 109 (-91)
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,196 DEBUG    RFM2Pi     9599 NEW FRAME : OK 5 68 0 0 0 68 0 98 92 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 (-0)
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,200 DEBUG    RFM2Pi     9599 Timestamp : 1555708023.2
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,200 DEBUG    RFM2Pi     9599 From Node : 5
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,201 DEBUG    RFM2Pi     9599    Values : [68, 0, 68, 236.5, 0, 0, 0, 0, 0, 0, 0]
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,202 DEBUG    RFM2Pi     9599 Sent to channel(start)' : ToEmonCMS
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,202 DEBUG    RFM2Pi     9599 Sent to channel(end)' : ToEmonCMS
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,391 DEBUG    MQTT       Publishing: emon/emonpi/power1 68
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,393 DEBUG    MQTT       Publishing: emon/emonpi/power2 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,395 DEBUG    MQTT       Publishing: emon/emonpi/power1pluspower2 68
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,397 DEBUG    MQTT       Publishing: emon/emonpi/vrms 236.5
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,398 DEBUG    MQTT       Publishing: emon/emonpi/t1 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,400 DEBUG    MQTT       Publishing: emon/emonpi/t2 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,402 DEBUG    MQTT       Publishing: emon/emonpi/t3 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,404 DEBUG    MQTT       Publishing: emon/emonpi/t4 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,406 DEBUG    MQTT       Publishing: emon/emonpi/t5 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,408 DEBUG    MQTT       Publishing: emon/emonpi/t6 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,410 DEBUG    MQTT       Publishing: emon/emonpi/pulsecount 0
Apr 19 21:07:03 emonpi emonhub[1646]: 2019-04-19 21:07:03,412 INFO     MQTT       Publishing: emonhub/rx/5/values 68,0,68,236.5,0,0,0,0,0,0,0
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,364 DEBUG    RFM2Pi     9600 NEW FRAME : OK 10 107 2 0 0 0 0 0 0 72 96 121 2 60 2 147 1 181 2 14 2 135 1 162 0 231 0 0 0 (-58)
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,368 DEBUG    RFM2Pi     9600 Timestamp : 1555708027.36
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,369 DEBUG    RFM2Pi     9600 From Node : 10
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,369 DEBUG    RFM2Pi     9600    Values : [619, 0, 0, 0, 246.48000000000002, 63.300000000000004, 57.2, 40.300000000000004, 69.3, 52.6, 39.1, 162, 231, 0]
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,370 DEBUG    RFM2Pi     9600      RSSI : -58
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,371 DEBUG    RFM2Pi     9600 Sent to channel(start)' : ToEmonCMS
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,371 DEBUG    RFM2Pi     9600 Sent to channel(end)' : ToEmonCMS
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,558 DEBUG    MQTT       Publishing: emon/emontx1/power1 619
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,561 DEBUG    MQTT       Publishing: emon/emontx1/power2 0
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,562 DEBUG    MQTT       Publishing: emon/emontx1/power3 0
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,564 DEBUG    MQTT       Publishing: emon/emontx1/power4 0
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,566 DEBUG    MQTT       Publishing: emon/emontx1/vrms 246.48
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,568 DEBUG    MQTT       Publishing: emon/emontx1/temp1 63.3
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,570 DEBUG    MQTT       Publishing: emon/emontx1/temp2 57.2
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,572 DEBUG    MQTT       Publishing: emon/emontx1/temp3 40.3
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,574 DEBUG    MQTT       Publishing: emon/emontx1/temp4 69.3
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,576 DEBUG    MQTT       Publishing: emon/emontx1/temp5 52.6
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,581 DEBUG    MQTT       Publishing: emon/emontx1/temp6 39.1
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,583 DEBUG    MQTT       Publishing: emon/emontx1/pulse 162
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,586 DEBUG    MQTT       Publishing: emon/emontx1/13 231
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,588 DEBUG    MQTT       Publishing: emon/emontx1/14 0
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,590 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 15 207 60 208 23 44 97 198 38 20 34 3 156 236 34 156 168 4 158 200 96 (-99)
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,591 DEBUG    MQTT       Publishing: emon/emontx1/rssi -58
Apr 19 21:07:07 emonpi emonhub[1646]: 2019-04-19 21:07:07,593 INFO     MQTT       Publishing: emonhub/rx/10/values 619,0,0,0,246.48,63.3,57.2,40.3,69.3,52.6,39.1,162,231,0,-58
Apr 19 21:07:08 emonpi emonhub[1646]: 2019-04-19 21:07:08,204 DEBUG    RFM2Pi     9601 NEW FRAME : OK 5 83 0 0 0 83 0 46 92 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 (-0)
Apr 19 21:07:08 emonpi emonhub[1646]: 2019-04-19 21:07:08,208 DEBUG    RFM2Pi     9601 Timestamp : 1555708028.2
Apr 19 21:07:08 emonpi emonhub[1646]: 2019-04-19 21:07:08,208 DEBUG    RFM2Pi     9601 From Node : 5
Apr 19 21:07:08 emonpi emonhub[1646]: 2019-04-19 21:07:08,209 DEBUG    RFM2Pi     9601    Values : [83, 0, 83, 235.98000000000002, 0, 0, 0, 0, 0, 0, 0]
Apr 19 21:07:08 emonpi emonhub[1646]: 2019-04-19 21:07:08,210 DEBUG    RFM2Pi     9601 Sent to channel(start)' : ToEmonCMS
Apr 19 21:07:08 emonpi emonhub[1646]: 2019-04-19 21:07:08,210 DEBUG    RFM2Pi     9601 Sent to channel(end)' : ToEmonCMS

[pb66 (Paul)]

6 lines per second isn’t impossible for a high traffic install I guess. I all revolves around how many devices, how often, how many metrics as well as how many and what type of end points that data is going to and whether it posts successfully every time. And there’s the “discarded” rf noise too. So very much an unknown amount!

There are no unexpected lines or duplication to suggest anything “odd” is happening in the excerpt you show but that doesn’t necessarily mean the whole 168k lines are all good.

When the MQTT interfacer was added to the emonpi variant there was an large increase in log traffic due to the per value publishing, as you can see each emontx1 update creates 14 different topics, each on a different line. As a sidenote here, it appears your node definition is not correct for emontx1 hence the “13” and “14” topics as there are only 12 names available for the 14 values, might be the payload has changed or possibly the wrong datacodes are being used. Back on topic. I have no experience of running the emonpi variant so I’m not sure of the log traffic, if it is this high ordinarily (or even occasionally) then the emonSD image must accommodate it in some way. One of the benefits of seperate logs (as I pointed out when this was discussed years over the MQTT service) is that the true service log data doesn’t get pushed out by faster moving general logging. What I mean here is if you cap the size of the emonhub journald, more often that not, there will be zero log messages retained about the starting of the service because of the high traffic when it in use. With the seperate logs the service logs are retained even when the application logs get rotated frequently.

The size of the file overall is inflated by the fact journald is adding the time and date, hostname, service name and PID to the front of every line. The pid might be mildly useful, once, but overall all that info is useless and only needed BECAUSE it’s journald, when you put all your logging together in one file you need to be able to separate it again (just seems so daft!!).

The time data generated by systemd is not granular enough for debugging emonhub (yes I’m absolutely sure there’s another tweak to the other tweaks you can do to sort that!) and if you stop emonhub from adding the timestamp you are then dedicating emonhub to ONLY being used on systemd as it is dependent on it for the timestamps. Any logs generated without a timestamp are useless so emonhub then ceases to be able to run on other platforms. eg I do all my emonhub dev on a windows box.

The fact you have 20M suggests the in-built (to emonhub) rotation is getting sidestepped too as the maximum filesize would be 5M.

This is something that needs to be looked at as part of the L2R++ (++ being L2R plus logrotation and other improvements) strategy I guess (although again, I’m sure there are lots of little tweaks in journald so that you can set the total log size individually for each service but that really isn’t a road we should even consider!) to get the best arrangement.

As it stands the alternatives are you could simply change loglevel to error or warning to reduce the logging and reduce the size, but when you have an issue (eg debugging emontx1 payload?) you must do that debugging inside a day or your setup could choke! That is not a great approach if the act of debugging also brings on a crash situation! You could change emonhub to put out less log messages but that might hinder debugging too, the concept of the debug loglevel is to be as verbose as sensibly possible. Plus what ever measures you take to emonhub only effect emonhub, what happens when apache2 get a bee in it’s bonnet about something or there is a brute force attack on ssh (if/when enabled and exposed) or any other high log traffic event.

By the way why has the syslog not been rotated in over 7 hours? Has the emonpi logrotation been disabled again?

[borpin (Brian Orpin)]

@pb66

6 lines per second isn’t impossible for a high traffic install I guess.

This is an out of the box EmonPi with a CT although it is picking up the RF from my other setup which is what is causing the higher than standard logging.

@pb66

As a sidenote here, it appears your node definition is not correct for emontx1 hence the “13” and “14” topics

That is my existing setup that I modified the sketch to transmit 8 temperatures.

@pb66

The size of the file overall is inflated by the fact journald is adding the time and date, hostname, service name and PID to the front of every line.

Interesting.

@pb66

The fact you have 20M suggests the in-built (to emonhub) rotation is getting sidestepped too as the maximum filesize would be 5M.

@pb66

By the way why has the syslog not been rotated in over 7 hours? Has the emonpi logrotation been disabled again?

I’ve never seen the ‘inbuilt’ logrotate work yet (on a fresh install). Another thing to investigate.

[pb66 (Paul)]

@borpin

I’ve never seen the ‘inbuilt’ logrotate work yet

You won’t see emonhub inbuilt rotation work if it is not managing the log file, ie not via journald. And even pre-emonhub systemd changes, you would only see it if the emonpi hourly 1M rotation wasn’t working or you created 5M of logs in less than an hour.

No wonder it so difficult debugging on an emonpi, aside from losing all the logs at reboot, the emonhub logs are effectively capped to between 1 and 2 hours max when the logrotation IS working and the system grinds to a halt if logrotation isn’t working.

Another thought for L2R++ is to alter the forced rotation command to log it’s output to a temp log file outside of /var/log and copy it back to /var/log once there is space since when the partition is full, it is unlikely logrotation will automatically run (via cron) if it cannot write to syslog as I’ve said before.

In fact that is possibly why your files are not being rotated. Try a manual logrotation via the command line, it’s the “cron to syslog” part that is blocking it most likely.

No such problem with the emonhub in-built rotation because there is no dependence on (or interference from) other systems. It deletes the previous rotated file, rotates and soldiers on. If installed and setup as intended emonhub is actually the only service that cannot fill /var/log and can continue to function when something else like syslog fills the partition.

[borpin (Brian Orpin)]

@pb66

No such problem with the emonhub in-built rotation

Was this rotation part of the emonhub script?

I’m working on an alternative (to the current) setup that I’ll propose formally when I am done but for now;

• Setup emonhub.service to direct log entries to a specific SyslogFacility
• Use rsyslog configuration to write all emonhub log entries to /var/log/emonhub.log
• Use standard logrotate package with a /etc/logrotate.d/emonhub configuration file to manage log rotation of emonhub.log.
• Install monit and setup to monitor the size of the emonhub.log file by creating a /etc/monit/conf-enabled/emonhub-monitrc file. When monit detects that the file is over a certain size, it runs logrotate.

Waiting to see if this works first.

Next

• Use monit to monitor /var/log so if it gets over a certain size (any log file) it forces a rotate (catch all to keep things running).
• Move the rotated emonhub.log file to disk (as a post rotate task) and then rotate in that location.

The only standard file that needs to be edited will be the rsyslog file and that is because the instructions in it are sequential.

[edit]
I could do something similar for the emoncms.log and also setup a systemd service file to trigger before shutdown to save the logs.

[pb66 (Paul)]

@borpin

Was this rotation part of the emonhub script?

No it’s part of the core source code. It’s “in-built” it works on mac and windows too, out of the box.

[borpin (Brian Orpin)]

@pb66

No it’s part of the core source code.

Can you point me to where it is please?

Am I right in thinking all it needs is a path to the log file passed as an argument?

openenergymonitor/emonhub/blob/cb9da3c14babf8d7f0c2203450465b6e9111c99b/src/emonhub.py#L269-L269

[pb66 (Paul)]

@borpin

Am I right in thinking all it needs is a path to the log file passed as an argument?

Correct, this can be via a command-line at the shell prompt or in the case of the init.d service file, the paths are all defined in /etc/default/emonhub (emonhub/conf/default/emonhub at emon-pi · openenergymonitor/emonhub · GitHub).

[borpin (Brian Orpin)]

So far my overnight test has worked exactly how I wanted. The process I have set up does this;

1. emonhub.log is written to /var/log/
2. The emonhub.log file is monitored by monit and when it is over a specified size, monit calls logrotate (not a forced rotate, as the logrotate directives will cause it to do the rotation anyway).
3. Logrotate is configured to rotate the emonhub.log file at the same specified size as above.
4. A postrotate directive firstly moves the rotated file to the data folder on disk. The moved file is then concatenated with any existing emonhub.log file and deleted.
5. The emonhub.log file grows over a 24hr period.
6. On a daily basis, the emonhub.log file in the data folder is rotated and compressed by the daily run of logrotate.

Over a period of time, a number of days of logs for emonhub can be stored for debugging purposes.

Notes:

1. This setup is independednt of how the emonhub.log file is generated (in this case by modifying the behaviour of rsyslog).
2. This setup is independent of where /var/log/ is mounted and any other management of that folder.
3. monit is a standard apt package (really useful!).
4. This setup does not require any changes to the standard setup of logrotate or monit other than the addition of a configuration file for each.
5. The length of time logs are retained for can be set in terms of days.
6. Setting the size directive reasonably low will minimise data lost on a system crash / reboot, but there are other mechanisms that could mitigate that.
7. It could easily be replicated for other logs.

This has been a 36hr test so far. Needs to be left a bit longer. It was built by removing the emoncms changes to logrotate on a standard EmonSD card (plus modifications to the generation of the emonhub.log file).

Configuration files (currently).

File /etc/monit/conf-enabled/emonhub-monitrc

check file emonhub.log with path /var/log/emonhub.log
       if size > 2 MB then exec "/usr/sbin/logrotate -v /etc/logrotate.conf"

File /etc/logrotate.d/emonhub

/var/log/emonhub.log {
        rotate 6
        daily
        size 2M
        maxsize 2M
        missingok
#        create 640 pi pi
        copytruncate
        notifempty
        postrotate
             mv /var/log/emonhub.log.1 /home/pi/data/emonhub-log/
             cat /home/pi/data/emonhub-log/emonhub.log.1 >> /home/pi/data/emonhub-log/emonhub.log
             rm /home/pi/data/emonhub-log/emonhub.log.1
        endscript
}

/home/pi/data/emonhub-log/emonhub.log {
        rotate 10
        daily
        compress
        missingok
        notifempty
}

[Edit 2] Checking out this item re the use of CopyRotate rsyslog with logrotate: reload rsyslog vs copytruncate - Server Fault

[pb66 (Paul)]

@borpin

@pb66

The size of the file overall is inflated by the fact journald is adding the time and date, hostname, service name and PID to the front of every line.

Interesting.

Holy smoke! I just learnt that each and every single log message in the journald seems to be recorded with a huge amount of metadata (see https://www.linode.com/docs/quick-answers/linux/how-to-use-journalctl/#anatomy-of-a-log-record).

eg a simple (picked at random)

stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us

message is actually recorded as

Fri 2019-04-19 19:42:57.035333 BST [s=27f1a72bfc0640128b6b548b770b287f;i=b8dd;b=e237f2c284ce47cba5c6d45118aad902;m=1
    _TRANSPORT=syslog
    PRIORITY=6
    SYSLOG_FACILITY=3
    SYSLOG_IDENTIFIER=rngd
    SYSLOG_PID=357
    _PID=357
    _UID=0
    _GID=0
    _COMM=rngd
    _EXE=/usr/sbin/rngd
    _CMDLINE=/usr/sbin/rngd -r /dev/hwrng
    _CAP_EFFECTIVE=3fffffffff
    _SYSTEMD_CGROUP=/system.slice/rng-tools.service
    _SYSTEMD_UNIT=rng-tools.service
    _SYSTEMD_SLICE=system.slice
    _SYSTEMD_INVOCATION_ID=3d6f34de61464f22b9140fc2c9b6468e
    _BOOT_ID=e237f2c284ce47cba5c6d45118aad902
    _MACHINE_ID=404b0a8479864042be7cf1bb6f01a0c2
    _HOSTNAME=raspberrypi
    MESSAGE=stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
    _SOURCE_REALTIME_TIMESTAMP=1555699377035333

Whilst I have no reason to disbelieve what I read about journald using a very efficient binary file structure, I’m dubious as to whether that efficiency actually equates to a smaller overall footprint, this footprint is of more consequence when working in just 1G of RAM.

I came across this logging - Why are journald logfiles so huge? - Server Fault (the title stuck out like a sore thumb when I was searching) hopefully this isn’t as bad as it appears, but it does need consideration especially if we are persisting the logs. Even whilst held in RAM they could be using more space than a conventional text log file and then persisting the “journald” files might turn out to cause more writes than the “direct” approach due to the increased overall size.

[borpin (Brian Orpin)]

@pb66

I just learnt that each and every single log message in the journald seems to be recorded with a huge amount of metadata

Interesting.

@pb66

Whilst I have no reason to disbelieve what I read about journald using a very efficient binary file structure, I’m dubious as to whether that efficiency actually equates to a smaller overall footprint, this footprint is of more consequence when working in just 1G of RAM.

Yes but for non-persistent storage it simply rotates the old stuff out at a defined storage limit. So for me

pi@emonpi:~ $ journalctl
-- Logs begin at Mon 2019-04-22 12:26:13 BST, end at Mon 2019-04-22 15:07:12 BST. --

@pb66

Even whilst held in RAM they could be using more space than a conventional text log file and then persisting the “journald” files might turn out to cause more writes than the “direct” approach due to the increased overall size.

Which is why I think breaking out the emonhub messages with rsyslog and then rotating that log file is a better solution.

[TrystanLea]

In the service file for service-runner, I noticed:

# VIEW STATUS / LOG
# If Using Syslog:
# systemctl status service-runner -n50
# where -nX is the number of log lines to view
# journalctl -f -u service-runner
# Otherwise:
# Specify
#StandardOutput=file:/var/log/service-runner.log
# tail -f /var/log/service-runner.log

https://github.com/emoncms/emoncms/blob/master/scripts/services/service-runner/service-runner.service

StandardOutput=file:/var/log/service-runner.log

Is there any reason not to specify the log file location here instead? it would keep it separate from the rsyslog configuration?

[pb66 (Paul)]

@TrystanLea

Is there any reason not to specify the log file location here instead? it would keep it separate from the rsyslog configuration?

I think @Greebo might have said this directive is not fully operational in some distros’s

Symlinking services in Jessie doesn't work

Ok, that wasn’t my hunch! That’s the error I was getting when I used StandardOutput=file: and that was caused by the “file:” specifier only being available from systemd v236. Interestingly, the error says type but your post has Type - are you sure the service file is in Sentence case as you posted it? FWIW, the version release history of systemd can be found here: systemd/NEWS at main · systemd/systemd · GitHub

But can we not just use std redirection as part of the ExecStart= command?

EG emonhub already has a --logfile commandline option for this purpose so if the command in the service unit was

ExecStart=/usr/share/emonhub/emonhub.py --config-file=/home/pi/data/emonhub.conf --logfile=/var/log/emonhub/emonhub.log

instead of

ExecStart=/usr/share/emonhub/emonhub.py --config-file=/home/pi/data/emonhub.conf

normal logging would be resumed despite the move to a systemd unit.

[TrystanLea]

Id be happy with that if there is general agreement. After all the emoncms scripts handle their own logging to /var/log/emoncms.log

[Greebo]

@pb66 is correct. I think that comment in the service-runner unit file came from a different service-unit that I started with as my “template”. As I said in the quoted post, that unit file option is only available from systemd v236.
jessie includes v215, stretch includes v232, buster includes v241.
There is also v241 in the debian stretch-backports repo, but I’ve not been able to find a Raspbian version of that package for stretch.