Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

No updates when running "in background" #98

Closed
2 tasks done
aebgit opened this issue Apr 28, 2023 · 9 comments
Closed
2 tasks done

No updates when running "in background" #98

aebgit opened this issue Apr 28, 2023 · 9 comments
Assignees
@ironsheep
Labels
duplicate This issue or pull request already exists Solution Provided Community provided a solution as comments to issue

Comments

@aebgit
Copy link

aebgit commented Apr 28, 2023 •
edited
Loading

Checklist:

  • I updated to the latest version available
  • I checked that my MQTT broker is otherwise working

Release with the issue:
[2023-04-28 14:00:16] - ISP-RPi-mqtt-daemon.py v1.8.4

Last working release (if known):
n/a

Hardware, Operating System, Python version:

  • Raspberry Pi 4 Modell B; 4 GB, ARM-Cortex-A72 4 x, 1,50 GHz, 4 GB RAM
# uname -a
Raspberry Pi 4 Modell B; 4 GB, ARM-Cortex-A72 4 x, 1,50 GHz, 4 GB RAM

# cat /etc/debian_version 
11.6

# cat /etc/os-release 
PRETTY_NAME="Raspbian GNU/Linux 11 (bullseye)"
NAME="Raspbian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"
VERSION_CODENAME=bullseye
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Description of problem:

I run 5 Raspis with RPi-Reporter-MQTT2HA-Daemon in a plain network connected to Mosquitto broker and then to Homeassistant.
I followed the installation guidelines straight forward and experienced no problems at all.

Four of them work fine, one has an issue. When I start the script manually via shell as unprivileged user or via sudo , it runs without problems:
# python3 /opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py.

