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

🐛 RFID Reader - ID wird durch Phoniebox nicht eingelesen #768

Closed
Thr33LittleBirds opened this issue Feb 1, 2020 · 23 comments
Closed
Assignees
Labels

Comments

@Thr33LittleBirds
Copy link

Thr33LittleBirds commented Feb 1, 2020

Hardware

PI:
Raspberry Pi Model B Rev 2p
RFID Reader
KKmoon HID 413d:2107
https://www.amazon.de/gp/product/B011XI2DE8/ref=as_li_qf_sp_asin_il_tl?ie=UTF8&camp=1638&creative=6742&creativeASIN=B011XI2DE8&linkCode=as2&tag=diebarnfeld-21

Bug

What I did

Ich habe den Raspberry aufgesetzt und das folgende Script verwendet
cd; rm buster-install-*; wget https://raw.githubusercontent.com/MiczFlor/RPi-Jukebox-RFID/master/scripts/installscripts/buster-install-default.sh; chmod +x buster-install-default.sh; ./buster-install-default.sh

What happened

Das Aufsetzen hat funktioniert und auch der RFIDReader schreibt eine ID ins Terminal (abgeschlossen durch ein Enter). Aber die ID erscheint nicht im WebFrontend und auch nicht in den Textdateien.

Further information that might help

Der RFID Reader funktioniert. Die Karten werden eingelesen und ins Terminal geschrieben
Ich kann ihn unter RegisterDevice.py auswählen und er steht auch in der Textdatei
Per Hand kann ich die ./rfid_trigger_play.sh -i=1234565 ausführen und der Wert wird erfolgreich auch im WebFrontend angezeigt.

551 habe ich befolgt und das brachte mir auch keinen Erfolg

Ich könnt in die Tischkante beißen...
Ich hoffe ihr könnt mir helfen.

Edit: Kann ich irgendwie herausfinden, ob das einlesen der Karte überhaupt irgendein relevantes Event auslöst. Also kann ich irgendwo ein print("Hallo") setzen um den Ort des Fehlers einzugrenzen?

@s-martin
Copy link
Collaborator

s-martin commented Feb 1, 2020

Ist vermutlich der gleiche Fehler wie in #747 und #761.

Wenn PR #767 gemergt ist, löst das hoffentlich ein paar Probleme.

@s-martin
Copy link
Collaborator

s-martin commented Feb 1, 2020

Fix in #767 was merged.

Could everyone still having this issue, check if a installation described in https://github.com/MiczFlor/RPi-Jukebox-RFID/wiki/INSTALL-stretch works now again?

@Thr33LittleBirds
Copy link
Author

Läuft! Ich danke Euch!

@jochmann
Copy link

Checked, unfortunately an installation from scratch did not fix the issue for me. Also with a reader HID 413d:2107

@s-martin
Copy link
Collaborator

What's the output of tail -n 500 /var/log/syslog?

@jochmann
Copy link

jochmann commented Jun 14, 2020

Sorry it took me so long. Have been quite distracted by world events.

The output of tail -n 500 /var/log/syslog is quite long.

Moreover, I have a growing suspicion that the setup process is not working for me and important libraries are being skipped or somehow missed. I wonder if that happens due to packet loss via SSH-headless setup? In any event, having the install process fail without a warning might be an issueson its own. Perhaps not return a "installation complete" if there are missing libraries?

// edit: this log is from a fresh setup, using raspbian lite most recent version as of 2020-06-14 (via raspberry Pi Imager.app) and the one-line-install of the same date

Jun 14 19:02:03 raspberrypi kernel: [    0.233366] CacheFiles: Loaded
Jun 14 19:02:03 raspberrypi kernel: [    0.247275] NET: Registered protocol family 2
Jun 14 19:02:03 raspberrypi kernel: [    0.248521] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
Jun 14 19:02:03 raspberrypi kernel: [    0.249031] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
Jun 14 19:02:03 raspberrypi kernel: [    0.249191] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
Jun 14 19:02:03 raspberrypi kernel: [    0.249405] TCP: Hash tables configured (established 8192 bind 8192)
Jun 14 19:02:03 raspberrypi kernel: [    0.249643] UDP hash table entries: 512 (order: 2, 16384 bytes)
Jun 14 19:02:03 raspberrypi kernel: [    0.249742] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
Jun 14 19:02:03 raspberrypi kernel: [    0.250126] NET: Registered protocol family 1
Jun 14 19:02:03 raspberrypi kernel: [    0.251110] RPC: Registered named UNIX socket transport module.
Jun 14 19:02:03 raspberrypi kernel: [    0.251153] RPC: Registered udp transport module.
Jun 14 19:02:03 raspberrypi kernel: [    0.251179] RPC: Registered tcp transport module.
Jun 14 19:02:03 raspberrypi kernel: [    0.251204] RPC: Registered tcp NFSv4.1 backchannel transport module.
Jun 14 19:02:03 raspberrypi kernel: [    0.253484] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 5 counters available
Jun 14 19:02:03 raspberrypi kernel: [    0.257711] Initialise system trusted keyrings
Jun 14 19:02:03 raspberrypi kernel: [    0.258109] workingset: timestamp_bits=14 max_order=18 bucket_order=4
Jun 14 19:02:03 raspberrypi kernel: [    0.271456] FS-Cache: Netfs 'nfs' registered for caching
Jun 14 19:02:03 raspberrypi kernel: [    0.272350] NFS: Registering the id_resolver key type
Jun 14 19:02:03 raspberrypi kernel: [    0.272419] Key type id_resolver registered
Jun 14 19:02:03 raspberrypi kernel: [    0.272446] Key type id_legacy registered
Jun 14 19:02:03 raspberrypi kernel: [    0.272485] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
Jun 14 19:02:03 raspberrypi kernel: [    0.279688] Key type asymmetric registered
Jun 14 19:02:03 raspberrypi kernel: [    0.279741] Asymmetric key parser 'x509' registered
Jun 14 19:02:03 raspberrypi kernel: [    0.279852] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
Jun 14 19:02:03 raspberrypi kernel: [    0.280125] io scheduler noop registered
Jun 14 19:02:03 raspberrypi kernel: [    0.280161] io scheduler deadline registered (default)
Jun 14 19:02:03 raspberrypi kernel: [    0.280481] io scheduler cfq registered
Jun 14 19:02:03 raspberrypi kernel: [    0.280515] io scheduler mq-deadline registered (default)
Jun 14 19:02:03 raspberrypi kernel: [    0.280544] io scheduler kyber registered
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Remount Root and Kernel File Systems...
Jun 14 19:02:03 raspberrypi kernel: [    0.283097] bcm2708_fb soc:fb: FB found 1 display(s)
Jun 14 19:02:03 raspberrypi kernel: [    0.293752] Console: switching to colour frame buffer device 82x26
Jun 14 19:02:03 raspberrypi kernel: [    0.301611] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
Jun 14 19:02:03 raspberrypi kernel: [    0.309742] bcm2835-rng 3f104000.rng: hwrng registered
Jun 14 19:02:03 raspberrypi kernel: [    0.312822] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
Jun 14 19:02:03 raspberrypi systemd[1]: Started udev Coldplug all Devices.
Jun 14 19:02:03 raspberrypi kernel: [    0.319101] vc-sm: Videocore shared memory driver
Jun 14 19:02:03 raspberrypi kernel: [    0.322337] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
Jun 14 19:02:03 raspberrypi kernel: [    0.343935] brd: module loaded
Jun 14 19:02:03 raspberrypi kernel: [    0.361133] loop: module loaded
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Helper to synchronize boot up for ifupdown...
Jun 14 19:02:03 raspberrypi kernel: [    0.364732] Loading iSCSI transport class v2.0-870.
Jun 14 19:02:03 raspberrypi kernel: [    0.368683] libphy: Fixed MDIO Bus: probed
Jun 14 19:02:03 raspberrypi kernel: [    0.371578] usbcore: registered new interface driver lan78xx
Jun 14 19:02:03 raspberrypi kernel: [    0.374392] usbcore: registered new interface driver smsc95xx
Jun 14 19:02:03 raspberrypi systemd[1]: Started Set the console keyboard layout.
Jun 14 19:02:03 raspberrypi kernel: [    0.377066] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Jun 14 19:02:03 raspberrypi kernel: [    0.407773] dwc_otg 3f980000.usb: base=(ptrval)
Jun 14 19:02:03 raspberrypi systemd[1]: Started Helper to synchronize boot up for ifupdown.
Jun 14 19:02:03 raspberrypi kernel: [    0.610891] Core Release: 2.80a
Jun 14 19:02:03 raspberrypi kernel: [    0.613597] Setting default values for core params
Jun 14 19:02:03 raspberrypi kernel: [    0.616375] Finished setting default values for core params
Jun 14 19:02:03 raspberrypi kernel: [    0.819589] Using Buffer DMA mode
Jun 14 19:02:03 raspberrypi systemd[1]: Started Remount Root and Kernel File Systems.
Jun 14 19:02:03 raspberrypi kernel: [    0.822302] Periodic Transfer Interrupt Enhancement - disabled
Jun 14 19:02:03 raspberrypi kernel: [    0.825049] Multiprocessor Interrupt Enhancement - disabled
Jun 14 19:02:03 raspberrypi kernel: [    0.827734] OTG VER PARAM: 0, OTG VER FLAG: 0
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Load/Save Random Seed...
Jun 14 19:02:03 raspberrypi kernel: [    0.830423] Dedicated Tx FIFOs mode
Jun 14 19:02:03 raspberrypi kernel: [    0.833655] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = bad14000 dma = 0xfad14000 len=9024
Jun 14 19:02:03 raspberrypi kernel: [    0.838908] FIQ FSM acceleration enabled for :
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Flush Journal to Persistent Storage...
Jun 14 19:02:03 raspberrypi kernel: [    0.838908] Non-periodic Split Transactions
Jun 14 19:02:03 raspberrypi kernel: [    0.838908] Periodic Split Transactions
Jun 14 19:02:03 raspberrypi kernel: [    0.838908] High-Speed Isochronous Endpoints
Jun 14 19:02:03 raspberrypi kernel: [    0.838908] Interrupt/Control Split Transaction hack enabled
Jun 14 19:02:03 raspberrypi kernel: [    0.851261] dwc_otg: Microframe scheduler enabled
Jun 14 19:02:03 raspberrypi kernel: [    0.851346] WARN::hcd_init_fiq:457: FIQ on core 1
Jun 14 19:02:03 raspberrypi kernel: [    0.853877] WARN::hcd_init_fiq:458: FIQ ASM at 8068fda0 length 36
Jun 14 19:02:03 raspberrypi kernel: [    0.856387] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
Jun 14 19:02:03 raspberrypi kernel: [    0.858951] dwc_otg 3f980000.usb: DWC OTG Controller
Jun 14 19:02:03 raspberrypi kernel: [    0.861527] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
Jun 14 19:02:03 raspberrypi kernel: [    0.864172] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
Jun 14 19:02:03 raspberrypi kernel: [    0.866780] Init: Port Power? op_state=1
Jun 14 19:02:03 raspberrypi kernel: [    0.869364] Init: Power Port (0)
Jun 14 19:02:03 raspberrypi kernel: [    0.872199] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
Jun 14 19:02:03 raspberrypi kernel: [    0.877301] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jun 14 19:02:03 raspberrypi kernel: [    0.880066] usb usb1: Product: DWC OTG Controller
Jun 14 19:02:03 raspberrypi kernel: [    0.882754] usb usb1: Manufacturer: Linux 4.19.118-v7+ dwc_otg_hcd
Jun 14 19:02:03 raspberrypi kernel: [    0.885502] usb usb1: SerialNumber: 3f980000.usb
Jun 14 19:02:03 raspberrypi kernel: [    0.889119] hub 1-0:1.0: USB hub found
Jun 14 19:02:03 raspberrypi kernel: [    0.891725] hub 1-0:1.0: 1 port detected
Jun 14 19:02:03 raspberrypi kernel: [    0.895022] dwc_otg: FIQ enabled
Jun 14 19:02:03 raspberrypi kernel: [    0.895030] dwc_otg: NAK holdoff enabled
Jun 14 19:02:03 raspberrypi kernel: [    0.895037] dwc_otg: FIQ split-transaction FSM enabled
Jun 14 19:02:03 raspberrypi kernel: [    0.895050] Module dwc_common_port init
Jun 14 19:02:03 raspberrypi kernel: [    0.895452] usbcore: registered new interface driver usb-storage
Jun 14 19:02:03 raspberrypi kernel: [    0.898334] mousedev: PS/2 mouse device common for all mice
Jun 14 19:02:03 raspberrypi kernel: [    0.902127] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
Jun 14 19:02:03 raspberrypi kernel: [    0.905113] bcm2835-cpufreq: min=600000 max=900000
Jun 14 19:02:03 raspberrypi kernel: [    0.908418] sdhci: Secure Digital Host Controller Interface driver
Jun 14 19:02:03 raspberrypi kernel: [    0.911201] sdhci: Copyright(c) Pierre Ossman
Jun 14 19:02:03 raspberrypi kernel: [    0.914471] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
Jun 14 19:02:03 raspberrypi kernel: [    0.917539] sdhci-pltfm: SDHCI platform and OF driver helper
Jun 14 19:02:03 raspberrypi kernel: [    0.921292] ledtrig-cpu: registered to indicate activity on CPUs
Jun 14 19:02:03 raspberrypi kernel: [    0.924331] hidraw: raw HID events driver (C) Jiri Kosina
Jun 14 19:02:03 raspberrypi kernel: [    0.927454] usbcore: registered new interface driver usbhid
Jun 14 19:02:03 raspberrypi kernel: [    0.930385] usbhid: USB HID core driver
Jun 14 19:02:03 raspberrypi kernel: [    0.934220] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
Jun 14 19:02:03 raspberrypi kernel: [    0.939127] [vc_sm_connected_init]: start
Jun 14 19:02:03 raspberrypi kernel: [    0.948113] [vc_sm_connected_init]: end - returning 0
Jun 14 19:02:03 raspberrypi kernel: [    0.952450] Initializing XFRM netlink socket
Jun 14 19:02:03 raspberrypi kernel: [    0.955187] NET: Registered protocol family 17
Jun 14 19:02:03 raspberrypi kernel: [    0.957993] Key type dns_resolver registered
Jun 14 19:02:03 raspberrypi kernel: [    0.961267] Registering SWP/SWPB emulation handler
Jun 14 19:02:03 raspberrypi kernel: [    0.964980] registered taskstats version 1
Jun 14 19:02:03 raspberrypi kernel: [    0.967696] Loading compiled-in X.509 certificates
Jun 14 19:02:03 raspberrypi kernel: [    0.979287] uart-pl011 3f201000.serial: cts_event_workaround enabled
Jun 14 19:02:03 raspberrypi kernel: [    0.982175] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
Jun 14 19:02:03 raspberrypi kernel: [    1.994385] console [ttyAMA0] enabled
Jun 14 19:02:03 raspberrypi kernel: [    2.003641] sdhost: log_buf @ (ptrval) (fad13000)
Jun 14 19:02:03 raspberrypi kernel: [    2.058098] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
Jun 14 19:02:03 raspberrypi kernel: [    2.068119] of_cfs_init
Jun 14 19:02:03 raspberrypi kernel: [    2.073469] of_cfs_init: OK
Jun 14 19:02:03 raspberrypi kernel: [    2.079687] Waiting for root device PARTUUID=66b7ae18-02...
Jun 14 19:02:03 raspberrypi kernel: [    2.108723] Indeed it is in host mode hprt0 = 00021501
Jun 14 19:02:03 raspberrypi kernel: [    2.204703] random: fast init done
Jun 14 19:02:03 raspberrypi kernel: [    2.215954] mmc0: host does not support reading read-only switch, assuming write-enable
Jun 14 19:02:03 raspberrypi kernel: [    2.232898] mmc0: new high speed SDHC card at address aaaa
Jun 14 19:02:03 raspberrypi kernel: [    2.242740] mmcblk0: mmc0:aaaa SL08G 7.40 GiB
Jun 14 19:02:03 raspberrypi kernel: [    2.253177]  mmcblk0: p1 p2
Jun 14 19:02:03 raspberrypi kernel: [    2.300743] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Jun 14 19:02:03 raspberrypi kernel: [    2.314550] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Jun 14 19:02:03 raspberrypi kernel: [    2.318609] usb 1-1: new high-speed USB device number 2 using dwc_otg
Jun 14 19:02:03 raspberrypi kernel: [    2.333193] devtmpfs: mounted
Jun 14 19:02:03 raspberrypi kernel: [    2.334160] Indeed it is in host mode hprt0 = 00001101
Jun 14 19:02:03 raspberrypi kernel: [    2.409706] Freeing unused kernel memory: 1024K
Jun 14 19:02:03 raspberrypi kernel: [    2.417488] Run /sbin/init as init process
Jun 14 19:02:03 raspberrypi kernel: [    2.579039] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
Jun 14 19:02:03 raspberrypi kernel: [    2.593157] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Jun 14 19:02:03 raspberrypi kernel: [    2.604359] hub 1-1:1.0: USB hub found
Jun 14 19:02:03 raspberrypi kernel: [    2.611492] hub 1-1:1.0: 5 ports detected
Jun 14 19:02:03 raspberrypi kernel: [    2.938627] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Jun 14 19:02:03 raspberrypi kernel: [    3.079033] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
Jun 14 19:02:03 raspberrypi kernel: [    3.096954] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Jun 14 19:02:03 raspberrypi kernel: [    3.110381] smsc95xx v1.0.6
Jun 14 19:02:03 raspberrypi kernel: [    3.203297] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:e0:3b:07
Jun 14 19:02:03 raspberrypi kernel: [    3.250757] NET: Registered protocol family 10
Jun 14 19:02:03 raspberrypi kernel: [    3.260583] Segment Routing with IPv6
Jun 14 19:02:03 raspberrypi kernel: [    3.318670] usb 1-1.2: new full-speed USB device number 4 using dwc_otg
Jun 14 19:02:03 raspberrypi kernel: [    3.481175] usb 1-1.2: New USB device found, idVendor=413d, idProduct=2107, bcdDevice= 0.00
Jun 14 19:02:03 raspberrypi kernel: [    3.497096] usb 1-1.2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Jun 14 19:02:03 raspberrypi kernel: [    3.522526] input: HID 413d:2107 as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.0/0003:413D:2107.0001/input/input0
Jun 14 19:02:03 raspberrypi kernel: [    3.591895] uart-pl011 3f201000.serial: no DMA platform data
Jun 14 19:02:03 raspberrypi kernel: [    3.619745] hid-generic 0003:413D:2107.0001: input,hidraw0: USB HID v1.11 Keyboard [HID 413d:2107] on usb-3f980000.usb-1.2/input0
Jun 14 19:02:03 raspberrypi kernel: [    3.748652] usb 1-1.4: new high-speed USB device number 5 using dwc_otg
Jun 14 19:02:03 raspberrypi kernel: [    3.906362] usb 1-1.4: New USB device found, idVendor=148f, idProduct=5370, bcdDevice= 1.01
Jun 14 19:02:03 raspberrypi kernel: [    3.921681] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jun 14 19:02:03 raspberrypi kernel: [    3.932649] usb 1-1.4: Product: 802.11 n WLAN
Jun 14 19:02:03 raspberrypi kernel: [    3.940520] usb 1-1.4: Manufacturer: Ralink
Jun 14 19:02:03 raspberrypi kernel: [    3.948041] usb 1-1.4: SerialNumber: 1.0
Jun 14 19:02:03 raspberrypi kernel: [    4.606642] random: systemd: uninitialized urandom read (16 bytes read)
Jun 14 19:02:03 raspberrypi kernel: [    4.632995] random: systemd: uninitialized urandom read (16 bytes read)
Jun 14 19:02:03 raspberrypi kernel: [    4.666132] random: systemd: uninitialized urandom read (16 bytes read)
Jun 14 19:02:03 raspberrypi kernel: [    5.829708] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Jun 14 19:02:03 raspberrypi kernel: [    6.738674] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
Jun 14 19:02:03 raspberrypi kernel: [    6.742285] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
Jun 14 19:02:03 raspberrypi kernel: [    6.742317] [vc_sm_connected_init]: start
Jun 14 19:02:03 raspberrypi kernel: [    6.747944] media: Linux media interface: v0.10
Jun 14 19:02:03 raspberrypi kernel: [    6.750687] [vc_sm_connected_init]: installed successfully
Jun 14 19:02:03 raspberrypi kernel: [    6.803516] videodev: Linux video capture interface: v2.00
Jun 14 19:02:03 raspberrypi kernel: [    6.870624] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jun 14 19:02:03 raspberrypi kernel: [    6.871026] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jun 14 19:02:03 raspberrypi kernel: [    6.889817] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Jun 14 19:02:03 raspberrypi kernel: [    6.904782] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Jun 14 19:02:03 raspberrypi kernel: [    6.906009] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Jun 14 19:02:03 raspberrypi kernel: [    6.914587] bcm2835_audio soc:audio: card created with 8 channels
Jun 14 19:02:03 raspberrypi kernel: [    6.946302] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
Jun 14 19:02:03 raspberrypi kernel: [    6.946370] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
Jun 14 19:02:03 raspberrypi kernel: [    6.958914] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
Jun 14 19:02:03 raspberrypi kernel: [    6.958971] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
Jun 14 19:02:03 raspberrypi kernel: [    6.969459] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
Jun 14 19:02:03 raspberrypi kernel: [    6.969531] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
Jun 14 19:02:03 raspberrypi kernel: [    7.358356] cfg80211: Loading compiled-in X.509 certificates for regulatory database
Jun 14 19:02:03 raspberrypi kernel: [    7.422247] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
Jun 14 19:02:03 raspberrypi kernel: [    7.769353] usb 1-1.4: reset high-speed USB device number 5 using dwc_otg
Jun 14 19:02:03 raspberrypi kernel: [    7.929591] ieee80211 phy0: rt2x00_set_rt: Info - RT chipset 5390, rev 0502 detected
Jun 14 19:02:03 raspberrypi kernel: [    7.960195] ieee80211 phy0: rt2x00_set_rf: Info - RF chipset 5370 detected
Jun 14 19:02:03 raspberrypi kernel: [    8.042287] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
Jun 14 19:02:03 raspberrypi kernel: [    8.044751] usbcore: registered new interface driver rt2800usb
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Create System Users...
Jun 14 19:02:03 raspberrypi systemd[1]: Started Load/Save Random Seed.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Create System Users.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Create Static Device Nodes in /dev...
Jun 14 19:02:03 raspberrypi systemd[1]: Started Flush Journal to Persistent Storage.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Create Static Device Nodes in /dev.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting udev Kernel Device Manager...
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Local File Systems (Pre).
Jun 14 19:02:03 raspberrypi systemd[1]: Started udev Kernel Device Manager.
Jun 14 19:02:03 raspberrypi systemd[1]: Found device /dev/ttyAMA0.
Jun 14 19:02:03 raspberrypi mtp-probe: checking bus 1, device 3: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1"
Jun 14 19:02:03 raspberrypi mtp-probe: checking bus 1, device 4: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2"
Jun 14 19:02:03 raspberrypi mtp-probe: bus: 1, device: 4 was not an MTP device
Jun 14 19:02:03 raspberrypi mtp-probe: checking bus 1, device 5: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4"
Jun 14 19:02:03 raspberrypi mtp-probe: bus: 1, device: 5 was not an MTP device
Jun 14 19:02:03 raspberrypi mtp-probe: bus: 1, device: 3 was not an MTP device
Jun 14 19:02:03 raspberrypi systemd-udevd[179]: Using default interface naming scheme 'v240'.
Jun 14 19:02:03 raspberrypi systemd[1]: Found device /dev/disk/by-partuuid/66b7ae18-01.
Jun 14 19:02:03 raspberrypi systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in FUSE Control File System being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in Huge Pages File System being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
Jun 14 19:02:03 raspberrypi systemd-udevd[172]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting File System Check on /dev/disk/by-partuuid/66b7ae18-01...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status...
Jun 14 19:02:03 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status.
Jun 14 19:02:03 raspberrypi systemd-fsck[241]: fsck.fat 4.1 (2017-01-24)
Jun 14 19:02:03 raspberrypi systemd-fsck[241]: /dev/mmcblk0p1: 311 files, 106330/516190 clusters
Jun 14 19:02:03 raspberrypi systemd[1]: Started File System Check on /dev/disk/by-partuuid/66b7ae18-01.
Jun 14 19:02:03 raspberrypi systemd[1]: Mounting /boot...
Jun 14 19:02:03 raspberrypi systemd[1]: Mounted /boot.
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Local File Systems.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Set console font and keymap...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Preprocess NFS configuration...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Create Volatile Files and Directories...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Raise network interfaces...
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Set console font and keymap.
Jun 14 19:02:03 raspberrypi systemd[1]: nfs-config.service: Succeeded.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Preprocess NFS configuration.
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in RPC security service for NFS server being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target NFS client services.
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Remote File Systems (Pre).
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Remote File Systems.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Create Volatile Files and Directories.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Network Time Synchronization...
Jun 14 19:02:03 raspberrypi systemd[1]: Started Update UTMP about System Boot/Shutdown.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Raise network interfaces.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Network Time Synchronization.
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target System Initialization.
Jun 14 19:02:03 raspberrypi systemd[1]: Listening on D-Bus System Message Bus Socket.
Jun 14 19:02:03 raspberrypi systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Jun 14 19:02:03 raspberrypi systemd[1]: Listening on triggerhappy.socket.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Daily Cleanup of Temporary Directories.
Jun 14 19:02:03 raspberrypi systemd[1]: Listening on mpd.socket.
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Sockets.
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Basic System.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting triggerhappy global hotkey daemon...
Jun 14 19:02:03 raspberrypi systemd[1]: Started Regular background program processing daemon.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Jun 14 19:02:03 raspberrypi cron[319]: (CRON) INFO (pidfile fd = 3)
Jun 14 19:02:03 raspberrypi thd[318]: Found socket passed from systemd
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Check for Raspberry Pi EEPROM updates...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Login Service...
Jun 14 19:02:03 raspberrypi cron[319]: (CRON) INFO (Running @reboot jobs)
Jun 14 19:02:03 raspberrypi systemd[1]: Starting System Logging Service...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Deferred execution scheduler...
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in Turn on SSH if /boot/ssh is present being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Manage Sound Card State (restore and store).
Jun 14 19:02:03 raspberrypi systemd[1]: Starting Save/Restore Sound Card State...
Jun 14 19:02:03 raspberrypi alsactl[327]: alsactl 1.1.8 daemon started
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting LSB: Switch to ondemand cpu governor (unless shift key is pressed)...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting rng-tools.service...
Jun 14 19:02:03 raspberrypi systemd[1]: Started D-Bus System Message Bus.
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: Found user 'avahi' (UID 108) and group 'avahi' (GID 113).
Jun 14 19:02:03 raspberrypi kernel: [   10.242394] random: crng init done
Jun 14 19:02:03 raspberrypi kernel: [   10.242421] random: 7 urandom warning(s) missed due to ratelimiting
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: Successfully dropped root privileges.
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: avahi-daemon 0.7 starting up.
Jun 14 19:02:03 raspberrypi rng-tools[331]: Starting Hardware RNG entropy gatherer daemon: rngd.
Jun 14 19:02:03 raspberrypi rngd[337]: rngd 2-unofficial-mt.14 starting up...
Jun 14 19:02:03 raspberrypi systemd[1]: Starting dphys-swapfile - set up, mount/unmount, and delete a swap file...
Jun 14 19:02:03 raspberrypi rsyslogd: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.1901.0]
Jun 14 19:02:03 raspberrypi rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="325" x-info="https://www.rsyslog.com"] start
Jun 14 19:02:03 raspberrypi systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped.
Jun 14 19:02:03 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Jun 14 19:02:03 raspberrypi rngd[337]: entropy feed to the kernel ready
Jun 14 19:02:03 raspberrypi systemd[1]: Starting WPA supplicant...
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target System Time Synchronized.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Clean PHP session files every 30 mins.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Daily apt download activities.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Daily rotation of log files.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Daily man-db regeneration.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Daily apt upgrade and clean activities.
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Timers.
Jun 14 19:02:03 raspberrypi systemd[1]: Started triggerhappy global hotkey daemon.
Jun 14 19:02:03 raspberrypi systemd[1]: Started System Logging Service.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Check for Raspberry Pi EEPROM updates.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Deferred execution scheduler.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Save/Restore Sound Card State.
Jun 14 19:02:03 raspberrypi systemd[1]: Started rng-tools.service.
Jun 14 19:02:03 raspberrypi dhcpcd[345]: dev: loaded udev
Jun 14 19:02:03 raspberrypi systemd[1]: Reached target Sound Card.
Jun 14 19:02:03 raspberrypi kernel: [   10.489502] 8021q: 802.1Q VLAN Support v1.8
Jun 14 19:02:03 raspberrypi systemd[1]: Started Login Service.
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: Successfully called chroot().
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: Successfully dropped remaining capabilities.
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: No service file found in /etc/avahi/services.
Jun 14 19:02:03 raspberrypi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: Network interface enumeration completed.
Jun 14 19:02:03 raspberrypi avahi-daemon[320]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 3559111896.
Jun 14 19:02:03 raspberrypi dphys-swapfile[341]: want /var/swap=100MByte, checking existing: keeping it
Jun 14 19:02:03 raspberrypi wpa_supplicant[346]: Successfully initialized wpa_supplicant
Jun 14 19:02:03 raspberrypi systemd[1]: Started WPA supplicant.
Jun 14 19:02:03 raspberrypi dhcpcd[345]: wlan0: starting wpa_supplicant
Jun 14 19:02:03 raspberrypi dhcpcd-run-hooks[390]: wlan0: starting wpa_supplicant
Jun 14 19:02:03 raspberrypi kernel: [   10.727492] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
Jun 14 19:02:03 raspberrypi systemd[1]: Started dphys-swapfile - set up, mount/unmount, and delete a swap file.
Jun 14 19:02:03 raspberrypi kernel: [   10.853795] ieee80211 phy0: rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'
Jun 14 19:02:03 raspberrypi kernel: [   10.855412] ieee80211 phy0: rt2x00lib_request_firmware: Info - Firmware detected - version: 0.36
Jun 14 19:02:04 raspberrypi kernel: [   11.230242] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: connected to Access Point `'
Jun 14 19:02:04 raspberrypi dhcpcd[345]: eth0: waiting for carrier
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: waiting for carrier
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: carrier acquired
Jun 14 19:02:04 raspberrypi kernel: [   11.562369] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Jun 14 19:02:04 raspberrypi kernel: [   11.562752] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Jun 14 19:02:04 raspberrypi dhcpcd[345]: DUID 00:01:00:01:26:60:d2:3a:ac:a2:13:22:86:bf
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: IAID 13:22:86:bf
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: adding address fe80::aea2:13ff:fe22:86bf
Jun 14 19:02:04 raspberrypi avahi-daemon[320]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::aea2:13ff:fe22:86bf.
Jun 14 19:02:04 raspberrypi avahi-daemon[320]: New relevant interface wlan0.IPv6 for mDNS.
Jun 14 19:02:04 raspberrypi avahi-daemon[320]: Registering new address record for fe80::aea2:13ff:fe22:86bf on wlan0.*.
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: probing address 192.168.2.222/24
Jun 14 19:02:04 raspberrypi raspi-config[330]: Checking if shift key is held down: No. Switching to ondemand scaling governor.
Jun 14 19:02:04 raspberrypi systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: carrier lost
Jun 14 19:02:04 raspberrypi dhcpcd[345]: wlan0: deleting address fe80::aea2:13ff:fe22:86bf
Jun 14 19:02:04 raspberrypi avahi-daemon[320]: Withdrawing address record for fe80::aea2:13ff:fe22:86bf on wlan0.
Jun 14 19:02:04 raspberrypi avahi-daemon[320]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::aea2:13ff:fe22:86bf.
Jun 14 19:02:04 raspberrypi avahi-daemon[320]: Interface wlan0.IPv6 no longer relevant for mDNS.
Jun 14 19:02:05 raspberrypi kernel: [   12.626213] wlan0: authenticate with 34:49:5b:67:73:b4
Jun 14 19:02:05 raspberrypi kernel: [   12.656503] wlan0: send auth to 34:49:5b:67:73:b4 (try 1/3)
Jun 14 19:02:05 raspberrypi kernel: [   12.657824] wlan0: authenticated
Jun 14 19:02:05 raspberrypi kernel: [   12.658642] wlan0: associate with 34:49:5b:67:73:b4 (try 1/3)
Jun 14 19:02:05 raspberrypi kernel: [   12.662186] wlan0: RX AssocResp from 34:49:5b:67:73:b4 (capab=0x1531 status=0 aid=5)
Jun 14 19:02:05 raspberrypi kernel: [   12.669462] wlan0: associated
Jun 14 19:02:05 raspberrypi kernel: [   12.832017] cryptd: max_cpu_qlen set to 1000
Jun 14 19:02:05 raspberrypi kernel: [   12.873367] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jun 14 19:02:05 raspberrypi dhcpcd[345]: wlan0: carrier acquired
Jun 14 19:02:05 raspberrypi dhcpcd[345]: wlan0: connected to Access Point `WLAN-T97KKT'
Jun 14 19:02:05 raspberrypi dhcpcd[345]: wlan0: IAID 13:22:86:bf
Jun 14 19:02:05 raspberrypi dhcpcd[345]: wlan0: adding address fe80::aea2:13ff:fe22:86bf
Jun 14 19:02:05 raspberrypi avahi-daemon[320]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::aea2:13ff:fe22:86bf.
Jun 14 19:02:05 raspberrypi avahi-daemon[320]: New relevant interface wlan0.IPv6 for mDNS.
Jun 14 19:02:05 raspberrypi dhcpcd[345]: wlan0: probing address 192.168.2.222/24
Jun 14 19:02:05 raspberrypi avahi-daemon[320]: Registering new address record for fe80::aea2:13ff:fe22:86bf on wlan0.*.
Jun 14 19:02:05 raspberrypi dhcpcd[345]: wlan0: soliciting an IPv6 router
Jun 14 19:02:06 raspberrypi systemd[1]: systemd-rfkill.service: Succeeded.
Jun 14 19:02:07 raspberrypi dhcpcd[345]: wlan0: Router Advertisement from fe80::1
Jun 14 19:02:07 raspberrypi dhcpcd[345]: wlan0: adding address 2003:e3:9f13:653a:aea2:13ff:fe22:86bf/64
Jun 14 19:02:07 raspberrypi avahi-daemon[320]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::aea2:13ff:fe22:86bf.
Jun 14 19:02:07 raspberrypi kernel: [   14.990394] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
Jun 14 19:02:07 raspberrypi avahi-daemon[320]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2003:e3:9f13:653a:aea2:13ff:fe22:86bf.
Jun 14 19:02:07 raspberrypi avahi-daemon[320]: Registering new address record for 2003:e3:9f13:653a:aea2:13ff:fe22:86bf on wlan0.*.
Jun 14 19:02:07 raspberrypi dhcpcd[345]: wlan0: adding route to 2003:e3:9f13:653a::/64
Jun 14 19:02:07 raspberrypi avahi-daemon[320]: Withdrawing address record for fe80::aea2:13ff:fe22:86bf on wlan0.
Jun 14 19:02:07 raspberrypi dhcpcd[345]: wlan0: requesting DHCPv6 information
Jun 14 19:02:07 raspberrypi dhcpcd[345]: wlan0: fe80::1 is reachable again
Jun 14 19:02:07 raspberrypi dhcpcd[345]: wlan0: adding default route via fe80::1
Jun 14 19:02:10 raspberrypi dhcpcd[345]: wlan0: using static address 192.168.2.222/24
Jun 14 19:02:10 raspberrypi avahi-daemon[320]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.222.
Jun 14 19:02:10 raspberrypi avahi-daemon[320]: New relevant interface wlan0.IPv4 for mDNS.
Jun 14 19:02:10 raspberrypi avahi-daemon[320]: Registering new address record for 192.168.2.222 on wlan0.IPv4.
Jun 14 19:02:10 raspberrypi dhcpcd[345]: wlan0: adding route to 192.168.2.0/24
Jun 14 19:02:10 raspberrypi dhcpcd[345]: wlan0: adding default route via 192.168.2.1
Jun 14 19:02:11 raspberrypi dhcpcd[345]: forked to background, child pid 473
Jun 14 19:02:11 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Jun 14 19:02:11 raspberrypi systemd[1]: Reached target Network.
Jun 14 19:02:11 raspberrypi systemd[1]: Starting Permit User Sessions...
Jun 14 19:02:11 raspberrypi systemd[1]: Started Phoniebox RFID-Reader Service.
Jun 14 19:02:11 raspberrypi systemd[1]: Reached target Network is Online.
Jun 14 19:02:11 raspberrypi systemd[1]: Starting LSB: exim Mail Transport Agent...
Jun 14 19:02:11 raspberrypi systemd[1]: Starting Lighttpd Daemon...
Jun 14 19:02:11 raspberrypi systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Jun 14 19:02:11 raspberrypi systemd[1]: Started Phoniebox Idle Watchdog Service.
Jun 14 19:02:11 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Jun 14 19:02:11 raspberrypi systemd[481]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Jun 14 19:02:11 raspberrypi systemd[481]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Jun 14 19:02:11 raspberrypi systemd[1]: Starting Music Player Daemon...
Jun 14 19:02:11 raspberrypi systemd[1]: Starting Samba NMB Daemon...
Jun 14 19:02:11 raspberrypi systemd[1]: Starting /etc/rc.local Compatibility...
Jun 14 19:02:11 raspberrypi systemd[1]: Started Phoniebox GPIO Buttons Service.
Jun 14 19:02:11 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Jun 14 19:02:11 raspberrypi systemd[1]: Started Permit User Sessions.
Jun 14 19:02:11 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 14 19:02:11 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 14 19:02:11 raspberrypi systemd[1]: Started /etc/rc.local Compatibility.
Jun 14 19:02:11 raspberrypi systemd[1]: Started Getty on tty1.
Jun 14 19:02:11 raspberrypi systemd[1]: Started Serial Getty on ttyAMA0.
Jun 14 19:02:11 raspberrypi systemd[1]: Reached target Login Prompts.
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 1.
Jun 14 19:02:12 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 14 19:02:12 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Jun 14 19:02:12 raspberrypi systemd[529]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Jun 14 19:02:12 raspberrypi systemd[529]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 14 19:02:12 raspberrypi systemd[1]: Started OpenBSD Secure Shell server.
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 2.
Jun 14 19:02:12 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 14 19:02:12 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Jun 14 19:02:12 raspberrypi systemd[603]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Jun 14 19:02:12 raspberrypi systemd[603]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 14 19:02:12 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 3.
Jun 14 19:02:13 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 14 19:02:13 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Jun 14 19:02:13 raspberrypi systemd[710]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Jun 14 19:02:13 raspberrypi systemd[710]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 4.
Jun 14 19:02:13 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 14 19:02:13 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Jun 14 19:02:13 raspberrypi systemd[811]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Jun 14 19:02:13 raspberrypi systemd[811]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 5.
Jun 14 19:02:13 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Start request repeated too quickly.
Jun 14 19:02:13 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 14 19:02:13 raspberrypi systemd[1]: Failed to start Phoniebox Rotary Encoder Service.
Jun 14 19:02:13 raspberrypi systemd[1]: Started Samba NMB Daemon.
Jun 14 19:02:13 raspberrypi systemd[1]: Started Lighttpd Daemon.
Jun 14 19:02:13 raspberrypi systemd[1]: Starting Samba SMB Daemon...
Jun 14 19:02:14 raspberrypi exim4[476]: Starting MTA: exim4.
Jun 14 19:02:14 raspberrypi systemd[1]: Started LSB: exim Mail Transport Agent.
Jun 14 19:02:14 raspberrypi daemon_rfid_reader.py[475]: 2020-06-14 19:02:14,038 - root - INFO - Dir_PATH: /home/pi/RPi-Jukebox-RFID/scripts
Jun 14 19:02:14 raspberrypi systemd[1]: Started Samba SMB Daemon.
Jun 14 19:02:16 raspberrypi systemd[1]: Started Music Player Daemon.
Jun 14 19:02:16 raspberrypi systemd[1]: Starting Phoniebox Startup...
Jun 14 19:02:16 raspberrypi bash[845]: cat: /home/pi/RPi-Jukebox-RFID/scripts/../settings/WlanIpMailYN: No such file or directory
Jun 14 19:02:16 raspberrypi bash[845]: rm: cannot remove '/home/pi/RPi-Jukebox-RFID/scripts/../settings/global.conf': No such file or directory
Jun 14 19:02:17 raspberrypi bash[845]: AUDIOFOLDERSPATH="/home/pi/RPi-Jukebox-RFID/shared/audiofolders"
Jun 14 19:02:17 raspberrypi bash[845]: PLAYLISTSFOLDERPATH="/home/pi/RPi-Jukebox-RFID/playlists"
Jun 14 19:02:17 raspberrypi bash[845]: SECONDSWIPE="RESTART"
Jun 14 19:02:17 raspberrypi bash[845]: AUDIOIFACENAME="PCM"
Jun 14 19:02:17 raspberrypi bash[845]: AUDIOVOLCHANGESTEP="3"
Jun 14 19:02:17 raspberrypi bash[845]: AUDIOVOLMAXLIMIT="100"
Jun 14 19:02:17 raspberrypi bash[845]: AUDIOVOLMINLIMIT="1"
Jun 14 19:02:17 raspberrypi bash[845]: AUDIOVOLSTARTUP="0"
Jun 14 19:02:17 raspberrypi bash[845]: VOLCHANGEIDLE="TRUE"
Jun 14 19:02:17 raspberrypi bash[845]: IDLETIMESHUTDOWN="0"
Jun 14 19:02:17 raspberrypi bash[845]: SHOWCOVER="ON"
Jun 14 19:02:17 raspberrypi bash[845]: READWLANIPYN="OFF"
Jun 14 19:02:17 raspberrypi bash[845]: EDITION="classic"
Jun 14 19:02:17 raspberrypi bash[845]: LANG="en-UK"
Jun 14 19:02:17 raspberrypi bash[845]: VERSION="2.0 - ed888da - master"
Jun 14 19:02:17 raspberrypi bash[845]: 0
Jun 14 19:02:18 raspberrypi dhcpcd[473]: wlan0: fe80::1 is reachable again
Jun 14 19:02:18 raspberrypi dhcpcd[473]: wlan0: fe80::1 is reachable again
Jun 14 19:02:19 raspberrypi bash[845]: High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
Jun 14 19:02:19 raspberrypi bash[845]: #011version 1.25.10; written and copyright by Michael Hipp and others
Jun 14 19:02:19 raspberrypi bash[845]: #011free software (LGPL) without any warranty but with best wishes
Jun 14 19:02:19 raspberrypi bash[845]: Directory: /home/pi/RPi-Jukebox-RFID/shared/
Jun 14 19:02:19 raspberrypi bash[845]: Playing MPEG stream 1 of 1: startupsound.mp3 ...
Jun 14 19:02:19 raspberrypi bash[845]: MPEG 1.0 L III cbr64 44100 j-s
Jun 14 19:02:19 raspberrypi bash[845]: Artist:  Phoniebox
Jun 14 19:02:23 raspberrypi bash[845]: [0:04] Decoding of startupsound.mp3 finished.
Jun 14 19:02:23 raspberrypi systemd[1]: Started Phoniebox Startup.
Jun 14 19:02:31 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Jun 14 19:02:43 raspberrypi systemd-timesyncd[274]: Timed out waiting for reply from [2a01:4f8:192:4022::2]:123 (2.debian.pool.ntp.org).
Jun 14 19:02:56 raspberrypi systemd-timesyncd[274]: Synchronized to time server for the first time [2a03:4000:8:f6::123]:123 (2.debian.pool.ntp.org).
Jun 14 19:03:25 raspberrypi systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
Jun 14 19:03:41 raspberrypi systemd[1]: dev-serial1.device: Job dev-serial1.device/start timed out.
Jun 14 19:03:41 raspberrypi systemd[1]: Timed out waiting for device /dev/serial1.
Jun 14 19:03:41 raspberrypi systemd[1]: Dependency failed for Configure Bluetooth Modems connected by UART.
Jun 14 19:03:41 raspberrypi systemd[1]: hciuart.service: Job hciuart.service/start failed with result 'dependency'.
Jun 14 19:03:41 raspberrypi systemd[1]: dev-serial1.device: Job dev-serial1.device/start failed with result 'timeout'.
Jun 14 19:03:41 raspberrypi systemd[1]: Reached target Multi-User System.
Jun 14 19:03:41 raspberrypi systemd[1]: Reached target Graphical Interface.
Jun 14 19:03:41 raspberrypi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Jun 14 19:03:41 raspberrypi systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Jun 14 19:03:41 raspberrypi systemd[1]: Started Update UTMP about System Runlevel Changes.
Jun 14 19:03:41 raspberrypi systemd[1]: Startup finished in 3.008s (kernel) + 1min 32.285s (userspace) = 1min 35.294s.
Jun 14 19:05:57 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Jun 14 19:05:57 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Jun 14 19:05:57 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Jun 14 19:05:57 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Jun 14 19:05:57 raspberrypi systemd[964]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jun 14 19:05:57 raspberrypi systemd[964]: Reached target Timers.
Jun 14 19:05:57 raspberrypi systemd[964]: Reached target Paths.
Jun 14 19:05:57 raspberrypi systemd[964]: Listening on GnuPG cryptographic agent and passphrase cache.
Jun 14 19:05:57 raspberrypi systemd[964]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jun 14 19:05:57 raspberrypi systemd[964]: Listening on GnuPG network certificate management daemon.
Jun 14 19:05:57 raspberrypi systemd[964]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jun 14 19:05:57 raspberrypi systemd[964]: Reached target Sockets.
Jun 14 19:05:57 raspberrypi systemd[964]: Reached target Basic System.
Jun 14 19:05:57 raspberrypi systemd[1]: Started User Manager for UID 1000.
Jun 14 19:05:57 raspberrypi systemd[964]: Starting Music Player Daemon...
Jun 14 19:05:57 raspberrypi systemd[1]: Started Session c1 of user pi.
Jun 14 19:05:59 raspberrypi mpd[976]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
Jun 14 19:05:59 raspberrypi systemd[964]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Jun 14 19:05:59 raspberrypi systemd[964]: mpd.service: Failed with result 'exit-code'.
Jun 14 19:05:59 raspberrypi systemd[964]: Failed to start Music Player Daemon.
Jun 14 19:05:59 raspberrypi systemd[964]: Reached target Default.
Jun 14 19:05:59 raspberrypi systemd[964]: Startup finished in 2.262s.

