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.

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

RC522 reads, but ID does not show in webinterface #1070

Closed
olli83 opened this issue Sep 28, 2020 · 5 comments
Closed

RC522 reads, but ID does not show in webinterface #1070

olli83 opened this issue Sep 28, 2020 · 5 comments

Comments

@olli83
Copy link

olli83 commented Sep 28, 2020

Bug

Hey! I am fairly new to the world of Raspberry and started this project for my little daughter.

I am using an RC522 RFID reader and initially had the issue described in #1001, but got that fixed. I wrote a script to test the reader separately to phoniebox and it works fine, so it does not appear to be incorrectly wired or have any libraries missing.

In the web interface of Phoniebox the ID field stays empty when I bring a tag close to the reader.

Any hints?

What I did

I installed the raspberry pi with above mentioned buster image and ran the installer script
Ran the steps to add an RC522 (libraries added and ran the steps described in the RC522 component readme)
Tested the RFID reader with a separate script
Fixed the issue described in #1001
Double checked java is enabled in browser displaying the web interface

What happened

No RFID ID showing up in web interface

The syslog usually notes that the channel for the RFID is already in use. Not sure if that is an issue. DId not do it this time when I created the log below.
There also appear to be some issues with MPD in the log and it states it failed to start. However, in other parts of the log it appears to be started.

At the moment there is a recurrent undervoltage issue, a new power supply is on order to fix this.

I am also surprised it takes 1m45s to start up. That appears to be rather long.

I expected this to happen

RFID ID number in web interface

Further information that might help