However, the moment I start the script via systemctl, the following happens:

  • the first set of telemetry is sent to the MQTT broker
  • after that, there is NO other refresh of the information.
  • The process is still alive (#ps -fax)

As a workaround I disabled it in systemctl and have added it to roots crontab, but the issue remained.
@reboot /usr/bin/python3 -u /opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py

I have also started it on a shell with debugging and verbose logging enabled, but could not spot any issues.
sudo python3 /opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py -d -v
...the only curious line I could find is this one, which appears occasionally in a different color:
[2023-04-28 14:00:19] - << INTR(0) >> Time to report! (14:00:19 - 2023/04/28)

Run our report script 'genBugInfo' on your failing device and include the output here:

# SCRIPT genBugInfo v1.1 run 23/04/28-14:16:54
# ----------------------------------------------------------------------

# /bin/cat /etc/apt/sources.list | /bin/egrep -v '#'
  
deb http://raspbian.raspberrypi.org/raspbian/ bullseye main contrib non-free rpi

 ----

# /bin/cat /etc/apt/sources.list | /bin/egrep -v '#' | /usr/bin/awk '{ print $3 }' | /bin/grep . | /usr/bin/sort -u | head -1
  
bullseye

 ----

# /bin/uname -r
  
6.1.21-v8+

 ----

# /bin/hostname -f
  
display1

 ----

# /usr/bin/uptime
  
 14:16:54 up 11:16,  3 users,  load average: 0.19, 0.25, 0.21

 ----

# /sbin/ifconfig
  
br-e454e7933844: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.0.0  broadcast <redacted>
        inet6 <redacted>  prefixlen 64  scopeid 0x20<link>
        ether <redacted>  txqueuelen 0  (Ethernet)
        RX packets 124251  bytes 11953095 (11.3 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 260768  bytes 347705178 (331.5 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

docker0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.0.0  broadcast <redacted>
        ether <redacted>  txqueuelen 0  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

eth0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether <redacted>  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet 127.0.0.1  netmask 255.0.0.0
        inet6 ::1  prefixlen 128  scopeid 0x10<host>
        loop  txqueuelen 1000  (Local Loopback)
        RX packets 6508  bytes 631412 (616.6 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 6508  bytes 631412 (616.6 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

veth4c9b962: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.0.0  broadcast <redacted>
        inet6 <redacted>  prefixlen 64  scopeid 0x20<link>
        ether <redacted>  txqueuelen 0  (Ethernet)
        RX packets 124213  bytes 13686696 (13.0 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 261413  bytes 347910389 (331.7 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.255.0  broadcast <redacted>
        inet6 <redacted>  prefixlen 64  scopeid 0x0<global>
        inet6 <redacted>  prefixlen 64  scopeid 0x20<link>
        ether <redacted>  txqueuelen 1000  (Ethernet)
        RX packets 573845  bytes 441732653 (421.2 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 142838  bytes 17020364 (16.2 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0


 ----

# /sbin/ifconfig | /bin/egrep 'Link|flags|inet|ether' | /bin/egrep -v -i 'lo:|loopback|inet6|\:\:1|127\.0\.0\.1'
  
br-e454e7933844: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.0.0  broadcast <redacted>
        ether <redacted>  txqueuelen 0  (Ethernet)
docker0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.0.0  broadcast <redacted>
        ether <redacted>  txqueuelen 0  (Ethernet)
eth0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether <redacted>  txqueuelen 1000  (Ethernet)
veth4c9b962: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.0.0  broadcast <redacted>
        ether ea:af:32:f6:f8:e4  txqueuelen 0  (Ethernet)
wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet <redacted>  netmask 255.255.255.0  broadcast <redacted>
        ether e4:5f:01:f3:71:30  txqueuelen 1000  (Ethernet)

 ----

# /sbin/route
  
Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
default         <redacted> 0.0.0.0         UG    303    0        0 wlan0
link-local      0.0.0.0         255.255.0.0     U     209    0        0 veth4c9b962
172.17.0.0      0.0.0.0         255.255.0.0     U     0      0        0 docker0
172.18.0.0      0.0.0.0         255.255.0.0     U     0      0        0 br-e454e7933844
192.168.178.0   0.0.0.0         255.255.255.0   U     303    0        0 wlan0

 ----

# /bin/ls -l /var/log/dpkg.log /var/log/dpkg.log.1 2>/dev/null
  
-rw-r--r-- 1 root root 45433 Apr 16 13:01 /var/log/dpkg.log
-rw-r--r-- 1 root root  6847 Mar  2 19:36 /var/log/dpkg.log.1

 ----

# /bin/grep 'status installed' /var/log/dpkg.log /var/log/dpkg.log.1 2>/dev/null | sort | tail -1
  
/var/log/dpkg.log:2023-04-16 13:01:02 status installed mailcap:all 3.69

 ----

# /bin/df -m
  
Filesystem     1M-blocks  Used Available Use% Mounted on
/dev/root          29644  6969     21418  25% /
devtmpfs            1640     0      1640   0% /dev
tmpfs               1898     0      1898   0% /dev/shm
tmpfs                759     2       758   1% /run
tmpfs                  5     1         5   1% /run/lock
/dev/mmcblk0p1       255    52       204  21% /boot
tmpfs                380     1       380   1% /run/user/1000

 ----

# /bin/df -m | /usr/bin/tail -n +2 | /bin/egrep -v 'tmpfs|boot'
  
/dev/root          29644  6969     21418  25% /

 ----

# ls -l /opt/vc/bin/vcgencmd /usr/bin/vcgencmd
  
ls: cannot access '/opt/vc/bin/vcgencmd': No such file or directory
-rwxr-xr-x 1 root root 13948 Mar 22 17:33 /usr/bin/vcgencmd

 ----

Python errors shown in the logs (if applicable):

Additional information:
@aebgit aebgit added the bug Something isn't working label Apr 28, 2023
@aebgit
Copy link
Author

aebgit commented Apr 28, 2023

...should have done this earlier. Here is some additional detail from journalctl -b --no-pager -u isp-rpi-reporter.service , but I have difficulties interpreting it:

Apr 28 13:38:16 display1 systemd[1]: isp-rpi-reporter.service: Succeeded.
Apr 28 13:38:16 display1 systemd[1]: isp-rpi-reporter.service: Consumed 15.902s CPU time.
Apr 28 13:38:19 display1 systemd[1]: isp-rpi-reporter.service: Scheduled restart job, restart counter is at 4.
Apr 28 13:38:19 display1 systemd[1]: Stopped RPi Reporter MQTT Client/Daemon.
Apr 28 13:38:19 display1 systemd[1]: isp-rpi-reporter.service: Consumed 15.902s CPU time.
Apr 28 13:38:19 display1 systemd[1]: Starting RPi Reporter MQTT Client/Daemon...
Apr 28 13:38:23 display1 systemd[1]: Started RPi Reporter MQTT Client/Daemon.
Apr 28 13:38:24 display1 python3[16402]: Traceback (most recent call last):
Apr 28 13:38:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 1809, in <module>
Apr 28 13:38:24 display1 python3[16402]:     afterMQTTConnect()  # now instead of after?
Apr 28 13:38:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 1799, in afterMQTTConnect
Apr 28 13:38:24 display1 python3[16402]:     handle_interrupt(0)
Apr 28 13:38:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 1782, in handle_interrupt
Apr 28 13:38:24 display1 python3[16402]:     update_values()
Apr 28 13:38:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 1763, in update_values
Apr 28 13:38:24 display1 python3[16402]:     getSystemTemperature()
Apr 28 13:38:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 968, in getSystemTemperature
Apr 28 13:38:24 display1 python3[16402]:     interpretedTemp = float(rpi_gpu_temp_raw)
Apr 28 13:38:24 display1 python3[16402]: ValueError: could not convert string to float: "Can't open device file: /dev/vcio\nTry creating a device file with: sudo mknod /dev/vcio c 100 0"
Apr 28 13:43:24 display1 python3[16402]: Exception in thread Thread-5:
Apr 28 13:43:24 display1 python3[16402]: Traceback (most recent call last):
Apr 28 13:43:24 display1 python3[16402]:   File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
Apr 28 13:43:24 display1 python3[16402]:     self.run()
Apr 28 13:43:24 display1 python3[16402]:   File "/usr/lib/python3.9/threading.py", line 1266, in run
Apr 28 13:43:24 display1 python3[16402]:     self.function(*self.args, **self.kwargs)
Apr 28 13:43:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 1490, in periodTimeoutHandler
Apr 28 13:43:24 display1 python3[16402]:     handle_interrupt(TIMER_INTERRUPT)  # '0' means we have a timer interrupt!!!
Apr 28 13:43:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 1782, in handle_interrupt
Apr 28 13:43:24 display1 python3[16402]:     update_values()
Apr 28 13:43:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 1763, in update_values
Apr 28 13:43:24 display1 python3[16402]:     getSystemTemperature()
Apr 28 13:43:24 display1 python3[16402]:   File "/opt/RPi-Reporter-MQTT2HA-Daemon/ISP-RPi-mqtt-daemon.py", line 968, in getSystemTemperature
Apr 28 13:43:24 display1 python3[16402]:     interpretedTemp = float(rpi_gpu_temp_raw)
Apr 28 13:43:24 display1 python3[16402]: ValueError: could not convert string to float: "Can't open device file: /dev/vcio\nTry creating a device file with: sudo mknod /dev/vcio c 100 0"

@jandamf
Copy link

jandamf commented Apr 30, 2023

I should have checked the list before upgrading. I am now having the same problem after updating to latest version.

I was 3 versions back and worked ok.

@ornative
Copy link

I am having the same issue on the same platform on both .83 and .84. Runs fine when started interactively, but has the same problem shown in the journalctl shown above.

@ironsheep ironsheep self-assigned this Apr 30, 2023
@ironsheep
Copy link
Owner

ironsheep commented Apr 30, 2023 •
edited
Loading

@jandamf and @ornative something we don't understand but seems to be happening is that the daemon user appears to be having permissions reset when the OS update happened. As a result, the fix is to apply once again the permissions needed to run the script. (please let me know if this solves your problem.)

Here's my response to duplicate issue #94:

Since the errors you show appear to be access to temps can you please recheck that your daemon account has the correct permissions?
https://github.com/ironsheep/RPi-Reporter-MQTT2HA-Daemon#set-up-daemon-account-to-allow-access-to-temperature-values

(Since you can run interactively, it seems to be an issue with the Daemon account.)

@ironsheep ironsheep added Solution Provided Community provided a solution as comments to issue duplicate This issue or pull request already exists and removed bug Something isn't working labels Apr 30, 2023
@jandamf
Copy link

jandamf commented Apr 30, 2023

@ironsheep

Thanks for the suggestion. I re-applied the permissions and that solved the problem.

@ornative
Copy link

That did correct the problem. Interesting, would be nice to know what element in the update is messing with the permissions.

@ironsheep
Copy link
Owner

Yep, if we ever find out I'll post more in these closed issues...

@aebgit
Copy link
Author

aebgit commented May 1, 2023

Solved. Thank you!!

@frennkie frennkie mentioned this issue Jan 7, 2024
Open
@xstrex
Copy link

xstrex commented Jan 16, 2024

I know this issue is closed, but could someone please tell me what their permissions are on /dev/vcio I'm running this in dietpi, and /dev/vcio exists, but has perms of crw------- 1 root root 10, 125 Jan 16 14:20 /dev/vcio. I suspect others are seeing root:video. Before I chase this down with dietpi, what's the output of ls -hl /dev/vcio?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ironsheep ironsheep

Labels
duplicate This issue or pull request already exists Solution Provided Community provided a solution as comments to issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@ironsheep @xstrex @aebgit @ornative @jandamf