Startup & systemd - a personal view

I had got the impression that you were by some of your comments, although, no you didn’t specifically say that I guess. Most of my comment were obviously with this assumption in mind, but none the less, I still feel that tackling the root cause of the problems ie the current method of logging in ram, is a better approach than just altering the services that have starting issues due to said root cause.

Other logs (such as emoncms) will still be an issue, not only with starting, but also with persisting for better debugging and not losing everything at a reboot.

I’m not saying the log files shouldn’t be moved to journalctl if thats what is wanted, but it doesn’t tackle the root problem system wide so an addditional fix to the ram logging is still needed and that fix alone, would fix the systemd starting issues (and lose rc.local) so moving the logs to journalctl is not a system wide fix and it becomes unnecessary when a wider fix is applied, that doesn’t mean it shouldn’t be done, just that’s it’s not a priority, just a possible “nice to have” .

But they are not held in 2 places, only the services that have been tweaked to send thier logs to journalctl do so. By default mysql, apache2 and redis etc only have normal logging, heres an example from a stock Debian stretch install. The logs only exist in /var/log, what you suggest is not removing duplicates but simply relocating them.

pb66@test2:~$ journalctl -u mysql
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal' can see all messages.
      Pass -q to turn off this notice.
-- No entries --
pb66@test2:~$ journalctl -q -u redis
pb66@test2:~$ sudo ls -la /var/log/{mysql,redis}
/var/log/mysql:
total 36
drwxr-s---  2 mysql adm  4096 Mar 16 06:25 .
drwxr-xr-x 11 root  root 4096 Mar 16 06:25 ..
-rw-r-----  1 mysql adm     0 Mar 16 06:25 error.log
-rw-r-----  1 mysql adm    20 Mar 15 06:25 error.log.1.gz
-rw-r-----  1 mysql adm    20 Mar 14 06:25 error.log.2.gz
-rw-r-----  1 mysql adm    20 Mar 13 06:25 error.log.3.gz
-rw-r-----  1 mysql adm    20 Mar 12 06:25 error.log.4.gz
-rw-r-----  1 mysql adm    20 Mar 11 06:25 error.log.5.gz
-rw-r-----  1 mysql adm    20 Mar 10 06:25 error.log.6.gz
-rw-r-----  1 mysql adm    20 Mar  9 06:25 error.log.7.gz

/var/log/redis:
total 6100
drwxr-x---  2 redis redis    4096 Mar 10 06:25 .
drwxr-xr-x 11 root  root     4096 Mar 16 06:25 ..
-rw-rw----  1 redis redis 2817401 Mar 16 10:45 redis-server.log
-rw-rw----  1 redis redis  351060 Jan 14 06:24 redis-server.log.10.gz
-rw-rw----  1 redis redis  263921 Jan  6 06:24 redis-server.log.11.gz
-rw-rw----  1 redis redis  351542 Dec 31 06:24 redis-server.log.12.gz
-rw-rw----  1 redis redis  262797 Mar 10 06:24 redis-server.log.1.gz
-rw-rw----  1 redis redis  350019 Mar  4 06:24 redis-server.log.2.gz
-rw-rw----  1 redis redis  265519 Feb 24 06:24 redis-server.log.3.gz
-rw-rw----  1 redis redis  354475 Feb 18 06:24 redis-server.log.4.gz
-rw-rw----  1 redis redis   64552 Feb 10 06:24 redis-server.log.5.gz
-rw-rw----  1 redis redis  200074 Feb  8 19:29 redis-server.log.6.gz
-rw-rw----  1 redis redis  351475 Feb  4 06:24 redis-server.log.7.gz
-rw-rw----  1 redis redis  307853 Jan 27 06:24 redis-server.log.8.gz
-rw-rw----  1 redis redis  264428 Jan 20 06:24 redis-server.log.9.gz
pb66@test2:~$

Ah ok, I missread that then! you are right, my mistake :slight_smile:

I guess that does still leave us with the service restarts not being needed on stretch but needed on jessie

I don’t know what you’re looking at but using the correct services, they most certainly are recorded in the journal:

pi@emonpi:~ $ journalctl -u apache2.service 
-- Logs begin at Thu 2016-11-03 17:16:42 UTC, end at Sat 2019-03-16 12:19:02 UTC
Mar 16 09:23:30 emonpi systemd[1]: Starting The Apache HTTP Server...
Mar 16 09:23:31 emonpi apachectl[1042]: AH00558: apache2: Could not reliably det
Mar 16 09:23:31 emonpi systemd[1]: Started The Apache HTTP Server.
pi@emonpi:~ $ journalctl -u redis-server.service 
-- Logs begin at Thu 2016-11-03 17:16:42 UTC, end at Sat 2019-03-16 12:19:02 UTC
Mar 16 09:23:18 emonpi systemd[1]: Starting Advanced key-value store...
Mar 16 09:23:19 emonpi run-parts[500]: run-parts: executing /etc/redis/redis-ser
Mar 16 09:23:19 emonpi run-parts[623]: run-parts: executing /etc/redis/redis-ser
Mar 16 09:23:19 emonpi systemd[1]: Started Advanced key-value store.
Mar 16 09:23:27 emonpi systemd[1]: Stopping Advanced key-value store...
Mar 16 09:23:28 emonpi run-parts[917]: run-parts: executing /etc/redis/redis-ser
Mar 16 09:23:28 emonpi run-parts[923]: run-parts: executing /etc/redis/redis-ser
Mar 16 09:23:28 emonpi systemd[1]: Stopped Advanced key-value store.
Mar 16 09:23:28 emonpi systemd[1]: Starting Advanced key-value store...
Mar 16 09:23:29 emonpi run-parts[930]: run-parts: executing /etc/redis/redis-ser
Mar 16 09:23:29 emonpi run-parts[938]: run-parts: executing /etc/redis/redis-ser
Mar 16 09:23:29 emonpi systemd[1]: Started Advanced key-value store.
pi@emonpi:~ $ journalctl -u mariadb.service 
-- Logs begin at Thu 2016-11-03 17:16:42 UTC, end at Sat 2019-03-16 12:20:01 UTC
Mar 16 09:23:18 emonpi systemd[1]: Starting MariaDB database server...
Mar 16 09:23:19 emonpi systemd[1]: Stopped MariaDB database server.
Mar 16 09:23:19 emonpi systemd[1]: Starting MariaDB database server...
Mar 16 09:23:22 emonpi mysqld[826]: 2019-03-16  9:23:22 1988657152 [Note] /usr/s
Mar 16 09:23:27 emonpi systemd[1]: Started MariaDB database server.
pi@emonpi:~ $ 

Note that bash-autocompletion fills in the service names given the first few letters. systemctl will tell you that mariadb is the name of the service for mysql if you don’t remember, which I agree is a bit of a faff.

FWIW, I’m talking only about current systems. From what you say, I’m supposing that you maintain emoncms on jessie for as long as jessie is supported? But there’s no reason to support it in the same way, nor to halt development of the current system because of a decision to support previous systems. If I choose to run an older version of a system, I expect it to keep running in pretty much that way until I upgrade to a new release. Indeed, that’s exactly why I use openSUSE Leap rather than Tumbleweed (roughly equivalent to Debian stable versus testing, I suppose).

Ok great, it sounds like maintaining multiple rc.local version would make sense so that we can move forward with better practice for suitable distributions.

I’m not sure what the distinction is, both are systemd and the current Stretch based image is using the same “jessieminimal” rc.local, it’s just the repo file name, it is always named rc.local when in use. The distinction will most likely be pre-this point in development and post-this point regardless of Distro (assuming wheezy is already not supported since that wasn’t systemd and has already been left behind)

Hopefully we will reach a point where the rc.local file, close to it’s current form is only needed for installs “pre-this point” and we can discard, empty or move to a distro stock rc.local, it hopefully it won’t matter which as it will not be used, so when systemd eventually no longer supports rc.local or Distros start omitting it, the emonSD will not be affected.

Whether you update/upgrade previous images to whatever come out of this discussion or not, the distinction, dependency on rc.local and rc.local content will revolve specifically around whether the install/image is post rc.local era or not. Once we know what the outcome is, it can be decided whether it can be rolled out to previous images. Whilst i would love to see an all new image, Glyn has made the commitment some time ago that the current image (at that time) would always be upgrade moving forward. So either that comitment gets broken, we upgrade existing images or we could end up maintaining multiple images.

Sounds good. We could detect the required condition for the older rc.local and make that available where applicable. The update process could install the correct rc.local based on conditions.

It should be possible to avoid multiple images this way? correct me if im wrong.

I’ve just been advised about a journald feature I wasn’t aware of, which has changed how I suggest we proceed slightly.

SyncIntervalSec=
The timeout before synchronizing journal files to disk. After syncing, journal files are placed in the OFFLINE state. Note that syncing is unconditionally done immediately after a log message of priority CRIT, ALERT or EMERG has been logged. This setting hence applies only to messages of the levels ERR, WARNING, NOTICE, INFO, DEBUG. The default timeout is 5 minutes. 

If I’m reading that correctly, it means that journald will work exactly as we would like, straight out of the box. That is, if /var/log/jounal exists, or we set its storage mode to persistent. Then journald will save everything to the disk/sdcard and it will only write to the device every five minutes, except in an emergency.

So all we then need to do is override the native logs of the various applications to somewhere like /dev/null

I’ll do some experiments.

Ok, so what you are displaying there is the log messages created by systemd at start up, they are always in systemctl and the very latest have always been displayed with systemctl status.

What you do not see in your output is the logging created by the softwares themselves, a very different thing, that is going to /var/log for the services you displayed. This is not duplicate logging it is different logging in different places.

This discussion came up years ago about mosquitto and the mqtt_input services and it was decided to keep the 2 seperate as they are different things. Take emonhub for example, that produces a vast amount of helpful messages, therefore if this is going to journalctl rather than /var/log, the systemctl log messages are buried, you will need to use some filtering and regexes perhaps top find the systemd logs within the pages and pages of emonhub log messages. That’s if it’s still there, systemd will by default only keep upto 26mb of total logs, so vital boot up info will be quickly lost if every service is logging verbosely to that 26mb limit, yes it can be changed, but there is no need when the logs are kept separate as you demonstrate with your output, just the start and stops of the service(s) are displayed and retained as the faster moving log info is going to /var/log.

The start and stops are not displayed in my output above purely because the system has been up so long the logs have been rotated out (I only enabled persisting journalctl recently on this test server)

pb66@test2:~$ systemctl status redis
â redis-server.service - Advanced key-value store
   Loaded: loaded (/lib/systemd/system/redis-server.service; enabled; vendor pre
set: enabled)
   Active: active (running) since Tue 2019-02-26 09:25:09 GMT; 2 week
s 4 days ago
     Docs: http://redis.io/documentation,
           man:redis-server(1)
 Main PID: 971 (redis-server)
    Tasks: 3 (limit: 4915)
   CGroup: /system.slice/redis-server.service
           ââ971 /usr/bin/redis-server 127.0.0.1:6379

Warning: Journal has been rotated since unit was started. Log output is incomple
te or unavailable.
pb66@test2:~$ sudo journalctl -u redis-server
-- No entries --
pb66@test2:~$ sudo ls -la /var/log/redis
total 6180
drwxr-x---  2 redis redis    4096 Mar 10 06:25 .
drwxr-xr-x 11 root  root     4096 Mar 16 06:25 ..
-rw-rw----  1 redis redis 2899641 Mar 16 15:06 redis-server.log
-rw-rw----  1 redis redis  351060 Jan 14 06:24 redis-server.log.10.gz
-rw-rw----  1 redis redis  263921 Jan  6 06:24 redis-server.log.11.gz
-rw-rw----  1 redis redis  351542 Dec 31 06:24 redis-server.log.12.gz
-rw-rw----  1 redis redis  262797 Mar 10 06:24 redis-server.log.1.gz
-rw-rw----  1 redis redis  350019 Mar  4 06:24 redis-server.log.2.gz
-rw-rw----  1 redis redis  265519 Feb 24 06:24 redis-server.log.3.gz
-rw-rw----  1 redis redis  354475 Feb 18 06:24 redis-server.log.4.gz
-rw-rw----  1 redis redis   64552 Feb 10 06:24 redis-server.log.5.gz
-rw-rw----  1 redis redis  200074 Feb  8 19:29 redis-server.log.6.gz
-rw-rw----  1 redis redis  351475 Feb  4 06:24 redis-server.log.7.gz
-rw-rw----  1 redis redis  307853 Jan 27 06:24 redis-server.log.8.gz
-rw-rw----  1 redis redis  264428 Jan 20 06:24 redis-server.log.9.gz
pb66@test2:~$

see the last line of the status

Warning: Journal has been rotated since unit was started. Log output is incomple
te or unavailable.

I think you should just drop Jessie support. It is ancient history.

I kind of sympathise with that view, in fact it was my first thought too. But then I noticed (I was actually looking up which was newer - jessie or stretch - I’m not a Debian expert, remember) that jessie is an LTS release that has support until 2020 so there is an argument for maintaining software that runs on it for that long too. But I don’t think there’s any need to enhance it. If somebody wants new features they should upgrade to stretch.

I suppose that Trystan et al have a better understanding of how many people are dependent on jessie for some reason.

I think that might be a moot point in this scope, if we are supporting Stretch as it currently stands, you automatically get support for Jessie, unless you opt for some very latest feature that isn’t in the underlying version of systemd used in Jessie. The question is whether we continue support for Jessie and/or Stretch with restarting in the rc.local as it’s already out there on the Stretch base emonSD .

You’re quite right; my apologies. I guess we’re back to plan A for the moment then. In which case …

The appropriate way to create tmpfs and directories therein is systemd-tmpfiles https://jlk.fjfi.cvut.cz/arch/manpages/man/systemd-tmpfiles.8 and that way all the directories/files are created before the services are started and there’s no need for serialized service restarts to add to the boot time.

I’ll keep looking for better alternatives.

But the whole premise of this thread at present is to find ways to eliminate rc.local, so that’s not really a question. Sure there’d need to be support for existing systems in some form.

Only if the logs and folders are lost at reboot. Using log2ram would mean that all the folders and logfiles are there with the right permissions and ownership prior to the services starting, so it works transparently. Aside from the log2ram (systemd) service needing to do it’s bit right up front, it works exactly the same as when the logs are on disc and never lost.

even when you turn on persisting the journalctl logs it would allow them to be rotated out of ram onto disc so you can have ram maintained logs to preserve/extend SDcard life AND persisted logs for a prolonged period without keeping them in RAM, with zero tweaking of any services or softwares.

I really cannot see any downside or reason to look else where. I’m not suggesting it wioll be perfect from the outset, but we can get involved in it’s development or maintain our own version. By adopting something that is already out there we are hitting the ground running and not trying to reinvent the wheel as we have been for the last 2-3 years.

Indeed it is, eliminating rc.local is long overdue and that is the larger part of the root issue (the current method of logging to ram). But there are already Stretch systems out there with the rc.local restarting in use. We cannot say we will no longer support Jessie, only Stretch in order to only support no rc.local setups. To support all existing Stretch images we need to rollout an upgrade or maintain multiple images. By supporting existing Stretch images, one way or another, we also support Jessie, theres nothing different (on this front) between Jessie or Stretch thus far. Only from here on will the stretch images be different so you cannot split it strictly Jessie vs Stretch.

Well, losing the logs is the status quo, so we haven’t lost anything. I agree log2ram looks interesting (specifically log2ram/log2ram at master · azlux/log2ram · GitHub ) but in the main cases of a system crash or a power failure (we had one this morning, they happen regularly) it won’t help. And in any case, as I said, saving service logs over reboot is not as useful as saving system logs.

The point is that journald does low-write ram-buffering out of the box. So you set it to persist to disk and it manages the writes every five minutes by default. I wouldn’t want to trust my system logs to log2ram until I have a lot more experience of it. It’s just not standard.

I’m not sure why “it won’t help” it’s miles better than what we have, only the logs since the last “persist to disk” would be lost, currently everything is lost.

The system logs will be saved, if you create /var/log/journal then all the system logs will be “persisted” (as systemd see’s it) to RAM and then log2ram will treat those systemd logs as any other, persisting them to disk at our chosen frequency and rotating them out of RAM to disk-only at a regular interval as per usual logrotates.

That’s great but it doesn’t fix the non-systemd logging eg emoncms, so we end up with 2 partial solutions to one problem.

That would need to be somewhere other than /var/log as we still need to keep /var/log in ram for the non-systemd logs.

That can be said for what ever solution we may concoct here, but log2ram has been around far longer than anything we haven’t yet come up with!

So run it on a dev system, or in parallel to something you do trust, If we never try it, it will never reach a “trusted” state. It is not possible for it to be worse than we have! It is a starting block, we will never find an established open-source commercial solution for what we need, ramlog has been suggested a few times but it is too complex, log2ram’s appeal is it’s simplicity. Don’t think of it as an application, but a gathering of a few commands in a service to automate logfile management in ram (specifically file and folder “creation”), that way it isn’t a million miles from what you are seeking, you would put trust in a handful of bash and/or systemd commands you/we cobbled together, we would then iorn out any issues that crop up. Using log2ram is just jumping in with a head start based on some ready made code!

You’ve missed the point. journald already does the low write buffering of system logs, but most importantly it writes-through to disk immediately any emergency messages as a system crashes, overriding the low-write policy. That’s exactly what’s needed* and what log2ram doesn’t do.

  • well modulo those rare cases where you have to have a serially-connected console to capture the last kernel message.

log2ram does not persist logs in the case of a crash or power fail. journald does in the case of a crash and [I can think how to implement] could on a power fail. But system crash is the most important case. Power fails don’t usually need investigating, and service fails don’t usually need persistent logs.