[VrahoK]

Hi everyone,

This has probably been discussed somewhere already but I couldn't find exactly the same behavior nor a sufficient explanation for a fix or workaround to try out, so sorry if this is a double post and feel free to refer me to an existing thread.

Problem description: I have a RPi3B, clean up-to-date Raspian Buster installation and installed prebuilt pilight stable (v8.1.5) from the repo. Now I have following behavior: pilight automatically starts on boot and the service seems to be running:

Code:

pi@HimbeerBox3:~ $ sudo service pilight status
? pilight.service - pilight
  Loaded: loaded (/etc/systemd/system/pilight.service; enabled; vendor preset: enabled)
  Active: active (running) since Fri 2019-12-13 10:35:03 GMT; 1min 46s ago
 Process: 354 ExecStart=/usr/local/sbin/pilight-daemon (code=exited, status=0/SUCCESS)
Main PID: 455 (pilight-daemon)
   Tasks: 13 (limit: 2200)
  Memory: 15.5M
  CGroup: /system.slice/pilight.service
          mq455 /usr/local/sbin/pilight-daemon

Dec 13 10:34:58 HimbeerBox3 systemd[1]: Starting pilight...
Dec 13 10:35:03 HimbeerBox3 systemd[1]: Started pilight.

When I try to access the pilight webserver (HimbeerBox3:5001) it seems to try and connect but then hangs. A website refresh shows no connection anymore. Checking for the status of the service:

Code:

pi@HimbeerBox3:~ $ sudo service pilight status
? pilight.service - pilight
  Loaded: loaded (/etc/systemd/system/pilight.service; enabled; vendor preset: enabled)
  Active: failed (Result: signal) since Fri 2019-12-13 10:42:29 GMT; 29s ago
 Process: 354 ExecStart=/usr/local/sbin/pilight-daemon (code=exited, status=0/SUCCESS)
Main PID: 455 (code=killed, signal=ABRT)

Dec 13 10:34:58 HimbeerBox3 systemd[1]: Starting pilight...
Dec 13 10:35:03 HimbeerBox3 systemd[1]: Started pilight.
Dec 13 10:42:29 HimbeerBox3 pilight-daemon[354]: pilight-daemon: /home/pilight/source/daemon-dev/libs/pilight/core/json.c:1147: emit_string: Assertion `utf8_validate(str)' failed.
Dec 13 10:42:29 HimbeerBox3 systemd[1]: pilight.service: Main process exited, code=killed, status=6/ABRT
Dec 13 10:42:29 HimbeerBox3 systemd[1]: pilight.service: Failed with result 'signal'.

After doing a "sudo service pilight start" again, the service seems to run stable

Code:

pi@HimbeerBox3:~ $ sudo service pilight status
? pilight.service - pilight
  Loaded: loaded (/etc/systemd/system/pilight.service; enabled; vendor preset: enabled)
  Active: active (running) since Fri 2019-12-13 10:46:53 GMT; 1s ago
 Process: 695 ExecStart=/usr/local/sbin/pilight-daemon (code=exited, status=0/SUCCESS)
Main PID: 696 (pilight-daemon)
   Tasks: 13 (limit: 2200)
  Memory: 5.4M
  CGroup: /system.slice/pilight.service
          mq696 /usr/local/sbin/pilight-daemon

Dec 13 10:46:53 HimbeerBox3 systemd[1]: Starting pilight...
Dec 13 10:46:53 HimbeerBox3 systemd[1]: Started pilight.

I could imagine something like the service being started too early on boot so not all networking is available or something like that but I'm not experienced enough to check for that. I have exactly the same setup and config running on a RPi1B+ successfully and stable (but fairly slow, that's why I want to migrate).

The content in /var/log/pilight.log:

Code:

=== FORCED REBOOT ===
(/home/pilight/source/daemon-dev/daemon.c #2588) [Dec 13 10:34:51:866394] INFO: Interrupt signal received. Please wait while pilight is shutting down
(/home/pilight/source/daemon-dev/daemon.c #2381) [Dec 13 10:34:51:879000] INFO: removed stale pid_file /var/run/pilight.pid

=== AUTOSTART ON BOOT ===
(/home/pilight/source/daemon-dev/libs/pilight/config/rules.c #117) [Dec 13 10:35:03:838807] INFO: rule #6 everything_off_manual was parsed in 0.003026 seconds
(/home/pilight/source/daemon-dev/libs/pilight/config/rules.c #117) [Dec 13 10:35:03:841783] INFO: rule #7 everything_on_manual was parsed in 0.002912 seconds
(/home/pilight/source/daemon-dev/daemon.c #3082) [Dec 13 10:35:03:956860] INFO: version v8.1.5
(/home/pilight/source/daemon-dev/libs/pilight/core/socket.c #168) [Dec 13 10:35:03:969298] INFO: daemon listening to port: 35055
(/home/pilight/source/daemon-dev/libs/pilight/core/socket.c #577) [Dec 13 10:35:03:973520] INFO: new client, ip: 127.0.0.1, port: 44816
(/home/pilight/source/daemon-dev/libs/pilight/core/webserver.c #1889) [Dec 13 10:35:03:985060] INFO: secured webserver started on port: 5002 (fd 16)
(/home/pilight/source/daemon-dev/libs/pilight/core/webserver.c #1892) [Dec 13 10:35:03:985155] INFO: regular webserver started on port: 5001 (fd 17)
(/home/pilight/source/daemon-dev/libs/pilight/events/events.c #2137) [Dec 13 10:35:04:87779] NOTICE: no pilight ssdp connections found
(/home/pilight/source/daemon-dev/libs/pilight/core/socket.c #577) [Dec 13 10:35:04:88307] INFO: new client, ip: 127.0.0.1, port: 44818
^^^^ last entry before crash -> client connected to webui

=== MANUAL RESTART OF pilight SERVICE ===
(/home/pilight/source/daemon-dev/libs/pilight/protocols/API/datetime.c #362) [Dec 13 10:46:53:723239] INFO: datetime time 13.737300:51.045700 seems to be in timezone: Europe/Berlin
^^^^ this line is missing in the former run????
(/home/pilight/source/daemon-dev/libs/pilight/config/rules.c #117) [Dec 13 10:46:53:755338] INFO: rule #6 everything_off_manual was parsed in 0.002190 seconds
(/home/pilight/source/daemon-dev/libs/pilight/config/rules.c #117) [Dec 13 10:46:53:757761] INFO: rule #7 everything_on_manual was parsed in 0.002403 seconds
(/home/pilight/source/daemon-dev/daemon.c #3082) [Dec 13 10:46:53:798472] INFO: version v8.1.5
(/home/pilight/source/daemon-dev/libs/pilight/core/socket.c #168) [Dec 13 10:46:53:809179] INFO: daemon listening to port: 40279
(/home/pilight/source/daemon-dev/libs/pilight/core/socket.c #577) [Dec 13 10:46:53:813003] INFO: new client, ip: 127.0.0.1, port: 52354
(/home/pilight/source/daemon-dev/libs/pilight/core/webserver.c #1889) [Dec 13 10:46:53:822392] INFO: secured webserver started on port: 5002 (fd 16)
(/home/pilight/source/daemon-dev/libs/pilight/core/webserver.c #1892) [Dec 13 10:46:53:822494] INFO: regular webserver started on port: 5001 (fd 17)
(/home/pilight/source/daemon-dev/libs/pilight/events/events.c #2137) [Dec 13 10:46:53:930648] NOTICE: no pilight ssdp connections found
(/home/pilight/source/daemon-dev/libs/pilight/core/socket.c #577) [Dec 13 10:46:53:931199] INFO: new client, ip: 127.0.0.1, port: 52356
^^^^ client connected, service still running

Looks like the only difference between the autostart and manual start is the print of the timezone detection. Not sure if that helps somehow.

/var/log/pilight.err doesn't show any relevant messages.

Any input and things to try out would be great to get as I'd obviously like this to work directly after boot. I could probably try something like force a restart at the end of the boot sequence or somehow delay the start of the service, I just wanted to check if this might be an actual bug that should be fixed somewhere in the code.

Thanks!
Vrah

[curlymo]

Does the latest nightly have the same issue?

[VrahoK]

Stupid beginner question: Can I just install the latest nighly over the stable installation or do I need to clean something up first?

Code:

root@pilight:~# apt-get install pilight=8.1.5-68-gaca36192

[curlymo]

Yes

[VrahoK]

With the latest nightly the issue is gone but I see a high CPU load (~25%) compared to before (~0.5%).

I also saw that the issue was gone, after I installed piSchedule and it came back after disabling autostart on boot for piSchedule, which points towards a race condition or so.

Do you have a potential change in mind which may have fixed the issue and which I could manually apply on top of 8.1.5 stable so I don't have the issue with the CPU load? I am used to building from source.

Thanks!

[VrahoK]

Unfortunately it looks like after downgrading to 8.1.5 stable the issue with the CPU load persists, so maybe I do need to clean things up for downgrading.

[curlymo]

Before we point to pilight, please try temporarily test on a clean install with the latest nightly. The race condition is unknown to me.

[VrahoK]

Alright, 2 more observations:

1. I realized today that I am actually seeing exactly the same behavior on my Pi1B+ with 8.1.5 stable and latest clean Raspbian Buster lite. I did not yet get to test the latest nightly on that one, will try to do so in the next days.
   
2. The CPU load has settled. For 8.1.5 stable it is back to where it was (< 3%), for the latest nightly I'm actually seeing impressive < 0.1% load in idle state.
   

So this issue can probably be closed for now given that the nightly seems to resolve it and it seems to be usable for now. Do you keep track of known issues for the nightlies so I could check and see if I'd want to use that as the “productive“ version?

Thanks for the immediate support around this. I absolutely appreciate all the hard work that has gone into the project!

[VrahoK]

Well, I just saw one more thing that may actually be related to the CPU load being super low: I am using a date/time field in my config, which is also shown on the webgui. With 8.1.5 this is working, in the latest nightly this field stays blank for the first run directly after the boot. Starting the daemon in debug mode or restarting the service resolves the issue.

I'll look deeper into this in the next days but maybe this behavior is a remainder of the original issue...

[curlymo]

The pilight manual changelog is the place i normally keep track of improvements and bugfixes. And of course, for a more detailed list, you can check github.