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

🐛 | RC522 irq not working properly #2387

Open
damaev opened this issue Jun 20, 2024 · 10 comments
Open

🐛 | RC522 irq not working properly #2387

damaev opened this issue Jun 20, 2024 · 10 comments
Labels
bug future3 Relates to future3 development needs triage

Comments

@damaev
Copy link
Contributor

damaev commented Jun 20, 2024 •
edited
Loading

Version

3.5.3

Branch

"future3/main", "v2/main"

OS

Bullseye lite 32bit

Pi model

Zero 2w

Hardware

Mfrc522

What happened?

The Reader is reading just from time to time, so it sometimes takes a looong time to read a card. Sometimes its fast.
I started having this issue after upgrading to a zero2 with some v3 Version half a year ago. Now i found the time to dig into it. Restarting with a plan v2 Version. Still haveing the issue.

What I tied:
Checking the soldering -> unchanged
Stopping almost all jobs -> unchanged
Starting daemon by hand -> rst pin already in use -> change to unused -> issue persists
Using my previous Version of phoniebox v2 from. 2 years ago -> issue persists
trying v3 with bullseye instead of bookworm -> issue persists

During that time I got the feeling the irq is not working.
Changing irq pin -> issue persists
Reading irq pin by hand -> interrupts appear randomly -> changing mfrc522 board -> interrupts appear randomly -> issue persists
Changing cables - issue persists

I got the feeling that for some reason, the irq is not working (maybe anymore) as planned by the designer of the underlying rc522.py library
Using another library without irq -> uid is read at hand

Digging into the Reader component of phoniebox again, I commented out the line "self.waiting_for_tag()"
Now I directly get the uid. -> ISSUE SOLVED

However, y am I the only one with this issue?
Will it cause more trouble?
Should an option "skip_irq" for rc522 readers be integrated.

Maybe someone has the time and hardware to dig into it.

Logs

No response

Configuration

No response

More info

issue solved but see above
@damaev damaev added bug future3 Relates to future3 development needs triage labels Jun 20, 2024
@s-martin
Copy link
Collaborator

Can you post the log here?

@damaev
Copy link
Contributor Author

damaev commented Jun 20, 2024

the error.log is empty. the app.log1 showing the delay between reading a card beeing in place all the time:

20.06.2024 16:06:03 -   19:readerbase.py      - jb.rfid.522(read_00) - read_00Thread   - INFO     - Initializing reader 'MFRC522 via SPI' from '/home/pi/RPi-Jukebox-RFID/src/jukebox/components/rfid/hardware/rc522_spi/rc522_spi.py'
20.06.2024 16:06:03 -   20:readerbase.py      - jb.rfid.522(read_00) - read_00Thread   - DEBUG    - Reader object is <components.rfid.hardware.rc522_spi.rc522_spi.ReaderClass object at 0x61b31bf8> for reader config key 'read_00'
20.06.2024 16:06:03 -   78:rc522_spi.py       - jb.rfid.522(read_00) - read_00Thread   - INFO     - Using legacy_mode = 'False'
20.06.2024 16:06:06 -  695:plugs.py           - jb.plugin.call       - StartJingle     - DEBUG    - Calling: volume.ctrl.set_volume(args=[40], kwargs=None)
20.06.2024 16:06:12 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:06:14 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:07:02 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': 'b4c4cc0c-96e1-46b0-9dc6-4bcd36e66ce1', 'package': 'cards', 'plugin': 'list_cards', 'method': None, 'kwargs': {}}
20.06.2024 16:07:02 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: cards.list_cards(args=(), kwargs={})
20.06.2024 16:07:02 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {}, 'id': 'b4c4cc0c-96e1-46b0-9dc6-4bcd36e66ce1'}
20.06.2024 16:07:48 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:07:48 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:08:06 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:08:06 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:08:42 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:08:42 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:08:55 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:08:55 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:09:28 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:09:28 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:10:00 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:10:00 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:10:13 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:10:13 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:10:44 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:10:44 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:11:18 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:11:18 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:11:37 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:11:37 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:11:54 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:11:54 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:12:13 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:12:13 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:13:26 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:13:26 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:13:47 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:13:47 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:14:07 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:14:07 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:14:28 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:14:28 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:14:49 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:14:49 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:15:37 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:15:37 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:15:54 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '75cb3abe-6079-4fc4-85d9-1e9644016f24', 'package': 'cards', 'plugin': 'list_cards', 'method': None, 'kwargs': {}}
20.06.2024 16:15:54 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: cards.list_cards(args=(), kwargs={})
20.06.2024 16:15:54 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {}, 'id': '75cb3abe-6079-4fc4-85d9-1e9644016f24'}
20.06.2024 16:15:56 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:15:56 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:15:59 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '3d572116-124b-4c86-ba62-0d1d7c565bcc', 'package': 'cards', 'plugin': 'list_cards', 'method': None, 'kwargs': {}}
20.06.2024 16:15:59 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: cards.list_cards(args=(), kwargs={})
20.06.2024 16:15:59 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {}, 'id': '3d572116-124b-4c86-ba62-0d1d7c565bcc'}
20.06.2024 16:16:15 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:16:15 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:16:35 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:16:35 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:16:55 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:16:55 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:17:15 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:17:15 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:17:37 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:17:37 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:17:58 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:17:58 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:18:18 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:18:18 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:19:04 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:19:04 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:19:23 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:19:23 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:19:42 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:19:42 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:20:02 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 16:20:02 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.started_at'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.version'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.temperature.cpu'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.timer.cputemp'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'playerstatus'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'rfid.card_id'
20.06.2024 16:20:39 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'volume.level'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.started_at'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.version'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.temperature.cpu'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.timer.cputemp'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'playerstatus'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'rfid.card_id'
20.06.2024 16:20:40 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'volume.level'
20.06.2024 16:20:41 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 16:20:41 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'

and after the change

20.06.2024 20:47:31 -   41:daemon.py          - jb.daemon            - MainThread      - INFO     - Starting Jukebox Daemon (Version 3.5.3)
20.06.2024 20:47:32 -   44:daemon.py          - jb.daemon            - MainThread      - INFO     - Git state: 0ab75c1d [2024-04-17] hotfix pyzmq installation on bullseye (pin version <26) (#2345)  (HEAD -> future3/main, tag: v3.5.3, origin/future3/main) [v3.5.3-dirty]
20.06.2024 20:47:32 -  318:cfghandler.py      - jb.cfghandler        - MainThread      - INFO     - (jukebox) Loading yaml file '/home/pi/RPi-Jukebox-RFID/shared/settings/jukebox.yaml'
20.06.2024 20:47:32 -  230:cfghandler.py      - jb.cfghandler        - MainThread      - DEBUG    - (jukebox) Replacing current config data
20.06.2024 20:47:32 -   53:daemon.py          - jb.daemon            - MainThread      - INFO     - Welcome to Jukebox
20.06.2024 20:47:32 -   54:daemon.py          - jb.daemon            - MainThread      - INFO     - Time of start: Thu Jun 20 20:47:31 2024
20.06.2024 20:47:32 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.publishing' as 'publishing'
20.06.2024 20:47:32 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.publishing.republish' as 'publishing.republish' (<class 'function'>)
20.06.2024 20:47:32 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling publishing.initialize()
20.06.2024 20:47:32 -  225:server.py          - jb.pub.server        - MainThread      - DEBUG    - PublishServer initialized (Pyzmq version: 25.1.2; ZMQ version: 4.3.5; has draft API: True)
20.06.2024 20:47:32 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.volume' as 'volume'
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.toggle_output
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.get_outputs
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.publish_volume
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.publish_outputs
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.set_volume
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.get_volume
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.change_volume
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.get_mute
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.mute
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.set_output
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.set_soft_max_volume
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PulseVolumeControl.get_soft_max_volume
20.06.2024 20:47:33 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling volume.initialize()
20.06.2024 20:47:33 -  250:__init__.py        - jb.pulse             - PulseMon        - INFO     - Start Pulse Monitor Thread
20.06.2024 20:47:33 -  613:__init__.py        - jb.pulse             - MainThread      - INFO     - Ignoring secondary audio output configuration because it is missing or incomplete
20.06.2024 20:47:33 -  352:__init__.py        - jb.pulse             - MainThread      - DEBUG    - Configured audio sinks: [PaSink(alias='Built-in speakers', pulse_sink_name='auto_null', volume_limit=100)]
20.06.2024 20:47:33 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.jingle' as 'jingle'
20.06.2024 20:47:33 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.jingle.play' as 'jingle.play' (<class 'function'>)
20.06.2024 20:47:33 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.jingle.play_startup' as 'jingle.play_startup' (<class 'function'>)
20.06.2024 20:47:33 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.jingle.play_shutdown' as 'jingle.play_shutdown' (<class 'function'>)
20.06.2024 20:47:33 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling jingle.initialize()
20.06.2024 20:47:33 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.jingle.alsawave' as 'jingle.alsawave'
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging AlsaWave.play
20.06.2024 20:47:33 -  318:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Decorating class components.jingle.alsawave.AlsaWave for auto-assignment into package 'jingle.alsawave'
20.06.2024 20:47:33 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling jingle.alsawave.initialize()
20.06.2024 20:47:33 -  337:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Instantiating decorated class 'components.jingle.alsawave.AlsaWave' and register as 'jingle.alsawave.alsawave'
20.06.2024 20:47:33 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'components.jingle.alsawave.AlsaWave' as 'jingle.alsawave.alsawave'
20.06.2024 20:47:33 -   24:__init__.py        - jb.jingle            - MainThread      - DEBUG    - Register 'wav' in <class 'components.jingle.JingleFactory'>.
20.06.2024 20:47:33 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.jingle.jinglemp3' as 'jingle.jinglemp3'
20.06.2024 20:47:33 -  318:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Decorating class components.jingle.jinglemp3.JingleMp3Play for auto-assignment into package 'jingle.jinglemp3'
20.06.2024 20:47:33 -  344:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Auto-tagging all methods and functions of class 'components.jingle.jinglemp3.JingleMp3Play'
20.06.2024 20:47:33 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling jingle.jinglemp3.initialize()
20.06.2024 20:47:33 -  337:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Instantiating decorated class 'components.jingle.jinglemp3.JingleMp3Play' and register as 'jingle.jinglemp3.jinglemp3'
20.06.2024 20:47:33 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'components.jingle.jinglemp3.JingleMp3Play' as 'jingle.jinglemp3.jinglemp3'
20.06.2024 20:47:33 -   24:__init__.py        - jb.jingle            - MainThread      - DEBUG    - Register 'mp3' in <class 'components.jingle.JingleFactory'>.
20.06.2024 20:47:33 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.playermpd' as 'player'
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.start
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.cancel
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.toggle
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.trigger
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.is_alive
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.get_timeout
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.set_timeout
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.publish
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericTimerClass.get_state
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericMultiTimerClass.start
20.06.2024 20:47:33 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging GenericMultiTimerClass.get_state
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.get_player_type_and_version
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.update
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.update_wait
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.play
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.stop
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.pause
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.prev
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.next
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.seek
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.rewind
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.replay
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.toggle
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.replay_if_stopped
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.shuffle
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.repeat
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.get_current_song
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.map_filename_to_playlist_pos
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.remove
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.move
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.play_single
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.resume
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.play_card
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.get_single_coverart
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.get_album_coverart
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.get_folder_content
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.play_folder
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.play_album
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.queue_load
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.playerstatus
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.playlistinfo
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.list_all_dirs
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.list_albums
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.list_songs_by_artist_and_album
20.06.2024 20:47:34 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging PlayerMPD.get_song_by_url
20.06.2024 20:47:34 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling player.initialize()
20.06.2024 20:47:34 -  169:__init__.py        - jb.PlayerMPD         - MainThread      - INFO     - Connected to MPD Version: 0.22.4
20.06.2024 20:47:34 -  202:multitimer.py      - jb.multitimers       - MainThread      - DEBUG    - mpd.timer_status: State = {'enabled': False, 'wait_seconds_per_iteration': 0.25, 'type': 'GenericEndlessTimerClass'}
20.06.2024 20:47:34 -  202:multitimer.py      - jb.multitimers       - mpd.timer_status - DEBUG    - mpd.timer_status: State = {'enabled': True, 'wait_seconds_per_iteration': 0.25, 'type': 'GenericEndlessTimerClass'}
20.06.2024 20:47:34 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'components.playermpd.PlayerMPD' as 'player.ctrl'
20.06.2024 20:47:34 -   24:__init__.py        - jb.player            - MainThread      - DEBUG    - MPD music lib path = /home/pi/RPi-Jukebox-RFID/shared/audiofolders; from /home/pi/.config/mpd/mpd.conf
20.06.2024 20:47:34 -  751:__init__.py        - jb.PlayerMPD         - MainThread      - INFO     - Change user rights for /home/pi/RPi-Jukebox-RFID/shared/audiofolders
20.06.2024 20:47:34 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.rfid.cards' as 'cards'
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.rfid.cards.list_cards' as 'cards.list_cards' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.rfid.cards.delete_card' as 'cards.delete_card' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.rfid.cards.register_card' as 'cards.register_card' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.rfid.cards.register_card_custom' as 'cards.register_card_custom' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.rfid.cards.load_card_database' as 'cards.load_card_database' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.rfid.cards.save_card_database' as 'cards.save_card_database' (<class 'function'>)
20.06.2024 20:47:34 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.rfid.reader' as 'rfid'
20.06.2024 20:47:34 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.timers' as 'timers'
20.06.2024 20:47:34 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.hostif.linux' as 'host'
20.06.2024 20:47:34 -   79:multitimer.py      - jb.multitimers       - mpd.timer_status - DEBUG    - Start timer 'mpd.timer_status in endless mode
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.shutdown' as 'host.shutdown' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.reboot' as 'host.reboot' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.jukebox_is_service' as 'host.jukebox_is_service' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.is_any_jukebox_service_active' as 'host.is_any_jukebox_service_active' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.restart_service' as 'host.restart_service' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.get_disk_usage' as 'host.get_disk_usage' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.get_cpu_temperature' as 'host.get_cpu_temperature' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.publish_cpu_temperature' as 'host.publish_cpu_temperature' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.get_ip_address' as 'host.get_ip_address' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.say_my_ip' as 'host.say_my_ip' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.wlan_disable_power_down' as 'host.wlan_disable_power_down' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.get_autohotspot_status' as 'host.get_autohotspot_status' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.stop_autohotspot' as 'host.stop_autohotspot' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.start_autohotspot' as 'host.start_autohotspot' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.hdmi_power_down' as 'host.hdmi_power_down' (<class 'function'>)
20.06.2024 20:47:34 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.hostif.linux.get_throttled' as 'host.get_throttled' (<class 'function'>)
20.06.2024 20:47:35 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling host.initialize()
20.06.2024 20:47:35 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling host.rpi_initialize()
20.06.2024 20:47:35 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.controls.bluetooth_audio_buttons' as 'bluetooth_audio_buttons'
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.controls.bluetooth_audio_buttons.activate' as 'bluetooth_audio_buttons.activate' (<class 'function'>)
20.06.2024 20:47:35 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling bluetooth_audio_buttons.initialize()
20.06.2024 20:47:35 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.gpio.gpioz.plugin' as 'gpio'
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.gpio.gpioz.plugin.on' as 'gpio.on' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.gpio.gpioz.plugin.off' as 'gpio.off' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.gpio.gpioz.plugin.set_value' as 'gpio.set_value' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.gpio.gpioz.plugin.flash' as 'gpio.flash' (<class 'function'>)
20.06.2024 20:47:35 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling gpio.initialize()
20.06.2024 20:47:35 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.synchronisation.rfidcards' as 'sync_rfidcards'
20.06.2024 20:47:35 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging SyncRfidcards.sync_change_on_rfid_scan
20.06.2024 20:47:35 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging SyncRfidcards.sync_all
20.06.2024 20:47:35 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging SyncRfidcards.sync_card_database
20.06.2024 20:47:35 -  459:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Tagging SyncRfidcards.sync_folder
20.06.2024 20:47:35 -  570:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load initializer: calling sync_rfidcards.initialize()
20.06.2024 20:47:35 -   78:__init__.py        - jb.sync_rfidcards    - MainThread      - INFO     - Sync RFID cards deactivated
20.06.2024 20:47:35 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'components.synchronisation.rfidcards.SyncRfidcards' as 'sync_rfidcards.ctrl'
20.06.2024 20:47:35 -  545:plugs.py           - jb.plugin            - MainThread      - INFO     - Loading plugin 'components.misc' as 'misc'
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.rpc_cmd_help' as 'misc.rpc_cmd_help' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.get_all_loaded_packages' as 'misc.get_all_loaded_packages' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.get_all_failed_packages' as 'misc.get_all_failed_packages' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.get_start_time' as 'misc.get_start_time' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.get_log_debug' as 'misc.get_log_debug' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.get_log_error' as 'misc.get_log_error' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.get_version' as 'misc.get_version' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.get_git_state' as 'misc.get_git_state' (<class 'function'>)
20.06.2024 20:47:35 -  278:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting function 'components.misc.empty_rpc_call' as 'misc.empty_rpc_call' (<class 'function'>)
20.06.2024 20:47:35 -  620:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load finalizer: calling volume.finalize()
20.06.2024 20:47:35 -  455:__init__.py        - jb.pulse             - MainThread      - INFO     - Audio sink is now 'Built-in speakers' :: 'auto_null'
20.06.2024 20:47:35 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'components.volume.PulseVolumeControl' as 'volume.ctrl'
20.06.2024 20:47:35 -  620:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load finalizer: calling jingle.finalize()
20.06.2024 20:47:35 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: jingle.play_startup(args=(), kwargs=None)
20.06.2024 20:47:35 -  620:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load finalizer: calling cards.finalize()
20.06.2024 20:47:35 -  695:plugs.py           - jb.plugin.call       - StartJingle     - DEBUG    - Calling: volume.ctrl.get_volume(args=(), kwargs=None)
20.06.2024 20:47:35 -  318:cfghandler.py      - jb.cfghandler        - MainThread      - INFO     - (cards) Loading yaml file '../../shared/settings/cards.yaml'
20.06.2024 20:47:35 -  230:cfghandler.py      - jb.cfghandler        - MainThread      - DEBUG    - (cards) Replacing current config data
20.06.2024 20:47:35 -  695:plugs.py           - jb.plugin.call       - StartJingle     - DEBUG    - Calling: volume.ctrl.set_volume(args=[30], kwargs=None)
20.06.2024 20:47:35 -  620:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load finalizer: calling rfid.finalize()
20.06.2024 20:47:35 -  318:cfghandler.py      - jb.cfghandler        - MainThread      - INFO     - (rfid) Loading yaml file '../../shared/settings/rfid.yaml'
20.06.2024 20:47:35 -  230:cfghandler.py      - jb.cfghandler        - MainThread      - DEBUG    - (rfid) Replacing current config data
20.06.2024 20:47:35 -  101:__init__.py        - jb.rfid(read_00)     - MainThread      - INFO     - For reader config key 'read_00': loading module 'rc522_spi'
20.06.2024 20:47:36 -  116:__init__.py        - jb.rfid(read_00)     - MainThread      - DEBUG    - Decoded removal action: player.ctrl.pause()
20.06.2024 20:47:36 -   42:__init__.py        - jb.jingle            - StartJingle     - DEBUG    - Auto: 'wav' from ../../resources/audio/startupsound.wav.
20.06.2024 20:47:36 -  139:__init__.py        - jb.rfid(read_00)     - read_00Thread   - DEBUG    - Start listening!
20.06.2024 20:47:36 -  620:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load finalizer: calling timers.finalize()
20.06.2024 20:47:36 -   50:__init__.py        - jb.alsaif            - StartJingle     - DEBUG    - Playing wave file
20.06.2024 20:47:36 -  202:multitimer.py      - jb.multitimers       - MainThread      - DEBUG    - timers.timer_shutdown: State = {'enabled': False, 'remaining_seconds': 0, 'wait_seconds': 3600, 'type': 'GenericTimerClass'}
20.06.2024 20:47:36 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'jukebox.multitimer.GenericTimerClass' as 'timers.timer_shutdown'
20.06.2024 20:47:36 -  202:multitimer.py      - jb.multitimers       - MainThread      - DEBUG    - timers.timer_stop_player: State = {'enabled': False, 'remaining_seconds': 0, 'wait_seconds': 3600, 'type': 'GenericTimerClass'}
20.06.2024 20:47:36 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'jukebox.multitimer.GenericTimerClass' as 'timers.timer_stop_player'
20.06.2024 20:47:36 -  202:multitimer.py      - jb.multitimers       - MainThread      - DEBUG    - timers.timer_fade_volume: State = {'enabled': False, 'wait_seconds_per_iteration': 900, 'iterations': 1, 'type': 'GenericMultiTimerClass'}
20.06.2024 20:47:36 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'jukebox.multitimer.GenericMultiTimerClass' as 'timers.timer_fade_volume'
20.06.2024 20:47:36 -  620:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load finalizer: calling host.finalize()
20.06.2024 20:47:36 -  202:multitimer.py      - jb.multitimers       - MainThread      - DEBUG    - host.timer.cputemp: State = {'enabled': False, 'wait_seconds_per_iteration': 10, 'type': 'GenericEndlessTimerClass'}
20.06.2024 20:47:36 -  290:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Enlisting an instance of class 'jukebox.multitimer.GenericEndlessTimerClass' as 'host.timer_temperature'
20.06.2024 20:47:36 -  202:multitimer.py      - jb.multitimers       - host.timer.cputemp - DEBUG    - host.timer.cputemp: State = {'enabled': True, 'wait_seconds_per_iteration': 10, 'type': 'GenericEndlessTimerClass'}
20.06.2024 20:47:36 -  620:plugs.py           - jb.plugin            - MainThread      - DEBUG    - Package load finalizer: calling gpio.finalize()
20.06.2024 20:47:36 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: misc.get_all_loaded_packages(args=(), kwargs=None)
20.06.2024 20:47:36 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: misc.get_all_failed_packages(args=(), kwargs=None)
20.06.2024 20:47:36 -  144:daemon.py          - jb.daemon            - MainThread      - INFO     - Loaded plugins: publishing, volume, jingle, jingle.alsawave, jingle.jinglemp3, player, cards, rfid, timers, host, bluetooth_audio_buttons, gpio, sync_rfidcards, misc
20.06.2024 20:47:36 -   64:server.py          - jb.rpc.server        - MainThread      - INFO     - Init RPC Server (Pyzmq version: 25.1.2; ZMQ version: 4.3.5; has draft API: True)
20.06.2024 20:47:36 -   72:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Connected to address 'inproc://JukeBoxRpcServer'
20.06.2024 20:47:36 -   78:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Connected to address 'tcp://*:5555'
20.06.2024 20:47:36 -   84:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Connected to address 'ws://*:5556'
20.06.2024 20:47:36 -   89:server.py          - jb.rpc.server        - MainThread      - INFO     - All socket connections initialized
20.06.2024 20:47:36 -  229:daemon.py          - jb.daemon            - MainThread      - INFO     - Start-up time: 3383.974 ms
20.06.2024 20:47:36 -  101:server.py          - jb.rpc.server        - MainThread      - INFO     - RPC Servers started
20.06.2024 20:47:36 -   79:multitimer.py      - jb.multitimers       - host.timer.cputemp - DEBUG    - Start timer 'host.timer.cputemp in endless mode
20.06.2024 20:47:36 -   19:readerbase.py      - jb.rfid.522(read_00) - read_00Thread   - INFO     - Initializing reader 'MFRC522 via SPI' from '/home/pi/RPi-Jukebox-RFID/src/jukebox/components/rfid/hardware/rc522_spi/rc522_spi.py'
20.06.2024 20:47:36 -   20:readerbase.py      - jb.rfid.522(read_00) - read_00Thread   - DEBUG    - Reader object is <components.rfid.hardware.rc522_spi.rc522_spi.ReaderClass object at 0x61b558c8> for reader config key 'read_00'
20.06.2024 20:47:36 -   78:rc522_spi.py       - jb.rfid.522(read_00) - read_00Thread   - INFO     - Using legacy_mode = 'False'
20.06.2024 20:47:38 -  695:plugs.py           - jb.plugin.call       - StartJingle     - DEBUG    - Calling: volume.ctrl.set_volume(args=[40], kwargs=None)
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.started_at'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.version'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.temperature.cpu'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.timer.cputemp'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'playerstatus'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'rfid.card_id'
20.06.2024 20:48:13 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'volume.level'
20.06.2024 20:48:13 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '1a20104b-4c73-4427-ad23-321c57fc2900', 'package': 'volume', 'plugin': 'ctrl', 'method': 'get_volume', 'kwargs': {}}
20.06.2024 20:48:13 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: volume.ctrl.get_volume(args=(), kwargs={})
20.06.2024 20:48:13 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': 40, 'id': '1a20104b-4c73-4427-ad23-321c57fc2900'}
20.06.2024 20:48:13 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': 'fc45e6b5-b51b-443f-babe-5f72fc45bf89', 'package': 'volume', 'plugin': 'ctrl', 'method': 'get_soft_max_volume', 'kwargs': {}}
20.06.2024 20:48:13 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: volume.ctrl.get_soft_max_volume(args=(), kwargs={})
20.06.2024 20:48:13 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': 70, 'id': 'fc45e6b5-b51b-443f-babe-5f72fc45bf89'}
20.06.2024 20:48:15 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': 'e6a0a93d-d682-4b9e-9521-9a44be1ca2b9', 'package': 'cards', 'plugin': 'list_cards', 'method': None, 'kwargs': {}}
20.06.2024 20:48:15 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: cards.list_cards(args=(), kwargs={})
20.06.2024 20:48:15 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {}, 'id': 'e6a0a93d-d682-4b9e-9521-9a44be1ca2b9'}
20.06.2024 20:48:32 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614471002911'
20.06.2024 20:48:32 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614471002911'
20.06.2024 20:48:35 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 20:48:35 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 20:48:38 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614471002911'
20.06.2024 20:48:39 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614471002911'
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:51 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.started_at'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.version'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.temperature.cpu'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.timer.cputemp'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'playerstatus'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'rfid.card_id'
20.06.2024 20:50:52 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'volume.level'
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:52:12 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.started_at'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.version'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.temperature.cpu'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.timer.cputemp'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'playerstatus'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'rfid.card_id'
20.06.2024 20:58:06 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'volume.level'
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 20:58:09 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.started_at'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.version'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.temperature.cpu'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.timer.cputemp'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'playerstatus'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'rfid.card_id'
20.06.2024 21:01:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'volume.level'
20.06.2024 21:02:04 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149613670231071'
20.06.2024 21:02:04 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149613670231071'
20.06.2024 21:02:10 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614469852193'
20.06.2024 21:02:10 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614469852193'
20.06.2024 21:02:13 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149613670231071'
20.06.2024 21:02:13 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149613670231071'
20.06.2024 21:02:15 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614471002911'
20.06.2024 21:02:15 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614471002911'
20.06.2024 21:02:19 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149613670231071'
20.06.2024 21:02:19 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149613670231071'
20.06.2024 21:02:22 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614216389153'
20.06.2024 21:02:22 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614216389153'
20.06.2024 21:02:24 -  175:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Received card id = '1149614469852193'
20.06.2024 21:02:24 -  224:__init__.py        - jb.rfid(read_00)     - read_00Thread   - INFO     - Unknown card: '1149614469852193'
20.06.2024 21:04:38 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:38 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:38 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:38 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:39 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:39 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:39 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:39 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:04:39 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'batt_status'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.plugins.loaded'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.started_at'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'core.version'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.temperature.cpu'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'host.timer.cputemp'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'playerstatus'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'rfid.card_id'
20.06.2024 21:06:02 -  260:server.py          - jb.pub.server        - PubServer       - INFO     - New subscription for topic b'volume.level'
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '9122ddf2-5eb3-4e7c-b42e-8e7dedb1c51c', 'package': 'host', 'plugin': 'get_disk_usage', 'method': None, 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: host.get_disk_usage(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {'total': 6983, 'used': 3024, 'free': 3643}, 'id': '9122ddf2-5eb3-4e7c-b42e-8e7dedb1c51c'}
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '4c0924ec-6fed-4241-94bc-3448ebd9f187', 'package': 'host', 'plugin': 'get_ip_address', 'method': None, 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: host.get_ip_address(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': '192.168.50.4', 'id': '4c0924ec-6fed-4241-94bc-3448ebd9f187'}
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': 'e34f9e9b-1d10-48d1-8b10-32097718a6a8', 'package': 'timers', 'plugin': 'timer_shutdown', 'method': 'get_state', 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: timers.timer_shutdown.get_state(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {'enabled': False, 'remaining_seconds': 0, 'wait_seconds': 3600, 'type': 'GenericTimerClass'}, 'id': 'e34f9e9b-1d10-48d1-8b10-32097718a6a8'}
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '995ecc52-194e-4012-957b-3d911cf256b4', 'package': 'timers', 'plugin': 'timer_stop_player', 'method': 'get_state', 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: timers.timer_stop_player.get_state(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {'enabled': False, 'remaining_seconds': 0, 'wait_seconds': 3600, 'type': 'GenericTimerClass'}, 'id': '995ecc52-194e-4012-957b-3d911cf256b4'}
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': 'fc99fab4-13cf-4264-a8e5-2066fc26edfe', 'package': 'timers', 'plugin': 'timer_fade_volume', 'method': 'get_state', 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: timers.timer_fade_volume.get_state(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {'enabled': False, 'wait_seconds_per_iteration': 900, 'iterations': 10, 'type': 'GenericMultiTimerClass'}, 'id': 'fc99fab4-13cf-4264-a8e5-2066fc26edfe'}
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': 'f8482325-1f4d-4496-ada2-e327eba244da', 'package': 'volume', 'plugin': 'ctrl', 'method': 'get_outputs', 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: volume.ctrl.get_outputs(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': {'active_alias': 'Built-in speakers', 'active_sink': 'auto_null', 'sink_list': [{'alias': 'Built-in speakers', 'pulse_sink_name': 'auto_null', 'volume_limit': 100}]}, 'id': 'f8482325-1f4d-4496-ada2-e327eba244da'}
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '814ef10c-e842-495c-9bed-137df21ae45b', 'package': 'volume', 'plugin': 'ctrl', 'method': 'get_soft_max_volume', 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: volume.ctrl.get_soft_max_volume(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': 70, 'id': '814ef10c-e842-495c-9bed-137df21ae45b'}
20.06.2024 21:06:06 -  111:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Request: {'id': '615a2d16-50d0-4d1e-92ca-f423511f5085', 'package': 'host', 'plugin': 'get_autohotspot_status', 'method': None, 'kwargs': {}}
20.06.2024 21:06:06 -  695:plugs.py           - jb.plugin.call       - MainThread      - DEBUG    - Calling: host.get_autohotspot_status(args=(), kwargs={})
20.06.2024 21:06:06 -  151:server.py          - jb.rpc.server        - MainThread      - DEBUG    - Sending response: {'result': 'not-installed', 'id': '615a2d16-50d0-4d1e-92ca-f423511f5085'}
20.06.2024 21:34:43 -  263:server.py          - jb.pub.server        - PubServer       - INFO     - Un-subscription received

@s-martin
Copy link
Collaborator

Just to understand your problem:
It is working, but sometimes you have a huge delay between reading the card and the action triggered, correct?

could you also post your rfid.yaml and cards.yaml?

As I don’t have a rc522 reader, others may have more experience.

@damaev
Copy link
Contributor Author

damaev commented Jun 21, 2024

I use a fresh system
Hence, Cards.yaml should be more or less plain.
I edited the rfid.yaml after opening this issue to allow placing instead of swiping.
Other than that it's like the setup-script configured it. So the issue used the autoconfig.
As I already mentioned, I also tested a plain v2. Even more, I did almost all testing on the v2/main setup. Like disabling all phoniebox services and starting python daemon-rfid.pywhich clearly showed the unsteady delays.
Therefore, I conclude, it's either is a problem related to the pi zero2; To my soldering, which I doublechecked (ut who knows); There was an update to the rc522 library or mfrc522-partnever really worked correctly (from my short digging into the documentation of the rc522, the purpose of the irq may not necessarily indicate a nearby card)

@damaev
Copy link
Contributor Author

damaev commented Jun 21, 2024

To clarify:
The reading of an uid seems to work pretty fine, like in no time. However the irq-signal is not dropping. Hence, the script keeps waiting for a tag even though a tag is present

@flesser
Copy link

flesser commented Jun 22, 2024

Can confirm, I have the same issue with a fresh install from master on a Raspberry 3B+ with RFID-RC522 connected to the default pins.

It hangs at self.device.wait_for_tag() ( https://github.com/MiczFlor/RPi-Jukebox-RFID/blob/master/scripts/Reader.py.experimental#L91 which gets copied to Reader.py be the setup script).

If I comment out that line, tag IDs get read.

@flesser flesser mentioned this issue Jun 22, 2024
Open
@damaev
Copy link
Contributor Author

damaev commented Jun 22, 2024

Did it work correctly beforhand on the 3b+?
I was Using a pi zero 1. So it was always Slowenien, but I wouldn't say that slow.

9month ago the rc522.py library was updated to include a timeout during wait_for_tag() especially for our project.
ondryaso/pi-rc522#70
Maybe this update is causing trouble now.

damaev added a commit to damaev/RPi-Jukebox-RFID that referenced this issue Jun 22, 2024
@damaev
skip irq-sequence by ipdating rc522_spi.py
ff602bf 
see MiczFlor#2387
@damaev
Copy link
Contributor Author

damaev commented Jun 22, 2024

i addad a fix with an additional config param skip_irq, see above

@flesser
Copy link

flesser commented Jun 23, 2024

Unfortunately with skip_irq (or commented out line) the "remove card to stop playing" does not work because reader.readCard() in https://github.com/damaev/RPi-Jukebox-RFID/blob/develop/scripts/daemon_rfid_reader.py#L88 now immediately returns even if there is no card, resulting in the alarm to be reset any read attempt, even if the cardid was None

@s-martin
Copy link
Collaborator

From my point of view the original problem is tracked in #2373
I suggest to close this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug future3 Relates to future3 development needs triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@flesser @s-martin @damaev