@s-martin
Copy link
Collaborator

I think you need to use the correct Reader file.

Please try
cp /home/pi/RPi-Jukebox-RFID/scripts/Reader.py.kkmoonRFIDreader home/pi/RPi-Jukebox-RFID/scripts/Reader.py
and
sudo systemctl restart phoniebox-rfid-reader

@jochmann
Copy link

jochmann commented Jun 14, 2020 via email

@MiczFlor
Copy link
Owner

I think the copy location is missing the initial slash

cp /home/pi/RPi-Jukebox-RFID/scripts/Reader.py.kkmoonRFIDreader /home/pi/RPi-Jukebox-RFID/scripts/Reader.py

@s-martin
Copy link
Collaborator

I think the copy location is missing the initial slash

cp /home/pi/RPi-Jukebox-RFID/scripts/Reader.py.kkmoonRFIDreader /home/pi/RPi-Jukebox-RFID/scripts/Reader.py

Oops, sorry.
Thanks for catching that.

@jochmann
Copy link

jochmann commented Jun 14, 2020 via email

@s-martin
Copy link
Collaborator

s-martin commented Jun 14, 2020

What's the output of
sudo tail -n 200 /var/log/lighttpd/error.log

and
tail -n 200 /var/log/syslog right after you swiped a card?

@jochmann
Copy link

jochmann commented Jun 14, 2020 via email

@jochmann
Copy link

jochmann commented Jun 14, 2020 via email

@s-martin
Copy link
Collaborator

s-martin commented Jun 15, 2020

In this line

cardid = reader.reader.readCard()

you have to remove one occurrance of reader so that the line is only cardid = reader.readCard().

Afterwards please use sudo systemctl restart phoniebox-rfid-reader

@jochmann
Copy link

can confirm that the line now reads cardid = reader.readCard() but after the sudo command and also after subsequent reboot, no change in bahavior.

@s-martin
Copy link
Collaborator

Ok, can you post the syslog results after a card swipe again?

@jochmann
Copy link

jochmann commented Jun 15, 2020

Jun 15 09:07:09 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 15 09:07:09 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 15 09:07:09 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 15 09:07:09 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 3.
Jun 15 09:07:09 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 15 09:07:09 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Jun 15 09:07:09 raspberrypi systemd[580]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Jun 15 09:07:09 raspberrypi systemd[580]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Jun 15 09:07:09 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 15 09:07:09 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 4.
Jun 15 09:07:10 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 15 09:07:10 raspberrypi systemd[1]: Started Phoniebox Rotary Encoder Service.
Jun 15 09:07:10 raspberrypi systemd[642]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
Jun 15 09:07:10 raspberrypi systemd[642]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 5.
Jun 15 09:07:10 raspberrypi systemd[1]: Stopped Phoniebox Rotary Encoder Service.
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Start request repeated too quickly.
Jun 15 09:07:10 raspberrypi systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
Jun 15 09:07:10 raspberrypi systemd[1]: Failed to start Phoniebox Rotary Encoder Service.
Jun 15 09:07:11 raspberrypi systemd[1]: Started Samba NMB Daemon.
Jun 15 09:07:11 raspberrypi systemd[1]: Starting Samba SMB Daemon...
Jun 15 09:07:11 raspberrypi systemd[1]: Started Lighttpd Daemon.
Jun 15 09:07:11 raspberrypi exim4[476]: Starting MTA: exim4.
Jun 15 09:07:11 raspberrypi systemd[1]: Started LSB: exim Mail Transport Agent.
Jun 15 09:07:11 raspberrypi daemon_rfid_reader.py[492]: 2020-06-15 09:07:11,472 - root - INFO - Dir_PATH: /home/pi/RPi-Jukebox-RFID/scripts
Jun 15 09:07:12 raspberrypi systemd[1]: Started Samba SMB Daemon.
Jun 15 09:07:13 raspberrypi systemd[1]: Started Music Player Daemon.
Jun 15 09:07:13 raspberrypi systemd[1]: Starting Phoniebox Startup...
Jun 15 09:07:13 raspberrypi bash[850]: AUDIOFOLDERSPATH="/home/pi/RPi-Jukebox-RFID/shared/audiofolders"
Jun 15 09:07:13 raspberrypi bash[850]: PLAYLISTSFOLDERPATH="/home/pi/RPi-Jukebox-RFID/playlists"
Jun 15 09:07:13 raspberrypi bash[850]: SECONDSWIPE="RESTART"
Jun 15 09:07:13 raspberrypi bash[850]: AUDIOIFACENAME="PCM"
Jun 15 09:07:13 raspberrypi bash[850]: AUDIOVOLCHANGESTEP="3"
Jun 15 09:07:13 raspberrypi bash[850]: AUDIOVOLMAXLIMIT="100"
Jun 15 09:07:13 raspberrypi bash[850]: AUDIOVOLMINLIMIT="1"
Jun 15 09:07:13 raspberrypi bash[850]: AUDIOVOLSTARTUP="0"
Jun 15 09:07:13 raspberrypi bash[850]: VOLCHANGEIDLE="TRUE"
Jun 15 09:07:13 raspberrypi bash[850]: IDLETIMESHUTDOWN="0"
Jun 15 09:07:13 raspberrypi bash[850]: SHOWCOVER="ON"
Jun 15 09:07:13 raspberrypi bash[850]: READWLANIPYN="OFF"
Jun 15 09:07:13 raspberrypi bash[850]: EDITION="classic"
Jun 15 09:07:13 raspberrypi bash[850]: LANG="en-UK"
Jun 15 09:07:13 raspberrypi bash[850]: VERSION="2.0 - ed888da - master"
Jun 15 09:07:13 raspberrypi bash[850]: 0
Jun 15 09:07:15 raspberrypi bash[850]: High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
Jun 15 09:07:15 raspberrypi bash[850]: #011version 1.25.10; written and copyright by Michael Hipp and others
Jun 15 09:07:15 raspberrypi bash[850]: #011free software (LGPL) without any warranty but with best wishes
Jun 15 09:07:16 raspberrypi bash[850]: Directory: /home/pi/RPi-Jukebox-RFID/shared/
Jun 15 09:07:16 raspberrypi bash[850]: Playing MPEG stream 1 of 1: startupsound.mp3 ...
Jun 15 09:07:16 raspberrypi bash[850]: MPEG 1.0 L III cbr64 44100 j-s
Jun 15 09:07:16 raspberrypi bash[850]: Artist:  Phoniebox
Jun 15 09:07:16 raspberrypi dhcpcd[474]: wlan0: fe80::1 is reachable again
Jun 15 09:07:16 raspberrypi dhcpcd[474]: wlan0: fe80::1 is reachable again
Jun 15 09:07:20 raspberrypi bash[850]: [0:04] Decoding of startupsound.mp3 finished.
Jun 15 09:07:20 raspberrypi systemd[1]: Started Phoniebox Startup.
Jun 15 09:07:29 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Jun 15 09:07:41 raspberrypi systemd-timesyncd[277]: Synchronized to time server for the first time [2001:638:708:30c9:708c:f9ff:fea9:fbe5]:123 (2.debian.pool.ntp.org).
Jun 15 09:08:21 raspberrypi systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
Jun 15 09:08:36 raspberrypi systemd[1]: dev-serial1.device: Job dev-serial1.device/start timed out.
Jun 15 09:08:36 raspberrypi systemd[1]: Timed out waiting for device /dev/serial1.
Jun 15 09:08:36 raspberrypi systemd[1]: Dependency failed for Configure Bluetooth Modems connected by UART.
Jun 15 09:08:36 raspberrypi systemd[1]: hciuart.service: Job hciuart.service/start failed with result 'dependency'.
Jun 15 09:08:36 raspberrypi systemd[1]: dev-serial1.device: Job dev-serial1.device/start failed with result 'timeout'.
Jun 15 09:08:36 raspberrypi systemd[1]: Reached target Multi-User System.
Jun 15 09:08:36 raspberrypi systemd[1]: Reached target Graphical Interface.
Jun 15 09:08:36 raspberrypi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Jun 15 09:08:37 raspberrypi systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Jun 15 09:08:37 raspberrypi systemd[1]: Started Update UTMP about System Runlevel Changes.
Jun 15 09:08:37 raspberrypi systemd[1]: Startup finished in 3.021s (kernel) + 1min 32.030s (userspace) = 1min 35.051s.
Jun 15 09:09:01 raspberrypi CRON[1045]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jun 15 09:09:04 raspberrypi systemd[1]: Starting Clean php session files...
Jun 15 09:09:04 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Jun 15 09:09:04 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Jun 15 09:09:04 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Jun 15 09:09:04 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Jun 15 09:09:04 raspberrypi systemd[1065]: Listening on GnuPG cryptographic agent and passphrase cache.
Jun 15 09:09:05 raspberrypi systemd[1065]: Reached target Timers.
Jun 15 09:09:05 raspberrypi systemd[1065]: Reached target Paths.
Jun 15 09:09:05 raspberrypi systemd[1065]: Listening on GnuPG network certificate management daemon.
Jun 15 09:09:05 raspberrypi systemd[1065]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jun 15 09:09:05 raspberrypi systemd[1065]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jun 15 09:09:05 raspberrypi systemd[1065]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jun 15 09:09:05 raspberrypi systemd[1065]: Reached target Sockets.
Jun 15 09:09:05 raspberrypi systemd[1065]: Reached target Basic System.
Jun 15 09:09:05 raspberrypi systemd[1]: Started User Manager for UID 1000.
Jun 15 09:09:05 raspberrypi systemd[1065]: Starting Music Player Daemon...
Jun 15 09:09:05 raspberrypi systemd[1]: Started Session c1 of user pi.
Jun 15 09:09:05 raspberrypi systemd[1]: phpsessionclean.service: Succeeded.
Jun 15 09:09:05 raspberrypi systemd[1]: Started Clean php session files.
Jun 15 09:09:06 raspberrypi mpd[1103]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
Jun 15 09:09:06 raspberrypi systemd[1065]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Jun 15 09:09:06 raspberrypi systemd[1065]: mpd.service: Failed with result 'exit-code'.
Jun 15 09:09:06 raspberrypi systemd[1065]: Failed to start Music Player Daemon.
Jun 15 09:09:06 raspberrypi systemd[1065]: Reached target Default.
Jun 15 09:09:06 raspberrypi systemd[1065]: Startup finished in 2.387s.
Jun 15 09:09:32 raspberrypi systemd[1]: session-c1.scope: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1]: Stopping User Manager for UID 1000...
Jun 15 09:09:42 raspberrypi systemd[1065]: Stopped target Default.
Jun 15 09:09:42 raspberrypi systemd[1065]: Stopped target Basic System.
Jun 15 09:09:42 raspberrypi systemd[1065]: Stopped target Sockets.
Jun 15 09:09:42 raspberrypi systemd[1065]: dirmngr.socket: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1065]: Closed GnuPG network certificate management daemon.
Jun 15 09:09:42 raspberrypi systemd[1065]: gpg-agent-extra.socket: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1065]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Jun 15 09:09:42 raspberrypi systemd[1065]: Stopped target Paths.
Jun 15 09:09:42 raspberrypi systemd[1065]: gpg-agent-browser.socket: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1065]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jun 15 09:09:42 raspberrypi systemd[1065]: gpg-agent-ssh.socket: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1065]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Jun 15 09:09:42 raspberrypi systemd[1065]: Stopped target Timers.
Jun 15 09:09:42 raspberrypi systemd[1065]: gpg-agent.socket: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1065]: Closed GnuPG cryptographic agent and passphrase cache.
Jun 15 09:09:42 raspberrypi systemd[1065]: Reached target Shutdown.
Jun 15 09:09:42 raspberrypi systemd[1065]: systemd-exit.service: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1065]: Started Exit the Session.
Jun 15 09:09:42 raspberrypi systemd[1065]: Reached target Exit the Session.
Jun 15 09:09:42 raspberrypi systemd[1]: [email protected]: Succeeded.
Jun 15 09:09:42 raspberrypi systemd[1]: Stopped User Manager for UID 1000.
Jun 15 09:09:43 raspberrypi systemd[1]: Stopping User Runtime Directory /run/user/1000...
Jun 15 09:09:43 raspberrypi systemd[1]: run-user-1000.mount: Succeeded.
Jun 15 09:09:43 raspberrypi systemd[1]: [email protected]: Succeeded.
Jun 15 09:09:43 raspberrypi systemd[1]: Stopped User Runtime Directory /run/user/1000.
Jun 15 09:09:43 raspberrypi systemd[1]: Removed slice User Slice of UID 1000.
Jun 15 09:09:44 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Jun 15 09:09:44 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Jun 15 09:09:44 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Jun 15 09:09:44 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Jun 15 09:09:44 raspberrypi systemd[1141]: Reached target Paths.
Jun 15 09:09:44 raspberrypi systemd[1141]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jun 15 09:09:44 raspberrypi systemd[1141]: Listening on GnuPG network certificate management daemon.
Jun 15 09:09:44 raspberrypi systemd[1141]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jun 15 09:09:44 raspberrypi systemd[1141]: Listening on GnuPG cryptographic agent and passphrase cache.
Jun 15 09:09:44 raspberrypi systemd[1141]: Reached target Timers.
Jun 15 09:09:44 raspberrypi systemd[1141]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jun 15 09:09:44 raspberrypi systemd[1141]: Reached target Sockets.
Jun 15 09:09:44 raspberrypi systemd[1141]: Reached target Basic System.
Jun 15 09:09:44 raspberrypi systemd[1]: Started User Manager for UID 1000.
Jun 15 09:09:44 raspberrypi systemd[1141]: Starting Music Player Daemon...
Jun 15 09:09:44 raspberrypi systemd[1]: Started Session c2 of user pi.
Jun 15 09:09:46 raspberrypi mpd[1153]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
Jun 15 09:09:46 raspberrypi systemd[1141]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Jun 15 09:09:46 raspberrypi systemd[1141]: mpd.service: Failed with result 'exit-code'.
Jun 15 09:09:46 raspberrypi systemd[1141]: Failed to start Music Player Daemon.
Jun 15 09:09:46 raspberrypi systemd[1141]: Reached target Default.
Jun 15 09:09:46 raspberrypi systemd[1141]: Startup finished in 2.081s.
Jun 15 09:14:11 raspberrypi systemd[1]: session-c2.scope: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1]: Stopping User Manager for UID 1000...
Jun 15 09:14:21 raspberrypi systemd[1141]: Stopped target Default.
Jun 15 09:14:21 raspberrypi systemd[1141]: Stopped target Basic System.
Jun 15 09:14:21 raspberrypi systemd[1141]: Stopped target Paths.
Jun 15 09:14:21 raspberrypi systemd[1141]: Stopped target Timers.
Jun 15 09:14:21 raspberrypi systemd[1141]: Stopped target Sockets.
Jun 15 09:14:21 raspberrypi systemd[1141]: gpg-agent-ssh.socket: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1141]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Jun 15 09:14:21 raspberrypi systemd[1141]: gpg-agent-extra.socket: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1141]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Jun 15 09:14:21 raspberrypi systemd[1141]: gpg-agent-browser.socket: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1141]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jun 15 09:14:21 raspberrypi systemd[1141]: dirmngr.socket: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1141]: Closed GnuPG network certificate management daemon.
Jun 15 09:14:21 raspberrypi systemd[1141]: gpg-agent.socket: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1141]: Closed GnuPG cryptographic agent and passphrase cache.
Jun 15 09:14:21 raspberrypi systemd[1141]: Reached target Shutdown.
Jun 15 09:14:21 raspberrypi systemd[1141]: systemd-exit.service: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1141]: Started Exit the Session.
Jun 15 09:14:21 raspberrypi systemd[1141]: Reached target Exit the Session.
Jun 15 09:14:21 raspberrypi systemd[1]: [email protected]: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1]: Stopped User Manager for UID 1000.
Jun 15 09:14:21 raspberrypi systemd[1]: Stopping User Runtime Directory /run/user/1000...
Jun 15 09:14:21 raspberrypi systemd[1]: run-user-1000.mount: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1]: [email protected]: Succeeded.
Jun 15 09:14:21 raspberrypi systemd[1]: Stopped User Runtime Directory /run/user/1000.
Jun 15 09:14:21 raspberrypi systemd[1]: Removed slice User Slice of UID 1000.
Jun 15 09:15:30 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Jun 15 09:15:30 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Jun 15 09:15:30 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Jun 15 09:15:30 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Jun 15 09:15:30 raspberrypi systemd[1239]: Listening on GnuPG cryptographic agent and passphrase cache.
Jun 15 09:15:30 raspberrypi systemd[1239]: Listening on GnuPG network certificate management daemon.
Jun 15 09:15:30 raspberrypi systemd[1239]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jun 15 09:15:30 raspberrypi systemd[1239]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jun 15 09:15:30 raspberrypi systemd[1239]: Reached target Timers.
Jun 15 09:15:30 raspberrypi systemd[1239]: Reached target Paths.
Jun 15 09:15:30 raspberrypi systemd[1239]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jun 15 09:15:30 raspberrypi systemd[1239]: Reached target Sockets.
Jun 15 09:15:30 raspberrypi systemd[1239]: Reached target Basic System.
Jun 15 09:15:30 raspberrypi systemd[1]: Started User Manager for UID 1000.
Jun 15 09:15:30 raspberrypi systemd[1239]: Starting Music Player Daemon...
Jun 15 09:15:30 raspberrypi systemd[1]: Started Session c3 of user pi.
Jun 15 09:15:32 raspberrypi mpd[1251]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
Jun 15 09:15:32 raspberrypi systemd[1239]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Jun 15 09:15:32 raspberrypi systemd[1239]: mpd.service: Failed with result 'exit-code'.
Jun 15 09:15:32 raspberrypi systemd[1239]: Failed to start Music Player Daemon.
Jun 15 09:15:32 raspberrypi systemd[1239]: Reached target Default.
Jun 15 09:15:32 raspberrypi systemd[1239]: Startup finished in 2.094s.

@s-martin
Copy link
Collaborator

Did y swipe a card before you read the log?

What does the lighttpd log say?

@MiczFlor
Copy link
Owner

hi @jochmann
you had a Phoniebox running before. was that the same hardware?

@jochmann
Copy link

jochmann commented Feb 7, 2021

@MiczFlor just to tie a bow on this, after I had to take some time off trouble shooting (was too frustrating to continue and then 2020 really got in the way, sorry):

Yes, I was running the same hardware before, which is why I never could understand or reproduce the original state. After reading #1046 did I finally get it: I must have swiped the working phoniebox with the configuration card, thus setting the reader into an unusable state. Running the fix described in the issue finally worked. Thank you so much for updating the docs so I could stumble across it!

I still think that the installation script could be a problem: Repeatedly I've experienced that a library was missing in the installation process due to connection issues with the relevant IPs online. The process continues to run, though, instead of abandoning right away and telling me about it. And only if you have at least passing experience with *nix can you tell and fix after the fact with some apt-get update or rerun of the installation routine. I don't know if this is an easy fix or even a problem for others, though.

@Sascha4546
Copy link

Sascha4546 commented Jul 13, 2022

Hello, i noticed that Neuftech changed the pcb of the reader ... i have the old and the new one here... the old version works fine and the new one seems to make problems

https://bilderupload.org/bild/404233483-old-works-fine
https://bilderupload.org/bild/d0f533530-new-causing-problems

@s-martin
Copy link
Collaborator

Hello, i noticed that Neuftech changed the pcb of the reader ... i have the old and the new one here... the old version works fine and the new one seems to make problems

https://bilderupload.org/bild/404233483-old-works-fine https://bilderupload.org/bild/d0f533530-new-causing-problems

Could you open a new issue (and include the pictures in the issue itself)?

Comments in already closed issues are usually overlooked, because they are considered done and nobody opens them.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

5 participants