raspberrypi kernel: [   14.647094] Bluetooth: Core ver 2.22
Sep 28 12:38:57 raspberrypi kernel: [   14.647195] NET: Registered protocol family 31
Sep 28 12:38:57 raspberrypi kernel: [   14.647207] Bluetooth: HCI device and connection manager initialized
Sep 28 12:38:57 raspberrypi kernel: [   14.647235] Bluetooth: HCI socket layer initialized
Sep 28 12:38:57 raspberrypi kernel: [   14.647253] Bluetooth: L2CAP socket layer initialized
Sep 28 12:38:57 raspberrypi kernel: [   14.647288] Bluetooth: SCO socket layer initialized
Sep 28 12:38:57 raspberrypi kernel: [   14.660787] Bluetooth: HCI UART driver ver 2.3
Sep 28 12:38:57 raspberrypi kernel: [   14.660806] Bluetooth: HCI UART protocol H4 registered
Sep 28 12:38:57 raspberrypi kernel: [   14.660900] Bluetooth: HCI UART protocol Three-wire (H5) registered
Sep 28 12:38:57 raspberrypi kernel: [   14.661183] Bluetooth: HCI UART protocol Broadcom registered
Sep 28 12:38:57 raspberrypi btuart[401]: bcm43xx_init
Sep 28 12:38:57 raspberrypi btuart[401]: Flash firmware /lib/firmware/brcm/BCM43430A1.hcd
Sep 28 12:38:57 raspberrypi btuart[401]: Set BDADDR UART: b8:27:eb:cf:4e:f1
Sep 28 12:38:57 raspberrypi btuart[401]: Set Controller UART speed to 921600 bit/s
Sep 28 12:38:57 raspberrypi btuart[401]: Device setup complete
Sep 28 12:38:57 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status...
Sep 28 12:38:57 raspberrypi systemd[1]: Started Configure Bluetooth Modems connected by UART.
Sep 28 12:38:57 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status.
Sep 28 12:38:57 raspberrypi systemd[1]: Created slice system-bthelper.slice.
Sep 28 12:38:57 raspberrypi systemd[1]: Starting Bluetooth service...
Sep 28 12:38:57 raspberrypi bluetoothd[574]: Bluetooth daemon 5.50
Sep 28 12:38:57 raspberrypi systemd[1]: Started Bluetooth service.
Sep 28 12:38:57 raspberrypi bluetoothd[574]: Starting SDP server
Sep 28 12:38:57 raspberrypi systemd[1]: Started Raspberry Pi bluetooth helper.
Sep 28 12:38:57 raspberrypi systemd[1]: Reached target Bluetooth.
Sep 28 12:38:57 raspberrypi kernel: [   15.068994] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Sep 28 12:38:57 raspberrypi kernel: [   15.069011] Bluetooth: BNEP filters: protocol multicast
Sep 28 12:38:57 raspberrypi kernel: [   15.069042] Bluetooth: BNEP socket layer initialized
Sep 28 12:38:57 raspberrypi bluetoothd[574]: Bluetooth management interface 1.14 initialized
Sep 28 12:38:57 raspberrypi dbus-daemon[437]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.5' (uid=0 pid=574 comm="/usr/lib/bluetooth/bluetoothd ")
Sep 28 12:38:57 raspberrypi dhcpcd[403]: wlan0: rebinding lease of 192.168.178.83
Sep 28 12:38:57 raspberrypi bluetoothd[574]: Sap driver initialization failed.
Sep 28 12:38:57 raspberrypi bluetoothd[574]: sap-server: Operation not permitted (1)
Sep 28 12:38:57 raspberrypi bthelper[575]: Raspberry Pi BDADDR already set
Sep 28 12:38:58 raspberrypi systemd[1]: Starting Hostname Service...
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: probing address 192.168.178.83/24
Sep 28 12:38:58 raspberrypi bluetoothd[574]: Failed to set privacy: Rejected (0x0b)
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 UUIDs: 00001801-0000-1000-8000-00805f9b34fb
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 UUIDs: 00001200-0000-1000-8000-00805f9b34fb
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 UUIDs: 00001800-0000-1000-8000-00805f9b34fb
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 Alias: BlueZ 5.50
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 Pairable: yes
Sep 28 12:38:58 raspberrypi bthelper[575]: Changing power off succeeded
Sep 28 12:38:58 raspberrypi dbus-daemon[437]: [system] Successfully activated service 'org.freedesktop.hostname1'
Sep 28 12:38:58 raspberrypi systemd[1]: Started Hostname Service.
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 Name: raspberrypi
Sep 28 12:38:58 raspberrypi bthelper[575]: [#033[0;93mCHG#033[0m] Controller B8:27:EB:CF:4E:F1 Alias: BlueZ 5.50
Sep 28 12:38:58 raspberrypi bthelper[575]: Changing power on succeeded
Sep 28 12:38:58 raspberrypi systemd[1]: bthelper@hci0.service: Succeeded.
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: soliciting an IPv6 router
Sep 28 12:38:58 raspberrypi kernel: [   15.896243] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: Router Advertisement from fe80::7eff:4dff:fe95:2d8b
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: adding address 2a04:4540:6a2e:d000:a123:a4f9:72a5:24f2/64
Sep 28 12:38:58 raspberrypi avahi-daemon[391]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::b6e6:eb2c:9a6f:767a.
Sep 28 12:38:58 raspberrypi avahi-daemon[391]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2a04:4540:6a2e:d000:a123:a4f9:72a5:24f2.
Sep 28 12:38:58 raspberrypi avahi-daemon[391]: Registering new address record for 2a04:4540:6a2e:d000:a123:a4f9:72a5:24f2 on wlan0.*.
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: adding route to 2a04:4540:6a2e:d000::/64
Sep 28 12:38:58 raspberrypi avahi-daemon[391]: Withdrawing address record for fe80::b6e6:eb2c:9a6f:767a on wlan0.
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: requesting DHCPv6 information
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: fe80::7eff:4dff:fe95:2d8b is reachable again
Sep 28 12:38:58 raspberrypi dhcpcd[403]: wlan0: adding default route via fe80::7eff:4dff:fe95:2d8b
Sep 28 12:38:59 raspberrypi bash[414]: High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
Sep 28 12:38:59 raspberrypi bash[414]: #011version 1.25.10; written and copyright by Michael Hipp and others
Sep 28 12:38:59 raspberrypi bash[414]: #011free software (LGPL) without any warranty but with best wishes
Sep 28 12:38:59 raspberrypi bash[414]: Directory: /home/pi/RPi-Jukebox-RFID/shared/
Sep 28 12:38:59 raspberrypi bash[414]: Playing MPEG stream 1 of 1: startupsound.mp3 ...
Sep 28 12:38:59 raspberrypi bash[414]: MPEG 1.0 L III cbr64 44100 j-s
Sep 28 12:38:59 raspberrypi bash[414]: Artist:  Phoniebox
Sep 28 12:39:01 raspberrypi CRON[631]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Sep 28 12:39:02 raspberrypi systemd[1]: systemd-rfkill.service: Succeeded.
Sep 28 12:39:02 raspberrypi systemd[1]: Starting Clean php session files...
Sep 28 12:39:03 raspberrypi dhcpcd[403]: wlan0: leased 192.168.178.83 for 864000 seconds
Sep 28 12:39:03 raspberrypi avahi-daemon[391]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.83.
Sep 28 12:39:03 raspberrypi avahi-daemon[391]: New relevant interface wlan0.IPv4 for mDNS.
Sep 28 12:39:03 raspberrypi avahi-daemon[391]: Registering new address record for 192.168.178.83 on wlan0.IPv4.
Sep 28 12:39:03 raspberrypi dhcpcd[403]: wlan0: adding route to 192.168.178.0/24
Sep 28 12:39:03 raspberrypi dhcpcd[403]: wlan0: adding default route via 192.168.178.1
Sep 28 12:39:03 raspberrypi systemd[1]: phpsessionclean.service: Succeeded.
Sep 28 12:39:03 raspberrypi systemd[1]: Started Clean php session files.
Sep 28 12:39:04 raspberrypi dhcpcd[403]: forked to background, child pid 719
Sep 28 12:39:04 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Sep 28 12:39:04 raspberrypi systemd[1]: Reached target Network.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox GPIO Control Service.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox Idle Watchdog Service.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Sep 28 12:39:04 raspberrypi systemd[722]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Sep 28 12:39:04 raspberrypi systemd[722]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox RFID-Reader Service.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox GPIO Buttons Service.
Sep 28 12:39:04 raspberrypi systemd[1]: Starting Permit User Sessions...
Sep 28 12:39:04 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Sep 28 12:39:04 raspberrypi bash[414]: [0:04] Decoding of startupsound.mp3 finished.
Sep 28 12:39:04 raspberrypi systemd[1]: Reached target Network is Online.
Sep 28 12:39:04 raspberrypi systemd[1]: Starting LSB: exim Mail Transport Agent...
Sep 28 12:39:04 raspberrypi systemd[1]: Starting Lighttpd Daemon...
Sep 28 12:39:04 raspberrypi systemd[1]: Starting Samba NMB Daemon...
Sep 28 12:39:04 raspberrypi systemd[1]: Starting /etc/rc.local Compatibility...
Sep 28 12:39:04 raspberrypi systemd[1]: Starting Mopidy music server...
Sep 28 12:39:04 raspberrypi systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Permit User Sessions.
Sep 28 12:39:04 raspberrypi systemd[1]: Started /etc/rc.local Compatibility.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox Startup.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Mopidy music server.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Getty on tty1.
Sep 28 12:39:04 raspberrypi systemd[1]: Reached target Login Prompts.
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 1.
Sep 28 12:39:04 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Sep 28 12:39:04 raspberrypi systemd[750]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Sep 28 12:39:04 raspberrypi systemd[750]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Sep 28 12:39:04 raspberrypi systemd[1]: Started OpenBSD Secure Shell server.
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 2.
Sep 28 12:39:04 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Sep 28 12:39:04 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Sep 28 12:39:04 raspberrypi systemd[792]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Sep 28 12:39:04 raspberrypi systemd[792]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Sep 28 12:39:04 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 3.
Sep 28 12:39:05 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Sep 28 12:39:05 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Sep 28 12:39:05 raspberrypi systemd[861]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Sep 28 12:39:05 raspberrypi systemd[861]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 4.
Sep 28 12:39:05 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Sep 28 12:39:05 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Sep 28 12:39:05 raspberrypi systemd[949]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Sep 28 12:39:05 raspberrypi systemd[949]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Sep 28 12:39:05 raspberrypi PhonieboxGPIOControl[720]: INFO:root:['VolumeControl', 'PrevNextControl', 'PlayPause', 'Shutdown', 'Volume0', 'VolumeUp', 'VolumeDown', 'NextSong', 'PrevSong', 'Halt']
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:05 raspberrypi PhonieboxGPIOControl[720]: INFO:root:adding GPIO-Device, VolumeControl
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 5.
Sep 28 12:39:05 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Start request repeated too quickly.
Sep 28 12:39:05 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Sep 28 12:39:05 raspberrypi systemd[1]: Failed to start Phoniebox Rotary Encoder Service.
Sep 28 12:39:05 raspberrypi PhonieboxGPIOControl[720]: WARNING:root:Could not add Device VolumeControl with [('enabled', 'True'), ('type', 'TwoButtonControl ;or RotaryEncoder'), ('pinup', '5'), ('pindown', '6'), ('pull_up', 'True'), ('hold_time', '0.3'), ('hold_repeat', 'True'), ('timebase', '0.1 ;only for RotaryEncoder'), ('functioncalldown', 'functionCallVolD'), ('functioncallup', 'functionCallVolU'), ('functioncalltwobuttons', 'functionCallVol0 ;only for TwoButtonControl')]
Sep 28 12:39:05 raspberrypi PhonieboxGPIOControl[720]: INFO:root:adding GPIO-Device, PrevNextControl
Sep 28 12:39:05 raspberrypi PhonieboxGPIOControl[720]: INFO:root:adding TwoButtonControl
Sep 28 12:39:05 raspberrypi systemd[1]: Started Lighttpd Daemon.
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:GPIODevices.two_button_control:adding new action
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:GPIODevices.simple_button:{}: set when_pressed
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:GPIODevices.simple_button:add new action
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:GPIODevices.simple_button:{}: set when_pressed
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:GPIODevices.simple_button:add new action
Sep 28 12:39:06 raspberrypi systemd[1]: Started Samba NMB Daemon.
Sep 28 12:39:06 raspberrypi systemd[1]: Starting Samba SMB Daemon...
Sep 28 12:39:06 raspberrypi daemon_rfid_reader.py[726]: Please run RegisterDevice.py first
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:adding GPIO-Device, PlayPause
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Device Shutdown not enabled
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Device Volume0 not enabled
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Device VolumeUp not enabled
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Device VolumeDown not enabled
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Device NextSong not enabled
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Device PrevSong not enabled
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Device Halt not enabled
Sep 28 12:39:06 raspberrypi PhonieboxGPIOControl[720]: INFO:root:Ready for taking actions
Sep 28 12:39:06 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
Sep 28 12:39:06 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
Sep 28 12:39:06 raspberrypi exim4[731]: Starting MTA: exim4.
Sep 28 12:39:06 raspberrypi systemd[1]: Started LSB: exim Mail Transport Agent.
Sep 28 12:39:06 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:06 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 1.
Sep 28 12:39:06 raspberrypi systemd[1]: Stopped Phoniebox RFID-Reader Service.
Sep 28 12:39:06 raspberrypi systemd[1]: Started Phoniebox RFID-Reader Service.
Sep 28 12:39:07 raspberrypi daemon_rfid_reader.py[1139]: Please run RegisterDevice.py first
Sep 28 12:39:07 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
Sep 28 12:39:07 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
Sep 28 12:39:07 raspberrypi systemd[1]: Started Samba SMB Daemon.
Sep 28 12:39:07 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:07 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 2.
Sep 28 12:39:07 raspberrypi systemd[1]: Stopped Phoniebox RFID-Reader Service.
Sep 28 12:39:07 raspberrypi systemd[1]: Started Phoniebox RFID-Reader Service.
Sep 28 12:39:07 raspberrypi systemd[1]: Reached target Multi-User System.
Sep 28 12:39:07 raspberrypi systemd[1]: Reached target Graphical Interface.
Sep 28 12:39:07 raspberrypi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Sep 28 12:39:07 raspberrypi systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Sep 28 12:39:07 raspberrypi systemd[1]: Started Update UTMP about System Runlevel Changes.
Sep 28 12:39:07 raspberrypi systemd[1]: Startup finished in 3.457s (kernel) + 21.403s (userspace) = 24.861s.
Sep 28 12:39:08 raspberrypi daemon_rfid_reader.py[1151]: Please run RegisterDevice.py first
Sep 28 12:39:08 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
Sep 28 12:39:08 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
Sep 28 12:39:08 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:08 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 3.
Sep 28 12:39:08 raspberrypi systemd[1]: Stopped Phoniebox RFID-Reader Service.
Sep 28 12:39:08 raspberrypi systemd[1]: Started Phoniebox RFID-Reader Service.
Sep 28 12:39:08 raspberrypi dhcpcd[719]: wlan0: fe80::7eff:4dff:fe95:2d8b is reachable again
Sep 28 12:39:08 raspberrypi dhcpcd[719]: wlan0: fe80::7eff:4dff:fe95:2d8b is reachable again
Sep 28 12:39:09 raspberrypi daemon_rfid_reader.py[1157]: Please run RegisterDevice.py first
Sep 28 12:39:09 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
Sep 28 12:39:09 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
Sep 28 12:39:09 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:09 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 4.
Sep 28 12:39:09 raspberrypi systemd[1]: Stopped Phoniebox RFID-Reader Service.
Sep 28 12:39:09 raspberrypi systemd[1]: Started Phoniebox RFID-Reader Service.
Sep 28 12:39:10 raspberrypi daemon_rfid_reader.py[1183]: Please run RegisterDevice.py first
Sep 28 12:39:10 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
Sep 28 12:39:10 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
Sep 28 12:39:10 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 12:39:10 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 5.
Sep 28 12:39:10 raspberrypi systemd[1]: Stopped Phoniebox RFID-Reader Service.
Sep 28 12:39:10 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Start request repeated too quickly.
Sep 28 12:39:10 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
Sep 28 12:39:10 raspberrypi systemd[1]: Failed to start Phoniebox RFID-Reader Service.
Sep 28 12:39:12 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.__main__ Starting Mopidy 3.0.2
Sep 28 12:39:12 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.config Loading config from builtin defaults
Sep 28 12:39:12 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy-local.conf
Sep 28 12:39:12 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy.conf
Sep 28 12:39:12 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.config Loading config from file:///etc/mopidy/mopidy.conf
Sep 28 12:39:12 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.config Loading config from command line options
Sep 28 12:39:12 raspberrypi mopidy[745]: ERROR    [MainThread] mopidy.internal.log Loading logging config '/etc/mopidy/logging.conf' failed. 'formatters'
Sep 28 12:39:13 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.__main__ Enabled extensions: stream, spotify, iris, file, m3u, mpd, softwaremixer, mopify, local, http
Sep 28 12:39:13 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.__main__ Disabled extensions: none
Sep 28 12:39:14 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.commands Starting Mopidy mixer: SoftwareMixer
Sep 28 12:39:14 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.commands Mixer volume set to 30
Sep 28 12:39:14 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.commands Starting Mopidy audio
Sep 28 12:39:14 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.commands Starting Mopidy backends: FileBackend, M3UBackend, StreamBackend, SpotifyBackend, LocalBackend
Sep 28 12:39:14 raspberrypi mopidy[745]: INFO     [Audio-2] mopidy.audio.actor Audio output set to "alsasink"
Sep 28 12:39:16 raspberrypi mopidy[745]: INFO     [SpotifyBackend-6] mopidy_spotify.web Logged into Spotify Web API as olliinhamburg
Sep 28 12:39:16 raspberrypi mopidy[745]: INFO     [SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in online mode
Sep 28 12:39:21 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Sep 28 12:39:34 raspberrypi systemd-timesyncd[349]: Synchronized to time server for the first time [2a04:d140::3]:123 (2.debian.pool.ntp.org).
Sep 28 12:39:40 raspberrypi systemd[1]: systemd-hostnamed.service: Succeeded.
Sep 28 12:40:16 raspberrypi systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
Sep 28 12:40:21 raspberrypi mopidy[745]: INFO     [SpotifyBackend-6] mopidy_spotify.playlists Refreshed 40 Spotify playlists
Sep 28 12:40:21 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.commands Starting Mopidy core
Sep 28 12:40:21 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.commands Starting Mopidy frontends: HttpFrontend, QueueManagerFrontend, IrisFrontend, MpdFrontend
Sep 28 12:40:21 raspberrypi mopidy[745]: INFO     [HttpFrontend-12] mopidy.http.actor HTTP server running at [::ffff:0.0.0.0]:6680
Sep 28 12:40:21 raspberrypi mopidy[745]: INFO     [IrisFrontend-14] mopidy_iris.core Starting Iris 3.45.0
Sep 28 12:40:21 raspberrypi mopidy[745]: INFO     [MainThread] mopidy_mpd.actor MPD server running at [::ffff:0.0.0.0]:6600
Sep 28 12:40:21 raspberrypi mopidy[745]: INFO     [MainThread] mopidy.commands Starting GLib mainloop
Sep 28 12:40:37 raspberrypi kernel: [  102.474989] Voltage normalised (0x00000000)
Sep 28 12:40:41 raspberrypi kernel: [  106.634931] Under-voltage detected! (0x00050005)
Sep 28 12:40:47 raspberrypi kernel: [  112.874853] Voltage normalised (0x00000000)
Sep 28 12:41:13 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Sep 28 12:41:13 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Sep 28 12:41:13 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Sep 28 12:41:13 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Sep 28 12:41:14 raspberrypi systemd[1218]: Listening on GnuPG cryptographic agent and passphrase cache.
Sep 28 12:41:14 raspberrypi systemd[1218]: Starting D-Bus User Message Bus Socket.
Sep 28 12:41:14 raspberrypi systemd[1218]: Reached target Paths.
Sep 28 12:41:14 raspberrypi systemd[1218]: Listening on GnuPG network certificate management daemon.
Sep 28 12:41:14 raspberrypi systemd[1218]: Reached target Timers.
Sep 28 12:41:14 raspberrypi systemd[1218]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Sep 28 12:41:14 raspberrypi systemd[1218]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Sep 28 12:41:14 raspberrypi systemd[1218]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Sep 28 12:41:14 raspberrypi systemd[1218]: Listening on D-Bus User Message Bus Socket.
Sep 28 12:41:14 raspberrypi systemd[1218]: Reached target Sockets.
Sep 28 12:41:14 raspberrypi systemd[1218]: Reached target Basic System.
Sep 28 12:41:14 raspberrypi systemd[1]: Started User Manager for UID 1000.
Sep 28 12:41:14 raspberrypi systemd[1218]: Starting Music Player Daemon...
Sep 28 12:41:14 raspberrypi systemd[1]: Started Session c1 of user pi.
Sep 28 12:41:14 raspberrypi kernel: [  139.914829] Under-voltage detected! (0x00050005)
Sep 28 12:41:17 raspberrypi mpd[1231]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
Sep 28 12:41:17 raspberrypi systemd[1218]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Sep 28 12:41:17 raspberrypi systemd[1218]: mpd.service: Failed with result 'exit-code'.
Sep 28 12:41:17 raspberrypi systemd[1218]: Failed to start Music Player Daemon.
Sep 28 12:41:17 raspberrypi systemd[1218]: Reached target Default.
Sep 28 12:41:17 raspberrypi systemd[1218]: Startup finished in 3.814s.
Sep 28 12:41:35 raspberrypi kernel: [  160.714982] Voltage normalised (0x00000000)
Sep 28 12:44:11 raspberrypi kernel: [  316.715353] rpi_firmware_get_throttled: 4 callbacks suppressed
Sep 28 12:44:11 raspberrypi kernel: [  316.715362] Under-voltage detected! (0x00050005)
Sep 28 12:44:49 raspberrypi kernel: [  354.155417] Under-voltage detected! (0x00050005)
Sep 28 12:45:18 raspberrypi kernel: [  383.275486] Under-voltage detected! (0x00050005)
Sep 28 12:46:08 raspberrypi kernel: [  433.195520] rpi_firmware_get_throttled: 7 callbacks suppressed
Sep 28 12:46:08 raspberrypi kernel: [  433.195529] Voltage normalised (0x00000000)
Sep 28 12:46:33 raspberrypi kernel: [  458.155532] Voltage normalised (0x00000000)
Sep 28 12:46:53 raspberrypi kernel: [  478.955610] Voltage normalised (0x00000000)

Software

Phoniebox 2.0

Base image and version

Current Buster Lite

Branch / Release

Master branch

Installscript

Used the install script for Phoniebox.

Hardware

RaspberryPi version

Model 3 B

RFID Reader

The RC522 RFID reader linked in the "shopping list" section

Soundcard

none

Other notable hardware

none

@olli83 olli83 added the bug label Sep 28, 2020
@olli83
Copy link
Author

olli83 commented Sep 28, 2020

Played around a bit further and found the reader service is not active. On retrospect I now also see that in the log above.

phoniebox-rfid-reader.service - Phoniebox RFID-Reader Service
   Loaded: loaded (/etc/systemd/system/phoniebox-rfid-reader.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Mon 2020-09-28 13:35:47 BST; 17min ago
  Process: 1359 ExecStart=/home/pi/RPi-Jukebox-RFID/scripts/daemon_rfid_reader.py (code=exited, status=1/FAILURE)
 Main PID: 1359 (code=exited, status=1/FAILURE)

Sep 28 13:35:47 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 13:35:47 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 5.
Sep 28 13:35:47 raspberrypi systemd[1]: Stopped Phoniebox RFID-Reader Service.
Sep 28 13:35:47 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Start request repeated too quickly.
Sep 28 13:35:47 raspberrypi systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
Sep 28 13:35:47 raspberrypi systemd[1]: Failed to start Phoniebox RFID-Reader Service.

I started it manually and shows active now. However, the original issue does not appear solved.

@stundenblume
Copy link

stundenblume commented Oct 5, 2020

@olli83
I had to do this (27.09.20):

  1. SPI activation (sudo raspi-config)

  2. sudo python3 -m pip install --upgrade --force-reinstall -r /home/pi/RPi-Jukebox-RFID/components/rfid-reader/PN532/requirements.txt
    Reference: RC522 module #11 (comment)

  3. sudo sh RPi-Jukebox-RFID/components/rfid-reader/RC522/setup_rc522.sh
    Reference: RC522 module #11 (comment)

@s-martin
Copy link
Collaborator

s-martin commented Oct 5, 2020

As @stundenblume said, please try

sudo sh RPi-Jukebox-RFID/components/rfid-reader/RC522/setup_rc522.sh

This should be sufficient, the script is supposed to do all the manual steps described.

@Erechtheus
Copy link

Hey folks! I recently (today) stumbled across the same issue. For me there was a missing dependency (i.e., py532lib) in the Reader.py.experimental script. So for me the script mentioned by @s-martin did not work!
This fixed my issue:
pip3 install py532lib

@olli83
Copy link
Author

olli83 commented Oct 11, 2020

I have commented out the py532lib references in the script, so this should not have been the issue. I started from scratch again to set up the RC522 standalone with some online tutorials. It worked and afterwards it also worked with the Phoniebox. I must have made a mistake somewhere along the line though I am not sure were.

Thanks for the support and also for removing the bug label. When starting a new thread it is not possible to assign any other label to it.

@olli83 olli83 closed this as completed Oct 11, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants