Mosquitto won't start on boot after raspbian and emonsd update

Hello,

I just upgraded my emonpi following instructions here : emonPi KRACK fix and upgraded emonpi/emonbase using web GUI.

But, at boot time, Mosquitto wouldn’t start. After some investigation reading this : Mosquitto not starting after emonSD update & upgrade - #18 by jeremypoulter and this : MQTT Log files - #9 by glyn.hudson, checking the rc.local_jessieminima had been properly updated, and the log file directory was properly created, I had a look at the service startup logs :

pi@emonpi(ro):mosquitto$ sudo journalctl -u mosquitto
-- Logs begin at Tue 2017-11-07 22:09:42 CET, end at Tue 2017-11-07 22:27:13 CET. --
Nov 07 22:09:44 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:09:44 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:09:44 emonpi mosquitto[515]: 1510088984: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:09:45 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:09:45 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:09:45 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:09:45 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:09:45 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:09:45 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:09:45 emonpi mosquitto[625]: 1510088985: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:09:45 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:09:45 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:09:45 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:09:45 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:09:45 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:09:45 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:09:45 emonpi mosquitto[690]: 1510088985: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:09:45 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:09:45 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:09:45 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:09:45 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:09:45 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:09:45 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:09:45 emonpi mosquitto[715]: 1510088985: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:09:45 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:09:45 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:09:46 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:09:46 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:09:46 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:09:46 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:09:46 emonpi mosquitto[790]: 1510088986: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:09:46 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:09:46 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:09:46 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:09:46 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:09:46 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:09:46 emonpi systemd[1]: mosquitto.service start request repeated too quickly, refusing to start.
Nov 07 22:09:46 emonpi systemd[1]: Failed to start Mosquitto MQTT Broker.
Nov 07 22:09:46 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:09:51 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:09:51 emonpi systemd[1]: mosquitto.service start request repeated too quickly, refusing to start.
Nov 07 22:09:51 emonpi systemd[1]: Failed to start Mosquitto MQTT Broker.

The last try (the one done by rc script I think) occurs 5 seconds after the “throttling” (5 restart in 10 secs by default)

If I finally start the service manually it works

Nov 07 22:14:13 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:14:13 emonpi systemd[1]: Started Mosquitto MQTT Broker.

So I just added a sleep just before the services restart in rc.local_jessieminima

# Restart services,they should run happy now log dir's are created
sleep 11
service apache2 restart
service redis-server restart
service mosquitto restart
service supervisor restart

And voila ! It works again on boot :grinning:

-- Logs begin at Tue 2017-11-07 22:37:51 CET, end at Tue 2017-11-07 22:39:07 CET. --
Nov 07 22:37:53 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:37:53 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:37:53 emonpi mosquitto[519]: 1510090673: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:37:54 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:37:54 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:37:54 emonpi mosquitto[624]: 1510090674: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:37:54 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:37:54 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:37:54 emonpi mosquitto[685]: 1510090674: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:37:54 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:37:54 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:37:54 emonpi mosquitto[700]: 1510090674: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:37:54 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:37:54 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:37:54 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 07 22:37:54 emonpi mosquitto[717]: 1510090674: Error: Unable to open log file /var/log/mosquitto/mosquitto.log for writing.
Nov 07 22:37:54 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 07 22:37:55 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:37:55 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 07 22:37:55 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 07 22:37:55 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:37:55 emonpi systemd[1]: mosquitto.service start request repeated too quickly, refusing to start.
Nov 07 22:37:55 emonpi systemd[1]: Failed to start Mosquitto MQTT Broker.
Nov 07 22:37:55 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 07 22:38:22 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 07 22:38:22 emonpi systemd[1]: Started Mosquitto MQTT Broker.

The last restart occurs after the 10 seconds of “throttling”

But I don’t like much adding “sleep” everywhere. Is there another way for correcting this ? Should I disable automatic start on boot so that the rc script only starts the services instead of restarting them ? Any drawbacks ?

Thanks.
JS

1 Like

Good work locating the cause, adding the “sleep” is indeed a good way of confirming the issue, but as you quite rightly say, adding sleeps everywhere is not good practice.

Yes, what you suggest with disabling the automatic start of the service(s) in question could be seen as a step in the right direction, even without being aware that a sleep is needed, it is/was pointless starting services knowing they are going to fail to start only to be started again at a later date in rc.local.

However. The services should not be restarted in rc.local, this is not unlike investing in something like a state of the art self-learning Nest heating and hotwater control system and then putting a plug on it and plugging it into one of these

as the benefits of a sophisticated and managed start up routine are being under mined by using rc.local in this way.

I understand why it’s been done that way in the past, it’s easy and the original services all remain as stock/default which is easier to maintain etc. However the correct thing to do would be to create a proper service unit/init script with a rule to be started very early in the boot process that creates those missing log folders/files, that way when the services in question are started in the normal manner, in the right order, in the correct way, at the appropriate times, the required log files/folders would already be there waiting and it would work the way it was intended.

So basically instead of subsequently applying a fix and restarting what failed after it’s failed using a now depreciated service, we should simply use the current and correct tool for the job and apply a fix ahead of it becoming an issue. That would be a fix rather than a workaround.

It seems rc.local isn’t even active in Stretch by default (although it can still be activated).

Hi @jsroques,

Nice work tracking this issue down. I have been unable to replicate the issue. On system (stock emonSD-26Oct17) it does eventually start.

sudo journalctl -u mosquitto
-- Logs begin at Wed 2017-11-08 15:10:19 UTC, end at Wed 2017-11-08 15:11:23 UTC. --
Nov 08 15:10:21 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 15:10:21 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 08 15:10:22 emonpi mosquitto[517]: 1510153822: Error: Unable to open log file /var/log/mosquitto/mosquitto.l
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 08 15:10:22 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 08 15:10:22 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 08 15:10:22 emonpi mosquitto[622]: 1510153822: Error: Unable to open log file /var/log/mosquitto/mosquitto.l
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 08 15:10:22 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 08 15:10:22 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 08 15:10:22 emonpi mosquitto[661]: 1510153822: Error: Unable to open log file /var/log/mosquitto/mosquitto.l
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 08 15:10:22 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 08 15:10:22 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 08 15:10:22 emonpi mosquitto[677]: 1510153822: Error: Unable to open log file /var/log/mosquitto/mosquitto.l
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 08 15:10:22 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 08 15:10:22 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 08 15:10:22 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 15:10:22 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 08 15:10:23 emonpi mosquitto[739]: 1510153823: Error: Unable to open log file /var/log/mosquitto/mosquitto.l
Nov 08 15:10:23 emonpi systemd[1]: mosquitto.service: main process exited, code=exited, status=1/FAILURE
Nov 08 15:10:23 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 08 15:10:23 emonpi systemd[1]: mosquitto.service holdoff time over, scheduling restart.
Nov 08 15:10:23 emonpi systemd[1]: Stopping Mosquitto MQTT Broker...
Nov 08 15:10:23 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 15:10:23 emonpi systemd[1]: mosquitto.service start request repeated too quickly, refusing to start.
Nov 08 15:10:23 emonpi systemd[1]: Failed to start Mosquitto MQTT Broker.
Nov 08 15:10:23 emonpi systemd[1]: Unit mosquitto.service entered failed state.
Nov 08 15:10:32 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 15:10:32 emonpi systemd[1]: Started Mosquitto MQTT Broker.

Out of interest what emonSD version are you running?

$ ls /boot | grep emonSD

Thanks a lot for helping out on the other thread, it looks like it’s been confirmed it’s same issue :+1:

I agree, adding delays is not ideal. 11s is quite a long delay. However I will as a temporary add this change to the rc.local script. This change will be automatically pulled in by all emonPi’s:

I wonder how the init script could be modified to wait for the log file to be created, or ideally create the logfile itself?

Ok, I’ve just taken a look and it’s possible to set a ConditionPathExists condition in /lib/systemd/system/mosquitto.service service file.

This stops the service starting initially since the path /var/log/mosquitto does not exist. When we later restart the service from r.local after the log file has been create mosquitto start nicely.

sudo nano /lib/systemd/system/mosquitto.service

[Unit]
Description=Mosquitto MQTT Broker
Documentation=man:mosquitto(8) https://mosquitto.org/
ConditionPathExists=/var/log/mosquitto


[Service]
ExecStart=/usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
Restart=always

[Install]
WantedBy=multi-user.target

sudo systemctl status mosquitto.service

● mosquitto.service - Mosquitto MQTT Broker
   Loaded: loaded (/lib/systemd/system/mosquitto.service; enabled)
   Active: inactive (dead)
           start condition failed at Wed 2017-11-08 16:22:53 UTC; 1min 34s ago
           ConditionPathExists=/var/log/mosquitto/ was not met
     Docs: man:mosquitto(8)
           https://mosquitto.org/

Much cleaner:

sudo journalctl -u mosquitto
-- Logs begin at Wed 2017-11-08 16:37:27 UTC, end at Wed 2017-11-08 16:47:36 UTC. --
Nov 08 16:37:29 emonpi systemd[1]: Started Mosquitto MQTT Broker.
Nov 08 16:37:56 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 16:37:56 emonpi systemd[1]: Started Mosquitto MQTT Broker.

@jrmoralesc could you test to see if adding ConditionPathExists=/var/log/mosquitto to the [unit] section of /lib/systemd/system/mosquitto.service and then removing the 11s delay allows mosquitto to start for you?

See Install OpenHAB2 on emonSD / emonPi - #34 by pb66 for a working example of a systemd unit that can create the log folder (and file?) if it doesn’t exist when the service is first called, removing the need for an entry in rc.local altogether.

It works the same way the emonhub init script always has but in the form of a service unit.

This approach has worked well for emonhub and can work equally well for all services we maintain or contribute to. But for Redis, Apache2 and Supervisor (which Dataplicity is dependent on) there needs to be another solution and that could be another service unit that doesn’t actually start anything, it simply creates the log folders/files for non-oem softwares and exits.

Instead of adding the paths and owners of the needed log file/folders to rc.local, add it to the logfile creation service unit instead. This new service could be part of the RO changes made to the OS.

I really cannot see why you would want to delay starting the Mosquitto service (or any other service) and rely on something else to create the logfile and start the service afterwards rather than creating the logfile before or at the latest when it is needed. Why add a “wait” or a “sleep” when neither is needed?

What happens if the logfile exists but is the wrong owner or permissions? The service will still try to start and fail, admittedly this is unlikely to happen at boot, but it could happen any other time, for example, what happens if the logfile gets deleted accidentally? even restarting the service won’t fix anything, the user will have to reboot or add it back in manually.

Apache2 and redis etc are beyond our control, but the OEM software’s that are specifically written to be run on an RO OS should be able to create there own logfiles and folders unaided.

Hello @glyn.hudson,

My version is emonSD-03May16

JS

Hello @pb66,

Just to make sure I understand what your saying : you can’t (shouldn’t) modify services conf files for software out of OEM control and rather add a “dummy” service which would run first and only creates missing directories / files ?

But in the end, if mosquitto needs the directory, it should be its responsibility to create it. So it should be better to modify mosquite.service and add “ExecStartPre”. Same thing for any other service. And those changes should be reflected in their original distribution. Wouldn’t you agree ?

May be a stupid question : By “RO OS” you mean Read Only OS ?
JS

“can’t” might be a bit strong, but playing with code that belongs to another maintained package could be problematic, it’s arguably better to run stock services and work around them.

Exactly that.

IMO true, but if the Mosquitto service was changed in service and those changes were pulled in by apt-get, our changes would be lost, there is no excuse for not doing this with OEM software, but it is debatable with the likes of Mosquitto, but since Glyn was suggesting an edit to make the service “wait” I see no reason to “wait” rather than create the folder/files.

IMO we remain stock and add the seperate service unit to create the files ahead of the service being called or we edit the service to create the logfiles itself, there is no point in moving away from “stock” to introduce a “wait”.

indeed.

Perhaps it is worth trying to submit a PR to Apache2 and Mosquitto as they are both open-source and the proposed changes only make the SW more robust and/or perhaps easier to install, I see no downside to making the service unit check for these files/folders and create if not present and correct since they have already made the SW dependent on the files being there.

I think I can recall a comment made some time ago about “Supervisor” by the developer of Dataplicity, that they have no intention of accommodating a fix for this, so we cannot expect this issue to disappear completely.

Hello again,

Sorry for the multiple posts…

I tested the following :

  • remove all reference to mosquitto from rc script
  • update mosquitto.service adding 2 “ExecStartPre”

The file now look like that (thanks @pb66 for the example) :

[Unit]
Description=Mosquitto MQTT Broker
Documentation=man:mosquitto(8) https://mosquitto.org/

[Service]
ExecStartPre=-/bin/mkdir -p /var/log/mosquitto
ExecStartPre=/bin/chown -R mosquitto:mosquitto /var/log/mosquitto
ExecStart=/usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
Restart=always

[Install]
WantedBy=multi-user.target

And it now boot faster (11 secs at least :wink:) and even much cleaner boot :

pi@emonpi(ro):~$ sudo journalctl -u mosquitto
-- Logs begin at Wed 2017-11-08 19:42:49 CET, end at Wed 2017-11-08 19:43:43 CET. --
Nov 08 19:42:51 emonpi systemd[1]: Starting Mosquitto MQTT Broker...
Nov 08 19:42:51 emonpi systemd[1]: Started Mosquitto MQTT Broker.

But it now comes down to a previous question : it is not good practise to modify a service stock configuration.

So, if the way is to go for a specific service, there is a oneshot service type. From system.d man :

… Behavior of oneshot is similar to simple; however, it is expected that the process has to exit before systemd starts follow-up units…

I could create an RO OS specific script, move all those directories / files creation there, and create this “oneshot” service.

JS

Nice! That looks like a good solution.

I agree that it’s a good idea to avoid modifying services and applications that we don’t have control over. However IMO modifying the *.service file is not really modifying the application it’s just customising the config. Is this not what the .service files are for?

Another option could be to do away with the need to a specific file by chaining the mosquitto config to log to syslog and let the system handle it. See mosquito logging config section

Unfortunately not. The service unit or init script is managed by by the package manager in the same way the main applications are. Even the proper config files are often switched out by apt-get, example the php.ini. The user is asked if they want to keep the old original or accept the new file. This isn’t the case for the init scripts as the maintainers do not expect them to be changed,

A very good example is actually this very package, Mosquitto. The file you guys are editing at /lib/systemd/system/mosquitto.service doesn’t exist on my totally stock (but not recently updated) emonpi, the service unit is located at /run/systemd/generator.late/mosquitto.service because it was created automatically by systemd-sysv-generator because even at Mosquitto version 1.4.13, it is still shipped with a init.d script located at /etc/init.d/mosquitto.

pi@emonpi(ro):~$ ls -la /etc/systemd/system/mosquitto.service
ls: cannot access /etc/systemd/system/mosquitto.service: No such file or directory
pi@emonpi(ro):~$ ls -la /run/systemd/system/mosquitto.service
ls: cannot access /run/systemd/system/mosquitto.service: No such file or directory
pi@emonpi(ro):~$ ls -la /usr/lib/systemd/system/mosquitto.service
ls: cannot access /usr/lib/systemd/system/mosquitto.service: No such file or directory
pi@emonpi(ro):~$ ls -la /run/systemd/generator.late/mosquitto.service
-rw-r--r-- 1 root root 572 Jan  1  1970 /run/systemd/generator.late/mosquitto.service
pi@emonpi(ro):~$ sudo systemctl status mosquitto.service
â mosquitto.service - LSB: mosquitto MQTT v3.1 message broker
   Loaded: loaded (/etc/init.d/mosquitto)
   Active: active (running) since Thu 2017-11-02 07:17:21 UTC; 1 weeks 0 days ago
  Process: 1656 ExecStop=/etc/init.d/mosquitto stop (code=exited, status=0/SUCCESS)
  Process: 1664 ExecStart=/etc/init.d/mosquitto start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/mosquitto.service
           ââ1670 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.
pi@emonpi(ro):~$ ls -la /etc/init.d/mosquitto
-rwxr-xr-x 1 root root 3323 Dec 22  2015 /etc/init.d/mosquitto
pi@emonpi(ro):~$

So if I was to update the service unit or the init.d script, or indeed if either of you had done so say a month ago, after updating those changes would be lost and the new unit located at /lib/systemd/system/mosquitto.service would be totally stock.

This is why it is unwise to alter files that are managed by a package manager in case they get changed. To which I’m sure you’ll say “but that’s unlikely to happen (again/often?)” but that translates to “in the event it was to happen again, and cause a problem, it will most likely be really difficult to locate as no one expects that file to get changed”

If the OS was not adapted to RO, the logfiles would persist a reboot and be there when the service units are called, therefore the closest thing we can get to normal operation is to ensure the logfiles are there ahead of when the service units are called. It is the easiest and the most reliable method, second only to getting the source changed to ensure the files are created in-house by the service unit when absent at boot time.

I’m not sure why this isn’t desirable. The old method has been strongly defended for a long time and this is exactly the same thing as was done previously in the wrong place at the wrong time, I’m just suggesting moving it to the right place, to be done at the right time.

This is the rc.local file on my emonpi

#!/bin/sh
#
# rc.local

/usr/bin/printf " My IP address is\033[0;31m `/sbin/ifconfig | grep "inet addr" | grep -v "127.0.0.1" | awk $

# Will only run if /var/log is mounted in tmpfs
if ( mount | grep "on /var/log "| grep -q "^tmpfs " )
then
  for i in "redis" "apache2" "mysql" "openhab" "logrotate" "mosquitto" "supervisor"; do mkdir /var/log/"$i"; done
  for i in "emoncms.log" "mysql.log" "mqtt_input.log" "redis/redis-server.log" "service-runner.log" "mysql/error.log" "apache2/error.log" "supervisor/supervisord.log" "ntp_update.log"; do touch /var/log/"$i"; done
  for i in "emoncms.log" "mysql.log" "mqtt_input.log" "redis/redis-server.log" "service-runner.log" "mysql/error.log" "apache2/error.log" "supervisor/supervisord.log" "ntp_update.log"; do ""chmod 666"" /var/log/"$i"; done

  chown -R root:adm /var/log/apache2
  chown -R redis:redis /var/log/redis
  chown -R mysql:adm /var/log/mysql
  chown -R openhab:openhab /var/log/openhab
  chown -R pi:pi /var/log/logrotate
  chown -R mosquitto:mosquitto /var/log/mosquitto
  chown -R dataplicity:dataplicity /var/log/supervisor;

  # Restart services,they should run happy now log dir's are created
  service apache2 restart
  service redis-server restart
  service mosquitto restart
  service supervisor restart
fi

# Run emonPi Update of first factory boot as Pi user (run condition > web connection exisits && ~/data/emonp$
su pi -c '/home/pi/emonpi/./firstbootupdate'

# wait for mosquitto to restart then restart services than depend on MQTT
sleep 5
service emonPiLCD restart
sleep 5
service mqtt_input restart
service lwrfd restart

## Start Wifi AP (uncomment if required) see emonpi/wifiAP/readme.md
# /home/pi/emonpi/wifiAP/wifiAP.sh start

exit 0

Are you really going to edit 7 individual service units and hope none of these get overwritten rather than writing one bespoke service unit? (And is that more sleeps? So is there now over 20 secs of sleeps in the current rc.local?)

There isn’t actually anything that needs to stay in that file, Exerything relates to creating logfiles or the restarting of services once those logfiles have been created except for su pi -c '/home/pi/emonpi/./firstbootupdate' which would be better served using the same mechanism as used when expanding the filesystem. A simple self deleting service is added and activated before powering down so on the next reboot it runs and deletes itself.

If you would prefer to retain the ability to reset the firstbootupdate (currently you can delete the update log) you could just self-deactivate the service rather than delete and to force a new firstbootupdate you just activate it again.

Hello,

So, here is an new test I did.

Created a little varlog.tar file containing /var/log required dirs and files with proper permissions. For now I located it in ~/emonpi. It contains the following :

drwxr-xr-x pi/pi             0 2017-11-08 19:42 apache2/
-rw-rw-rw- pi/pi             0 2017-11-10 21:19 apache2/error.log
-rw-rw-rw- pi/pi             0 2017-11-10 21:18 emoncms.log
-rw-r--r-- pi/pi             0 2017-11-10 22:16 eom-varlog.flag
drwxr-xr-x pi/pi             0 2017-11-10 21:20 logrotate/
drwxr-xr-x pi/pi             0 2017-11-10 21:20 mosquitto/
-rw-rw-rw- pi/pi             0 2017-11-08 19:42 mqtt_input.log
drwxr-xr-x pi/pi             0 2017-11-10 21:21 mysql/
-rw-r--r-- pi/pi             0 2017-11-10 21:21 mysql/error.log
-rw-rw-rw- pi/pi             0 2017-11-08 19:42 mysql.log
-rw-rw-rw- pi/pi             0 2017-11-08 19:42 ntp_update.log
drwxr-xr-x pi/pi             0 2017-11-08 19:42 openhab/
drwxr-xr-x pi/pi             0 2017-11-08 19:42 redis/
-rw-rw-rw- pi/pi            10 2017-11-10 21:21 redis/redis-server.log
-rw-rw-rw- pi/pi             0 2017-11-10 21:18 service-runner.log
drwxr-xr-x pi/pi             0 2017-11-08 19:42 supervisor/
-rw-rw-rw- pi/pi             0 2017-11-08 19:42 supervisor/supervisord.log

Then, I created a oem-varlog.service :

#
# OpenEnergyMonitor - Creation required directories and file in /var/log
#

[Unit]
Description=Creates required directories and file in /var/log
RequiresMountsFor=/var/log

[Service]
Type=oneshot
ExecStart=/bin/tar -xpf /home/pi/emonpi/varlog.tar -C /var/log
RemainAfterExit=yes

[Install]
WantedBy=multi-user.target

Then enable it using sudo systemctl enable oem-varlog.service

I also remove the commands from rc script.

Rebooting… and it seems to work.

I used a tar file because it then requires only one command in the service file, no need for an additionnal script. But modifiying the tar file may not be as easy as modifying a script… It probably needs some “tweaking”, separating openhab & oem files in 2 distincts services for instance for modularity (I personnaly disabled openhab), find a propoer place for the tar file… But would you think it is the way to go ?

JS

Sounds good.

Keeping the folder and file structures out of the service unit is a probably a better approach than trying to make the new service unit check, create, touch and chown each log file, tar, rsync or cp could be used, but I think tar would be the fastest.

If using tar it isn’t essential to restore from a tar file, you could just keep a template folder with all the empty logfiles and folders set up and use something like tar cpf - /path/to/template | tar xpSf - -C /var/log.

What would be cool is to clone the folder/file template from the working system so that when a new package is installed and the new logfiles get created in /var/log by the package manager, they also get added to the template. This could be done in a similar way to the fake-hwclock so that the template is updated hourly and on shutdown.

When this was discussed a couple of years back, I suggested we did something like this to retain logs across a reboot.

I’m not totally up to speed with the systemd options, what prioritizes oem-varlog.service to run before all the services that we are creating logs for? AFAIK WantedBy=multi-user.target is the same runlevel that we need to get ahead of, I sort of expected something like before= to list all those services that need logfiles created, not an ideal solution if using a template or cloned folder. Editing each service unit to have before=oem-varlog.service isn’t a viable option either.

Hello,

That would be faster than a simple cp ? As it is just empty folders / files so it should be fast anyway, creating a tar was a simple way of keeping things tidy but having a raw folder is easier to maintain. Anyway, this is easy to change.

I thought of doing that but, if the files / folders are created by the package manager, if they get accidentally removed… they would also be removed from the template. Unless we always “add” but then you’ll end up with useless stuff.

Then why not create a standard fs instead of a tmpfs ? I guess it is mainly because of SD card wearing and risk of fs corruption. But keeping logs on a separate fs, it is limiting corruption to this fs and prevent total failure in case log fs gets unusable. You’ll have to rebuild / reformat the log fs and just loose logs. So it would come down to wearning.

Yep… I’ll have a look to see what I can come up with.

JS

Apparently so, I’ve often read tar is faster than cp and they are both faster than rsync for cold copying, rsync has the advantage when just copying the changes.

Absolutely, I wasn’t criticizing, in fact if we were working with a fixed quantity then a tar file would be better, but, yes for easy maintenance, a template would be easier.

Indeed, but in fact it would be no different to them getting “accidentally removed” on a normal read write OS.

Exactly, it’s the choosing the lesser evil, risk loosing files that get accidentally deleted by the user verses accumulating redundant files by just adding.

Correct. The idea of saving the logfiles from ram to disk periodically and at shutdown would limit the wear by keeping all the continuous streams of log entries in ram and writing to disk in batches, much like the buffered-write mode of emoncms.

Another suggestion back then was to use some logrotate functionality to rotate the logs out of ram onto disk so only the latest logs remain in RAM, this would improve ram management too.

Regards an alternative logfile location there are multiple options, it could either be sited on the writable partition, or the service that performs the log backup/cloning could make the OS writable for a moment, that’s how the fake-hwclock works. The advantage of this is that the files will be available earlier in the startup process. Originally the fake-hwclock was backed up to the /data partition but we found that often the Pi would boot with a date of 1/1/1970 as the /data partition wasn’t always mounted in time for when the file was needed during start-up. This isn’t something we would want happening with the saved logfiles (or template?). /var/log_backup might be an ideal place. in the past I have hard-linked /var/log to /var/log2 before making the OS RO and adding the tmpfs /var/log, then when the tmpfs /var/log hides the disk copy of /var/log, the original files are still available at /var/log2.

[edit] The other consideration with the logfile location is that not all read-only images have a writable partition, so the “momentarily mount rw” option would be more universal and perhaps even protect the logfiles from accidental deletion too if RO most of the time.

Nice work @jsroques. I like the .tar solution and service to extract into /var/log before the other services start on bootup. Using a tar will allow us to keep the empty files and folder on github. I’m assuming the tar honours the folder and file permissions?

I would prefer to keep the tar manual creation rather than allowing services to be able to automatically add their logs. This allows us to keep control over what’s being logged.

~/emonpi is the best place to store the file so it can be included in the emonPi repo:

Would you like me to add these changes into a dev branch of the emonPi repo so we can further test and refin?

Thanks for your help.

It only lets you keep control of what’s permitted to log correctly and not cause problems. For a user to add a package that needs or wants logging, any attempts to edit the log.tar will block future emonpi updates or get over written.

Manually adding the files or folders to a template folder will retain the ownership and permissions and allow users to add a log file if needed for other services. all you need to put in the emonpi updater is short list of commands (like were originally in rc.local) so that if the log_template folder doesn’t exist, it gets created with all the usual files and permisions etc. That way if someone messes it up, they can just delete the folder and update the emonpi to fix.

Hello,

I am not sure I understood what you meant (and I am not a git guru…) So you create a new branch so I can push the scripts and config file ? So I would put the “template” files structure in some subdir in emonpi. But where would you put the service file ?

Or you add the files yourself ? I can send you the config and tar files as is ?

Whatever seems easier for you.

Yes, the -p in the tar command (as in “preserve”) takes care of this.

Anyway, the 2 next things I can have a look at would be to make sure the folders get created before requiring services start up and launch a “backup” every so often. I won’t have time in the next few days but can work on this starting end of next week.

Hello,

I have been thinking and do some research about this and here are some results… and questions…

How do you update files outside emonpi directories ? Typically, systemd file ?

About execution order, it seems that using before= wilth a list of of log files depending services (that is apache, redis-server, mosquitto and supervisor) will make sure that the service creating the logs will run before them. I found a nice article here : systemd: Unit dependencies and order - Fedora Magazine

Also, it may be usefull to separate the “default” log package, the “user” log package and the log backups.

For “log package”

  1. Defauls log package : have a ~/emonpi/logtools/varlog.template directory, making it simpler to update and keeping it in ro fs limiting the risk of user messing it up

  2. User’s log package : only backup directory structure and create empty files with proper perms in ~/data/varlog.template as the fs is RW and volume is low. This way it is easy to recreate the user’s log structure if needed but won’t affect oem default log structure : if the user deletes its own ~/data/varlog.template it should not affect oem.

  3. Use an oem-varlog service which

  • copies both ~/emonpi/logtools/varlog.template and ~/data/varlog.template (using tar cpf - /path/to/template | tar xpSf - -C /var/log for instance)
  • makes a backup of the structure in ~/data/varlog.template
  1. Have a script in cron which backups the structure, let say every 10 minutes

For log backup

It is a bit trickier…

I don’t understand what you mean. And I though hard links worked for individual file only.

Anyway, I had a look at logrotate but backup cannot cross file system boundaries. Thus, it cannot be used to backup logs from tmpfs to another permanent fs.

Putting them in ~/data is a bit dangerous as it could fillup the fs

So, a backup could be done in ~/log.backup for instance which could be it’s own fs or, if not, remount / as rw, do the backup and remount as ro. May be rsync could be an efficient way (but kind of overkill?)

What do you think ? I’ll be testing some of that but I’ve had issues with my emonpi locking up my ssh session although emoncms seems to work…

1 Like

usually a script inside the emonpi folder will create/edit/replace any files outside the github maintained folders.

indeed that would work, but it is less than ideal having to list all the services inside that logfile creating service, it undermines having a template folder, you may as well just keep all the stuff that’s currently in rc.local but move it too the new service. The idea of the template was that the service would not need editing and woulds remain standard regardless of how many logfiles it was creating.

This is why I suggested doing it as some kind of runlevel based ordering “before anything else” type statement although that is very broad.

Yes, you’re right and jogged my memory on why I abandoned that route and just copied the /var/log folder to /var/somethingelse as part of the RO implementations. When I have since looked at some old scripts I could only see cp and no ln /var/log and for the life of me couldn’t recall why.

Really? Ok, I didn’t know that. I assumed it would be able to put them in /var/somethingelse if the FS was momentarily RW.

i’d be interested in how your tests go, I would be happy to work on this too as it is something I feel is important, the emonhub.log files keep getting rotated out ever hour by logrotate and any reboot results in all logs lost. improvements here would make debugging much easier as well as making the RO OS more robust and installation easier.

“log files” was the first thing to cross my mind when I saw this EmonCms inputs page not charging When OpenRemote is starting at startup post.

1 Like