lepresenced und G-Tags - nach einiger Zeit nur noch absent/unreachable

[stiefl]

Guten Morgen,

hatte jetzt nur kurz Zeit für einen Test. Bei erneutem/verzögertem Start dürfts wieder richtig funktionieren. Beide G-Tags bleiben present.

Den Filter hab ich gestern schon geändert  mich nervt sowas selber. Das kam durch die Änderung auf hci1 

[PatrickR]

Mahlzeit! Hatte gestern nochmal die LSB-Zeilen des Initscripts aktualisiert, um die Startreihenfolge zu fixen, aber systemd interessiert das leider nicht. Werde wohl in den sauren Apfel beißen müssen und es direkt mit systemd machen.

Patrick


Von unterwegs gesendet.

[PatrickR]

Guten Abend!

Anbei ein aktualisiertes Paket zum Testen, ob sich lepresenced und bluetooth beim Start noch verhaken. Ich musste leider etwas tricksen, da systemd trotz expliziter Abhängigkeit von von bluetooth.service lepresenced zu früh startet.

Patrick

[Lucky2k12]

Danke, ich habs installiert, neu gestartet und läuft auf Anhieb.
Ich werde weiter beobachten.

[PatrickR]

Danke, ich habs installiert, neu gestartet und läuft auf Anhieb.
Ich werde weiter beobachten.

Sehr gut, musste nämlich für die Umstellung auf poetteringd einiges umbauen.

Hattest Du vorher das Problem mit der Startreihenfolge?


Von unterwegs gesendet.

[stiefl]

Hi Patrick,

soeben installiert und sowohl ohne Bluetooth-Dongle als auch mit getestet. Lepresenced startet jetzt ganz zum Schluss und schaut bis jetzt sehr gut aus. Anbei aktueller Syslog mit angestecktem Dongle:

Code Auswählen Erweitern

Sep  2 14:24:59 raspberrypi systemd[1]: Mounting Configuration File System...
Sep  2 14:24:59 raspberrypi systemd[1]: Mounted FUSE Control File System.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Apply Kernel Variables...
Sep  2 14:24:59 raspberrypi systemd[1]: Mounted Configuration File System.
Sep  2 14:24:59 raspberrypi systemd[1]: Started File System Check on Root Device.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Apply Kernel Variables.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Create Static Device Nodes in /dev.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting udev Kernel Device Manager...
Sep  2 14:24:59 raspberrypi systemd-fsck[108]: e2fsck 1.43.3 (04-Sep-2016)
Sep  2 14:24:59 raspberrypi systemd-fsck[108]: /dev/mmcblk0p2: clean, 43396/465392 files, 347898/1923584 blocks
Sep  2 14:24:59 raspberrypi systemd[1]: Started udev Kernel Device Manager.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Copy rules generated while the root was ro...
Sep  2 14:24:59 raspberrypi fake-hwclock[110]: Sat  2 Sep 12:24:57 UTC 2017
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: Set preliminary keymap...
Sep  2 14:24:59 raspberrypi systemd[1]: Started Copy rules generated while the root was ro.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Sound Card.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Sound Card.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting system-systemd\x2drfkill.slice.
Sep  2 14:24:59 raspberrypi systemd[1]: Created slice system-systemd\x2drfkill.slice.
Sep  2 14:24:59 raspberrypi systemd[1]: Mounted Huge Pages File System.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Set Up Additional Binary Formats.
Sep  2 14:24:59 raspberrypi systemd[1]: Mounted FUSE Control File System.
Sep  2 14:24:59 raspberrypi keyboard-setup[147]: Setting preliminary keymap...done.
Sep  2 14:24:59 raspberrypi systemd[1]: Started LSB: Set preliminary keymap.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Show Plymouth Boot Screen...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Remount Root and Kernel File Systems...
Sep  2 14:24:59 raspberrypi systemd[1]: Found device /dev/disk/by-partuuid/3cb9faaa-01.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting File System Check on /dev/disk/by-partuuid/3cb9faaa-01...
Sep  2 14:24:59 raspberrypi systemd[1]: Started Remount Root and Kernel File Systems.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status of rfkill0...
Sep  2 14:24:59 raspberrypi systemd[1]: Started Various fixups to make systemd work better on Debian.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Load/Save Random Seed...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Local File Systems (Pre).
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Local File Systems (Pre).
Sep  2 14:24:59 raspberrypi systemd[1]: Started Load/Save Random Seed.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status of rfkill0.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status of rfkill1...
Sep  2 14:24:59 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status of rfkill1.
Sep  2 14:24:59 raspberrypi systemd[1]: Received SIGRTMIN+20 from PID 265 (plymouthd).
Sep  2 14:24:59 raspberrypi systemd[1]: Started Show Plymouth Boot Screen.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Forward Password Requests to Plymouth Directory Watch.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Forward Password Requests to Plymouth Directory Watch.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Paths.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Paths.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting system-ifup.slice.
Sep  2 14:24:59 raspberrypi systemd[1]: Created slice system-ifup.slice.
Sep  2 14:24:59 raspberrypi systemd-fsck[258]: fsck.fat 3.0.27 (2014-11-12)
Sep  2 14:24:59 raspberrypi systemd-fsck[258]: /dev/mmcblk0p1: 145 files, 42838/84059 clusters
Sep  2 14:24:59 raspberrypi systemd[1]: Started File System Check on /dev/disk/by-partuuid/3cb9faaa-01.
Sep  2 14:24:59 raspberrypi systemd[1]: Mounting /boot...
Sep  2 14:24:59 raspberrypi systemd[1]: Mounted /boot.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Local File Systems.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Local File Systems.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Tell Plymouth To Write Out Runtime Data...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Create Volatile Files and Directories...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Remote File Systems.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Remote File Systems.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Trigger Flushing of Journal to Persistent Storage...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: Switch to ondemand cpu governor (unless shift key is pressed)...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: Prepare console...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: Raise network interfaces....
Sep  2 14:24:59 raspberrypi systemd[1]: Started Trigger Flushing of Journal to Persistent Storage.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Tell Plymouth To Write Out Runtime Data.
Sep  2 14:24:59 raspberrypi raspi-config[288]: Checking if shift key is held down:Error opening '/dev/input/event*': No such file or directory
Sep  2 14:24:59 raspberrypi raspi-config[288]: No. Switching to ondemand scaling governor.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Create Volatile Files and Directories.
Sep  2 14:24:59 raspberrypi systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Sep  2 14:24:59 raspberrypi kbd[289]: Setting console screen modes.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Sep  2 14:24:59 raspberrypi systemd[1]: Started Update UTMP about System Boot/Shutdown.
Sep  2 14:24:59 raspberrypi kbd[289]: setterm: $TERM is not defined.
Sep  2 14:24:59 raspberrypi systemd[1]: Started LSB: Prepare console.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: Set console font and keymap...
Sep  2 14:24:59 raspberrypi console-setup[341]: Setting up console font and keymap...done.
Sep  2 14:24:59 raspberrypi systemd[1]: Started LSB: Set console font and keymap.
Sep  2 14:24:59 raspberrypi networking[290]: Configuring network interfaces...done.
Sep  2 14:24:59 raspberrypi systemd[1]: Started LSB: Raise network interfaces..
Sep  2 14:24:59 raspberrypi systemd[1]: Starting ifup for wlan0...
Sep  2 14:24:59 raspberrypi systemd[1]: Started ifup for wlan0.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting System Initialization.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target System Initialization.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack Activation Socket.
Sep  2 14:24:59 raspberrypi systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting D-Bus System Message Bus Socket.
Sep  2 14:24:59 raspberrypi systemd[1]: Listening on D-Bus System Message Bus Socket.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Sockets.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Sockets.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Daily Cleanup of Temporary Directories.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Daily Cleanup of Temporary Directories.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Timers.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Timers.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Manage Sound Card State (restore and store).
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Restore Sound Card State...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Basic System.
Sep  2 14:24:59 raspberrypi systemd[1]: Reached target Basic System.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting System Logging Service...
Sep  2 14:24:59 raspberrypi systemd[1]: Started Turn on SSH if /boot/ssh is present.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Regular background program processing daemon...
Sep  2 14:24:59 raspberrypi systemd[1]: Started Regular background program processing daemon.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Configure Bluetooth Modems connected by UART...
Sep  2 14:24:59 raspberrypi systemd[1]: Started getty on tty2-tty6 if dbus and logind are not available.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting D-Bus System Message Bus...
Sep  2 14:24:59 raspberrypi systemd[1]: Started D-Bus System Message Bus.
Sep  2 14:24:59 raspberrypi cron[444]: (CRON) INFO (pidfile fd = 3)
Sep  2 14:24:59 raspberrypi dhcpcd[438]: version 6.7.1 starting
Sep  2 14:24:59 raspberrypi dhcpcd[438]: dev: loaded udev
Sep  2 14:24:59 raspberrypi dhcpcd[438]: eth0: adding address fe80::9a56:fcf4:d191:389a
Sep  2 14:24:59 raspberrypi dhcpcd[438]: wlan0: adding address fe80::ffca:ed7e:16ea:d574
Sep  2 14:24:59 raspberrypi cron[444]: (CRON) INFO (Running @reboot jobs)
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: Found user 'avahi' (UID 105) and group 'avahi' (GID 110).
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: Successfully dropped root privileges.
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: avahi-daemon 0.6.31 starting up.
Sep  2 14:24:59 raspberrypi wpa_supplicant[451]: Successfully initialized wpa_supplicant
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Booting Linux on physical CPU 0x0
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Linux version 4.9.35-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #1014 SMP Fri Jun 30 14:47:43 BST 2017
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] CPU: div instructions available: patching division code
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] OF: fdt:Machine model: Raspberry Pi 3 Model B Rev 1.2
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] cma: Reserved 8 MiB at 0x3a800000
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Memory policy: Data cache writealloc
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] On node 0 totalpages: 241664
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] free_area_init_node: node 0, pgdat 80c6ee40, node_mem_map b9faa000
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]   Normal zone: 2124 pages used for memmap
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]   Normal zone: 0 pages reserved
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]   Normal zone: 241664 pages, LIFO batch:31
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] percpu: Embedded 14 pages/cpu @b9f64000 s25600 r8192 d23552 u57344
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] pcpu-alloc: s25600 r8192 d23552 u57344 alloc=14*4096
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 239540
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000  dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=3cb9faaa-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Memory: 936296K/966656K available (7168K kernel code, 484K rwdata, 2012K rodata, 1024K init, 778K bss, 22168K reserved, 8192K cma-reserved)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Virtual kernel memory layout:
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]     vmalloc : 0xbb800000 - 0xff800000   (1088 MB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]     lowmem  : 0x80000000 - 0xbb000000   ( 944 MB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]       .text : 0x80008000 - 0x80800000   (8160 kB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]       .init : 0x80b00000 - 0x80c00000   (1024 kB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]       .data : 0x80c00000 - 0x80c79014   ( 485 kB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000]        .bss : 0x80c7b000 - 0x80d3da64   ( 779 kB)
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Hierarchical RCU implementation.
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] Build-time adjustment of leaf fanout to 32.
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] NR_IRQS:16 nr_irqs:16 16
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] arm_arch_timer: Architected cp15 timer(s) running at 19.20MHz (phys).
Sep  2 14:24:59 raspberrypi kernel: [    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
Sep  2 14:24:59 raspberrypi kernel: [    0.000009] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
Sep  2 14:24:59 raspberrypi kernel: [    0.000025] Switching to timer-based delay loop, resolution 52ns
Sep  2 14:24:59 raspberrypi kernel: [    0.000335] Console: colour dummy device 80x30
Sep  2 14:24:59 raspberrypi kernel: [    0.001225] console [tty1] enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.001279] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
Sep  2 14:24:59 raspberrypi kernel: [    0.001350] pid_max: default: 32768 minimum: 301
Sep  2 14:24:59 raspberrypi kernel: [    0.001711] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.001753] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.002778] Disabling cpuset control group subsystem
Sep  2 14:24:59 raspberrypi kernel: [    0.002970] CPU: Testing write buffer coherency: ok
Sep  2 14:24:59 raspberrypi kernel: [    0.003043] ftrace: allocating 22390 entries in 66 pages
Sep  2 14:24:59 raspberrypi kernel: [    0.055545] CPU0: update cpu_capacity 1024
Sep  2 14:24:59 raspberrypi kernel: [    0.055612] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Sep  2 14:24:59 raspberrypi kernel: [    0.055714] Setting up static identity map for 0x100000 - 0x100034
Sep  2 14:24:59 raspberrypi kernel: [    0.057961] CPU1: update cpu_capacity 1024
Sep  2 14:24:59 raspberrypi kernel: [    0.057968] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
Sep  2 14:24:59 raspberrypi kernel: [    0.058691] CPU2: update cpu_capacity 1024
Sep  2 14:24:59 raspberrypi kernel: [    0.058698] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
Sep  2 14:24:59 raspberrypi kernel: [    0.059367] CPU3: update cpu_capacity 1024
Sep  2 14:24:59 raspberrypi kernel: [    0.059374] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
Sep  2 14:24:59 raspberrypi kernel: [    0.059457] Brought up 4 CPUs
Sep  2 14:24:59 raspberrypi kernel: [    0.059629] SMP: Total of 4 processors activated (153.60 BogoMIPS).
Sep  2 14:24:59 raspberrypi kernel: [    0.059659] CPU: All CPU(s) started in HYP mode.
Sep  2 14:24:59 raspberrypi kernel: [    0.059685] CPU: Virtualization extensions available.
Sep  2 14:24:59 raspberrypi kernel: [    0.060507] devtmpfs: initialized
Sep  2 14:24:59 raspberrypi kernel: [    0.071510] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
Sep  2 14:24:59 raspberrypi kernel: [    0.071833] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
Sep  2 14:24:59 raspberrypi kernel: [    0.071895] futex hash table entries: 1024 (order: 4, 65536 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.072458] pinctrl core: initialized pinctrl subsystem
Sep  2 14:24:59 raspberrypi kernel: [    0.073378] NET: Registered protocol family 16
Sep  2 14:24:59 raspberrypi kernel: [    0.075632] DMA: preallocated 1024 KiB pool for atomic coherent allocations
Sep  2 14:24:59 raspberrypi kernel: [    0.084498] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
Sep  2 14:24:59 raspberrypi kernel: [    0.084546] hw-breakpoint: maximum watchpoint size is 8 bytes.
Sep  2 14:24:59 raspberrypi kernel: [    0.084718] Serial: AMBA PL011 UART driver
Sep  2 14:24:59 raspberrypi kernel: [    0.086616] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.087161] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
Sep  2 14:24:59 raspberrypi kernel: [    0.087525] irq: no irq domain found for /soc/aux@0x7e215000 !
Sep  2 14:24:59 raspberrypi kernel: [    0.156104] bcm2835-dma 3f007000.dma: DMA legacy API manager at bb80f000, dmachans=0x1
Sep  2 14:24:59 raspberrypi kernel: [    0.157977] SCSI subsystem initialized
Sep  2 14:24:59 raspberrypi kernel: [    0.158154] usbcore: registered new interface driver usbfs
Sep  2 14:24:59 raspberrypi kernel: [    0.158255] usbcore: registered new interface driver hub
Sep  2 14:24:59 raspberrypi kernel: [    0.158369] usbcore: registered new device driver usb
Sep  2 14:24:59 raspberrypi kernel: [    0.165093] raspberrypi-firmware soc:firmware: Attached to firmware from 2017-07-03 14:16
Sep  2 14:24:59 raspberrypi kernel: [    0.166484] clocksource: Switched to clocksource arch_sys_counter
Sep  2 14:24:59 raspberrypi kernel: [    0.213344] VFS: Disk quotas dquot_6.6.0
Sep  2 14:24:59 raspberrypi kernel: [    0.213454] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.213682] FS-Cache: Loaded
Sep  2 14:24:59 raspberrypi kernel: [    0.213947] CacheFiles: Loaded
Sep  2 14:24:59 raspberrypi kernel: [    0.226211] NET: Registered protocol family 2
Sep  2 14:24:59 raspberrypi kernel: [    0.227155] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.227292] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.227503] TCP: Hash tables configured (established 8192 bind 8192)
Sep  2 14:24:59 raspberrypi kernel: [    0.227615] UDP hash table entries: 512 (order: 2, 16384 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.227683] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    0.227916] NET: Registered protocol family 1
Sep  2 14:24:59 raspberrypi kernel: [    0.228346] RPC: Registered named UNIX socket transport module.
Sep  2 14:24:59 raspberrypi kernel: [    0.228379] RPC: Registered udp transport module.
Sep  2 14:24:59 raspberrypi kernel: [    0.228406] RPC: Registered tcp transport module.
Sep  2 14:24:59 raspberrypi kernel: [    0.228434] RPC: Registered tcp NFSv4.1 backchannel transport module.
Sep  2 14:24:59 raspberrypi kernel: [    0.229376] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
Sep  2 14:24:59 raspberrypi kernel: [    0.231687] workingset: timestamp_bits=14 max_order=18 bucket_order=4
Sep  2 14:24:59 raspberrypi kernel: [    0.247824] FS-Cache: Netfs 'nfs' registered for caching
Sep  2 14:24:59 raspberrypi kernel: [    0.248827] NFS: Registering the id_resolver key type
Sep  2 14:24:59 raspberrypi kernel: [    0.248884] Key type id_resolver registered
Sep  2 14:24:59 raspberrypi kernel: [    0.248912] Key type id_legacy registered
Sep  2 14:24:59 raspberrypi kernel: [    0.251362] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
Sep  2 14:24:59 raspberrypi kernel: [    0.251507] io scheduler noop registered
Sep  2 14:24:59 raspberrypi kernel: [    0.251537] io scheduler deadline registered (default)
Sep  2 14:24:59 raspberrypi kernel: [    0.251847] io scheduler cfq registered
Sep  2 14:24:59 raspberrypi kernel: [    0.257550] BCM2708FB: allocated DMA memory fa910000
Sep  2 14:24:59 raspberrypi kernel: [    0.257605] BCM2708FB: allocated DMA channel 0 @ bb80f000
Sep  2 14:24:59 raspberrypi kernel: [    0.266296] Console: switching to colour frame buffer device 82x26
Sep  2 14:24:59 raspberrypi kernel: [    0.273767] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.277667] bcm2835-aux-uart 3f215040.serial: could not get clk: -517
Sep  2 14:24:59 raspberrypi kernel: [    0.281017] bcm2835-rng 3f104000.rng: hwrng registered
Sep  2 14:24:59 raspberrypi kernel: [    0.283430] vc-cma: Videocore CMA driver
Sep  2 14:24:59 raspberrypi kernel: [    0.285785] vc-cma: vc_cma_base      = 0x00000000
Sep  2 14:24:59 raspberrypi kernel: [    0.288181] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
Sep  2 14:24:59 raspberrypi kernel: [    0.290447] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
Sep  2 14:24:59 raspberrypi kernel: [    0.292802] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB)
Sep  2 14:24:59 raspberrypi kernel: [    0.312349] brd: module loaded
Sep  2 14:24:59 raspberrypi kernel: [    0.323285] loop: module loaded
Sep  2 14:24:59 raspberrypi kernel: [    0.325375] Loading iSCSI transport class v2.0-870.
Sep  2 14:24:59 raspberrypi kernel: [    0.328065] usbcore: registered new interface driver smsc95xx
Sep  2 14:24:59 raspberrypi kernel: [    0.330204] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Sep  2 14:24:59 raspberrypi kernel: [    0.560329] Core Release: 2.80a
Sep  2 14:24:59 raspberrypi kernel: [    0.562383] Setting default values for core params
Sep  2 14:24:59 raspberrypi kernel: [    0.564511] Finished setting default values for core params
Sep  2 14:24:59 raspberrypi kernel: [    0.767081] Using Buffer DMA mode
Sep  2 14:24:59 raspberrypi kernel: [    0.769205] Periodic Transfer Interrupt Enhancement - disabled
Sep  2 14:24:59 raspberrypi kernel: [    0.771447] Multiprocessor Interrupt Enhancement - disabled
Sep  2 14:24:59 raspberrypi kernel: [    0.773675] OTG VER PARAM: 0, OTG VER FLAG: 0
Sep  2 14:24:59 raspberrypi kernel: [    0.775863] Dedicated Tx FIFOs mode
Sep  2 14:24:59 raspberrypi kernel: [    0.778326] WARN::dwc_otg_hcd_init:1032: FIQ DMA bounce buffers: virt = 0xba904000 dma = 0xfa904000 len=9024
Sep  2 14:24:59 raspberrypi kernel: [    0.782771] FIQ FSM acceleration enabled for :
Sep  2 14:24:59 raspberrypi kernel: [    0.782771] Non-periodic Split Transactions
Sep  2 14:24:59 raspberrypi kernel: [    0.782771] Periodic Split Transactions
Sep  2 14:24:59 raspberrypi kernel: [    0.782771] High-Speed Isochronous Endpoints
Sep  2 14:24:59 raspberrypi kernel: [    0.782771] Interrupt/Control Split Transaction hack enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.794126] dwc_otg: Microframe scheduler enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.794175] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x8058ef90
Sep  2 14:24:59 raspberrypi kernel: [    0.796479] WARN::hcd_init_fiq:460: FIQ ASM at 0x8058f300 length 36
Sep  2 14:24:59 raspberrypi kernel: [    0.798799] WARN::hcd_init_fiq:486: MPHI regs_base at 0xbb87a000
Sep  2 14:24:59 raspberrypi kernel: [    0.801149] dwc_otg 3f980000.usb: DWC OTG Controller
Sep  2 14:24:59 raspberrypi kernel: [    0.803465] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
Sep  2 14:24:59 raspberrypi kernel: [    0.805824] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
Sep  2 14:24:59 raspberrypi kernel: [    0.808163] Init: Port Power? op_state=1
Sep  2 14:24:59 raspberrypi kernel: [    0.810416] Init: Power Port (0)
Sep  2 14:24:59 raspberrypi kernel: [    0.812787] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Sep  2 14:24:59 raspberrypi kernel: [    0.815097] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Sep  2 14:24:59 raspberrypi kernel: [    0.817413] usb usb1: Product: DWC OTG Controller
Sep  2 14:24:59 raspberrypi kernel: [    0.819659] usb usb1: Manufacturer: Linux 4.9.35-v7+ dwc_otg_hcd
Sep  2 14:24:59 raspberrypi kernel: [    0.821927] usb usb1: SerialNumber: 3f980000.usb
Sep  2 14:24:59 raspberrypi kernel: [    0.825017] hub 1-0:1.0: USB hub found
Sep  2 14:24:59 raspberrypi kernel: [    0.827234] hub 1-0:1.0: 1 port detected
Sep  2 14:24:59 raspberrypi kernel: [    0.829964] dwc_otg: FIQ enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.829968] dwc_otg: NAK holdoff enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.829972] dwc_otg: FIQ split-transaction FSM enabled
Sep  2 14:24:59 raspberrypi kernel: [    0.829986] Module dwc_common_port init
Sep  2 14:24:59 raspberrypi kernel: [    0.830225] usbcore: registered new interface driver usb-storage
Sep  2 14:24:59 raspberrypi kernel: [    0.832551] mousedev: PS/2 mouse device common for all mice
Sep  2 14:24:59 raspberrypi kernel: [    0.835635] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
Sep  2 14:24:59 raspberrypi kernel: [    0.838188] bcm2835-cpufreq: min=600000 max=1200000
Sep  2 14:24:59 raspberrypi kernel: [    0.840838] sdhci: Secure Digital Host Controller Interface driver
Sep  2 14:24:59 raspberrypi kernel: [    0.843148] sdhci: Copyright(c) Pierre Ossman
Sep  2 14:24:59 raspberrypi kernel: [    0.845661] sdhost-bcm2835 3f202000.sdhost: could not get clk, deferring probe
Sep  2 14:24:59 raspberrypi kernel: [    0.850248] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
Sep  2 14:24:59 raspberrypi kernel: [    0.852792] sdhci-pltfm: SDHCI platform and OF driver helper
Sep  2 14:24:59 raspberrypi kernel: [    0.857853] ledtrig-cpu: registered to indicate activity on CPUs
Sep  2 14:24:59 raspberrypi kernel: [    0.860500] hidraw: raw HID events driver (C) Jiri Kosina
Sep  2 14:24:59 raspberrypi kernel: [    0.863169] usbcore: registered new interface driver usbhid
Sep  2 14:24:59 raspberrypi kernel: [    0.865628] usbhid: USB HID core driver
Sep  2 14:24:59 raspberrypi kernel: [    0.868899] vchiq: vchiq_init_state: slot_zero = 0xba980000, is_master = 0
Sep  2 14:24:59 raspberrypi kernel: [    0.873110] Initializing XFRM netlink socket
Sep  2 14:24:59 raspberrypi kernel: [    0.875653] NET: Registered protocol family 17
Sep  2 14:24:59 raspberrypi kernel: [    0.878268] Key type dns_resolver registered
Sep  2 14:24:59 raspberrypi kernel: [    0.881081] Registering SWP/SWPB emulation handler
Sep  2 14:24:59 raspberrypi kernel: [    0.884260] registered taskstats version 1
Sep  2 14:24:59 raspberrypi kernel: [    0.887065] vc-sm: Videocore shared memory driver
Sep  2 14:24:59 raspberrypi kernel: [    0.889574] [vc_sm_connected_init]: start
Sep  2 14:24:59 raspberrypi kernel: [    0.892497] [vc_sm_connected_init]: end - returning 0
Sep  2 14:24:59 raspberrypi kernel: [    0.899943] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
Sep  2 14:24:59 raspberrypi kernel: [    0.907350] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 220, base_baud = 31250000) is a 16550
Sep  2 14:24:59 raspberrypi kernel: [    0.913009] sdhost: log_buf @ ba907000 (fa907000)
Sep  2 14:24:59 raspberrypi kernel: [    0.986513] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
Sep  2 14:24:59 raspberrypi kernel: [    0.991214] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
Sep  2 14:24:59 raspberrypi kernel: [    0.993702] mmc-bcm2835 3f300000.mmc: DMA channel allocated
Sep  2 14:24:59 raspberrypi kernel: [    1.046668] Indeed it is in host mode hprt0 = 00021501
Sep  2 14:24:59 raspberrypi kernel: [    1.109209] of_cfs_init
Sep  2 14:24:59 raspberrypi kernel: [    1.111658] of_cfs_init: OK
Sep  2 14:24:59 raspberrypi kernel: [    1.114421] Waiting for root device PARTUUID=3cb9faaa-02...
Sep  2 14:24:59 raspberrypi kernel: [    1.120207] mmc0: host does not support reading read-only switch, assuming write-enable
Sep  2 14:24:59 raspberrypi kernel: [    1.126925] mmc0: new high speed SDHC card at address 0001
Sep  2 14:24:59 raspberrypi kernel: [    1.130069] mmcblk0: mmc0:0001 SPCC 7.38 GiB
Sep  2 14:24:59 raspberrypi kernel: [    1.135003]  mmcblk0: p1 p2
Sep  2 14:24:59 raspberrypi kernel: [    1.135616] random: fast init done
Sep  2 14:24:59 raspberrypi kernel: [    1.143520] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    1.147510] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    1.151451] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    1.156507] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
Sep  2 14:24:59 raspberrypi kernel: [    1.246516] usb 1-1: new high-speed USB device number 2 using dwc_otg
Sep  2 14:24:59 raspberrypi kernel: [    1.248795] Indeed it is in host mode hprt0 = 00001101
Sep  2 14:24:59 raspberrypi kernel: [    1.251309] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Sep  2 14:24:59 raspberrypi kernel: [    1.255502] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Sep  2 14:24:59 raspberrypi kernel: [    1.270937] devtmpfs: mounted
Sep  2 14:24:59 raspberrypi kernel: [    1.312593] Freeing unused kernel memory: 1024K (80b00000 - 80c00000)
Sep  2 14:24:59 raspberrypi kernel: [    1.314493] mmc1: new high speed SDIO card at address 0001
Sep  2 14:24:59 raspberrypi kernel: [    1.476837] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Sep  2 14:24:59 raspberrypi kernel: [    1.479320] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep  2 14:24:59 raspberrypi kernel: [    1.482583] hub 1-1:1.0: USB hub found
Sep  2 14:24:59 raspberrypi kernel: [    1.485020] hub 1-1:1.0: 5 ports detected
Sep  2 14:24:59 raspberrypi kernel: [    1.816522] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Sep  2 14:24:59 raspberrypi kernel: [    1.892947] NET: Registered protocol family 10
Sep  2 14:24:59 raspberrypi kernel: [    1.946990] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Sep  2 14:24:59 raspberrypi kernel: [    1.950159] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep  2 14:24:59 raspberrypi kernel: [    1.957811] smsc95xx v1.0.5
Sep  2 14:24:59 raspberrypi kernel: [    2.050255] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:6e:9f:75
Sep  2 14:24:59 raspberrypi kernel: [    2.146534] usb 1-1.2: new full-speed USB device number 4 using dwc_otg
Sep  2 14:24:59 raspberrypi kernel: [    2.279651] usb 1-1.2: New USB device found, idVendor=1a86, idProduct=7523
Sep  2 14:24:59 raspberrypi kernel: [    2.282360] usb 1-1.2: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Sep  2 14:24:59 raspberrypi kernel: [    2.285087] usb 1-1.2: Product: USB2.0-Serial
Sep  2 14:24:59 raspberrypi kernel: [    2.586523] usb 1-1.4: new full-speed USB device number 5 using dwc_otg
Sep  2 14:24:59 raspberrypi kernel: [    2.731422] usb 1-1.4: New USB device found, idVendor=0a12, idProduct=0001
Sep  2 14:24:59 raspberrypi kernel: [    2.731432] usb 1-1.4: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Sep  2 14:24:59 raspberrypi kernel: [    2.731439] usb 1-1.4: Product: CSR8510 A10
Sep  2 14:24:59 raspberrypi kernel: [    3.625277] Bluetooth: Core ver 2.22
Sep  2 14:24:59 raspberrypi kernel: [    3.625347] NET: Registered protocol family 31
Sep  2 14:24:59 raspberrypi kernel: [    3.625353] Bluetooth: HCI device and connection manager initialized
Sep  2 14:24:59 raspberrypi kernel: [    3.625373] Bluetooth: HCI socket layer initialized
Sep  2 14:24:59 raspberrypi kernel: [    3.625386] Bluetooth: L2CAP socket layer initialized
Sep  2 14:24:59 raspberrypi kernel: [    3.625417] Bluetooth: SCO socket layer initialized
Sep  2 14:24:59 raspberrypi kernel: [    3.654563] usbcore: registered new interface driver btusb
Sep  2 14:24:59 raspberrypi kernel: [    3.689744] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
Sep  2 14:24:59 raspberrypi kernel: [    4.030556] usbcore: registered new interface driver brcmfmac
Sep  2 14:24:59 raspberrypi kernel: [    4.032625] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Sep  2 14:24:59 raspberrypi kernel: [    4.211734] brcmfmac: Firmware version = wl0: May 27 2016 00:13:38 version 7.45.41.26 (r640327) FWID 01-df77e4a7
Sep  2 14:24:59 raspberrypi kernel: [    4.811626] random: crng init done
Sep  2 14:24:59 raspberrypi kernel: [    4.996219] usbcore: registered new interface driver usbserial
Sep  2 14:24:59 raspberrypi kernel: [    4.996272] usbcore: registered new interface driver usbserial_generic
Sep  2 14:24:59 raspberrypi kernel: [    4.996332] usbserial: USB Serial support registered for generic
Sep  2 14:24:59 raspberrypi kernel: [    4.999351] usbcore: registered new interface driver ch341
Sep  2 14:24:59 raspberrypi kernel: [    4.999429] usbserial: USB Serial support registered for ch341-uart
Sep  2 14:24:59 raspberrypi kernel: [    4.999487] ch341 1-1.2:1.0: ch341-uart converter detected
Sep  2 14:24:59 raspberrypi kernel: [    5.001221] usb 1-1.2: ch341-uart converter now attached to ttyUSB0
Sep  2 14:24:59 raspberrypi kernel: [    5.239563] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sep  2 14:24:59 raspberrypi kernel: [    5.239596] brcmfmac: power management disabled
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: Successfully called chroot().
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: Successfully dropped remaining capabilities.
Sep  2 14:24:59 raspberrypi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting Login Service...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: FHEM server...
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: triggerhappy hotkey daemon...
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: No service file found in /etc/avahi/services.
Sep  2 14:24:59 raspberrypi systemd[1]: Starting LSB: Autogenerate and use a swap file...
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::ffca:ed7e:16ea:d574.
Sep  2 14:24:59 raspberrypi avahi-daemon[439]: New relevant interface wlan0.IPv6 for mDNS.
Sep  2 14:25:00 raspberrypi avahi-daemon[439]: Network interface enumeration completed.
Sep  2 14:25:00 raspberrypi avahi-daemon[439]: Registering new address record for fe80::ffca:ed7e:16ea:d574 on wlan0.*.
Sep  2 14:25:00 raspberrypi avahi-daemon[439]: Registering HINFO record with values 'ARMV7L'/'LINUX'.
Sep  2 14:25:00 raspberrypi systemd[1]: Started System Logging Service.
Sep  2 14:25:00 raspberrypi systemd[1]: Started Restore Sound Card State.
Sep  2 14:25:00 raspberrypi dphys-swapfile[496]: Starting dphys-swapfile swapfile setup ...
Sep  2 14:25:00 raspberrypi systemd[1]: Started Login Service.
Sep  2 14:25:00 raspberrypi triggerhappy[495]: Error opening '/dev/input/event*': No such file or directory
Sep  2 14:25:00 raspberrypi systemd[1]: Started LSB: triggerhappy hotkey daemon.
Sep  2 14:25:00 raspberrypi wpa_supplicant[536]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep  2 14:25:00 raspberrypi dphys-swapfile[496]: want /var/swap=100MByte, checking existing: keeping it
Sep  2 14:25:00 raspberrypi kernel: [    6.134461] Adding 102396k swap on /var/swap.  Priority:-1 extents:4 across:241660k SSFS
Sep  2 14:25:00 raspberrypi dphys-swapfile[496]: done.
Sep  2 14:25:00 raspberrypi systemd[1]: Started LSB: Autogenerate and use a swap file.
Sep  2 14:25:00 raspberrypi avahi-daemon[439]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::9a56:fcf4:d191:389a.
Sep  2 14:25:00 raspberrypi avahi-daemon[439]: New relevant interface eth0.IPv6 for mDNS.
Sep  2 14:25:00 raspberrypi dhcpcd[438]: eth0: waiting for carrier
Sep  2 14:25:00 raspberrypi avahi-daemon[439]: Registering new address record for fe80::9a56:fcf4:d191:389a on eth0.*.
Sep  2 14:25:00 raspberrypi dhcpcd[438]: wlan0: waiting for carrier
Sep  2 14:25:00 raspberrypi kernel: [    6.297857] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Sep  2 14:25:00 raspberrypi kernel: [    6.298189] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Sep  2 14:25:00 raspberrypi fhem[494]: Starting fhem...
Sep  2 14:25:00 raspberrypi wpa_supplicant[536]: wlan0: Trying to associate with c0:3f:0e:7a:87:c2 (SSID='wlan@coam24' freq=2412 MHz)
Sep  2 14:25:00 raspberrypi wpa_supplicant[536]: wlan0: Associated with c0:3f:0e:7a:87:c2
Sep  2 14:25:00 raspberrypi kernel: [    6.653727] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Sep  2 14:25:00 raspberrypi wpa_supplicant[536]: wlan0: WPA: Key negotiation completed with c0:3f:0e:7a:87:c2 [PTK=CCMP GTK=TKIP]
Sep  2 14:25:00 raspberrypi wpa_supplicant[536]: wlan0: CTRL-EVENT-CONNECTED - Connection to c0:3f:0e:7a:87:c2 completed [id=0 id_str=]
Sep  2 14:25:00 raspberrypi dhcpcd[438]: wlan0: carrier acquired
Sep  2 14:25:00 raspberrypi dhcpcd[438]: DUID 00:01:00:01:20:ef:8d:ea:b8:27:eb:6e:9f:75
Sep  2 14:25:00 raspberrypi dhcpcd[438]: wlan0: IAID eb:3b:ca:20
Sep  2 14:25:01 raspberrypi avahi-daemon[439]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 680655785.
Sep  2 14:25:01 raspberrypi systemd[1]: Started LSB: FHEM server.
Sep  2 14:25:01 raspberrypi dhcpcd[438]: wlan0: rebinding lease of 192.168.252.150
Sep  2 14:25:01 raspberrypi dhcpcd[438]: wlan0: soliciting an IPv6 router
Sep  2 14:25:04 raspberrypi btuart[447]: bcm43xx_init
Sep  2 14:25:04 raspberrypi kernel: [   10.151702] Bluetooth: HCI UART driver ver 2.3
Sep  2 14:25:04 raspberrypi kernel: [   10.151716] Bluetooth: HCI UART protocol H4 registered
Sep  2 14:25:04 raspberrypi kernel: [   10.151722] Bluetooth: HCI UART protocol Three-wire (H5) registered
Sep  2 14:25:04 raspberrypi kernel: [   10.151899] Bluetooth: HCI UART protocol Broadcom registered
Sep  2 14:25:04 raspberrypi btuart[447]: Flash firmware /lib/firmware/BCM43430A1.hcd
Sep  2 14:25:04 raspberrypi btuart[447]: Set Controller UART speed to 460800 bit/s
Sep  2 14:25:04 raspberrypi btuart[447]: Device setup complete
Sep  2 14:25:04 raspberrypi systemd[1]: Started Configure Bluetooth Modems connected by UART.
Sep  2 14:25:04 raspberrypi systemd[1]: Starting Bluetooth service...
Sep  2 14:25:04 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status of rfkill2...
Sep  2 14:25:04 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status of rfkill2.
Sep  2 14:25:04 raspberrypi bluetoothd[642]: Bluetooth daemon 5.23
Sep  2 14:25:04 raspberrypi systemd[1]: Started Bluetooth service.
Sep  2 14:25:04 raspberrypi systemd[1]: Starting Bluetooth.
Sep  2 14:25:04 raspberrypi systemd[1]: Reached target Bluetooth.
Sep  2 14:25:04 raspberrypi systemd[1]: Starting lepresenced...
Sep  2 14:25:04 raspberrypi bluetoothd[642]: Starting SDP server
Sep  2 14:25:04 raspberrypi kernel: [   10.315896] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Sep  2 14:25:04 raspberrypi kernel: [   10.315904] Bluetooth: BNEP filters: protocol multicast
Sep  2 14:25:04 raspberrypi kernel: [   10.315916] Bluetooth: BNEP socket layer initialized
Sep  2 14:25:04 raspberrypi bluetoothd[642]: Bluetooth management interface 1.14 initialized
Sep  2 14:25:04 raspberrypi dbus[449]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Sep  2 14:25:04 raspberrypi systemd[1]: Starting Hostname Service...
Sep  2 14:25:04 raspberrypi bluetoothd[642]: Sap driver initialization failed.
Sep  2 14:25:04 raspberrypi bluetoothd[642]: sap-server: Operation not permitted (1)
Sep  2 14:25:04 raspberrypi bluetoothd[642]: Sap driver initialization failed.
Sep  2 14:25:04 raspberrypi bluetoothd[642]: sap-server: Operation not permitted (1)
Sep  2 14:25:04 raspberrypi systemd-hostnamed[647]: Warning: nss-myhostname is not installed. Changing the local hostname might make it unresolveable. Please install nss-myhostname!
Sep  2 14:25:04 raspberrypi dbus[449]: [system] Successfully activated service 'org.freedesktop.hostname1'
Sep  2 14:25:04 raspberrypi systemd[1]: Started Hostname Service.
Sep  2 14:25:07 raspberrypi dhcpcd[438]: wlan0: leased 192.168.252.150 for 43200 seconds
Sep  2 14:25:07 raspberrypi avahi-daemon[439]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.252.150.
Sep  2 14:25:07 raspberrypi dhcpcd[438]: wlan0: adding route to 192.168.252.0/24
Sep  2 14:25:07 raspberrypi dhcpcd[438]: wlan0: adding default route via 192.168.252.254
Sep  2 14:25:07 raspberrypi avahi-daemon[439]: New relevant interface wlan0.IPv4 for mDNS.
Sep  2 14:25:07 raspberrypi avahi-daemon[439]: Registering new address record for 192.168.252.150 on wlan0.IPv4.
Sep  2 14:25:07 raspberrypi dhcpcd[438]: forked to background, child pid 734
Sep  2 14:25:07 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Sep  2 14:25:07 raspberrypi systemd[1]: Starting Network.
Sep  2 14:25:07 raspberrypi systemd[1]: Reached target Network.
Sep  2 14:25:07 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Sep  2 14:25:07 raspberrypi systemd[1]: Started OpenBSD Secure Shell server.
Sep  2 14:25:07 raspberrypi systemd[1]: Starting /etc/rc.local Compatibility...
Sep  2 14:25:07 raspberrypi systemd[1]: Starting Permit User Sessions...
Sep  2 14:25:07 raspberrypi systemd[1]: Starting Network is Online.
Sep  2 14:25:07 raspberrypi systemd[1]: Reached target Network is Online.
Sep  2 14:25:07 raspberrypi systemd[1]: Starting LSB: Start NTP daemon...
Sep  2 14:25:07 raspberrypi systemd[1]: Started /etc/rc.local Compatibility.
Sep  2 14:25:07 raspberrypi systemd[1]: Started Permit User Sessions.
Sep  2 14:25:07 raspberrypi systemd[1]: Starting Terminate Plymouth Boot Screen...
Sep  2 14:25:07 raspberrypi systemd[1]: Starting Hold until boot process finishes up...
Sep  2 14:25:07 raspberrypi systemd[1]: Received SIGRTMIN+21 from PID 265 (plymouthd).
Sep  2 14:25:07 raspberrypi ntp[739]: Starting NTP server: ntpderror: unexpectedly disconnected from boot status daemon
Sep  2 14:25:07 raspberrypi systemd[1]: Started Terminate Plymouth Boot Screen.
Sep  2 14:25:07 raspberrypi systemd[1]: Started Hold until boot process finishes up.
Sep  2 14:25:07 raspberrypi systemd[1]: Starting Getty on tty1...
Sep  2 14:25:07 raspberrypi systemd[1]: Started Getty on tty1.
Sep  2 14:25:07 raspberrypi systemd[1]: Starting Login Prompts.
Sep  2 14:25:07 raspberrypi systemd[1]: Reached target Login Prompts.
Sep  2 14:25:07 raspberrypi ntpd[754]: ntpd 4.2.6p5@1.2349-o Mon Jul 25 22:35:28 UTC 2016 (1)
Sep  2 14:25:07 raspberrypi ntpd[756]: proto: precision = 0.469 usec
Sep  2 14:25:07 raspberrypi ntpd[756]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Sep  2 14:25:07 raspberrypi ntp[739]: .
Sep  2 14:25:07 raspberrypi systemd[1]: Started LSB: Start NTP daemon.
Sep  2 14:25:07 raspberrypi ntpd[756]: Listen and drop on 1 v6wildcard :: UDP 123
Sep  2 14:25:07 raspberrypi ntpd[756]: Listen normally on 2 lo 127.0.0.1 UDP 123
Sep  2 14:25:07 raspberrypi ntpd[756]: Listen normally on 3 wlan0 192.168.252.150 UDP 123
Sep  2 14:25:07 raspberrypi ntpd[756]: Listen normally on 4 wlan0 fe80::ffca:ed7e:16ea:d574 UDP 123
Sep  2 14:25:07 raspberrypi ntpd[756]: Listen normally on 5 lo ::1 UDP 123
Sep  2 14:25:07 raspberrypi ntpd[756]: peers refreshed
Sep  2 14:25:07 raspberrypi ntpd[756]: Listening on routing socket on fd #22 for interface updates
Sep  2 14:25:13 raspberrypi dhcpcd[734]: wlan0: no IPv6 Routers available
Sep  2 14:25:14 raspberrypi systemd[1]: Started lepresenced.
Sep  2 14:25:14 raspberrypi systemd[1]: Starting Multi-User System.
Sep  2 14:25:14 raspberrypi systemd[1]: Reached target Multi-User System.
Sep  2 14:25:14 raspberrypi systemd[1]: Starting Graphical Interface.
Sep  2 14:25:14 raspberrypi systemd[1]: Reached target Graphical Interface.
Sep  2 14:25:14 raspberrypi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Sep  2 14:25:14 raspberrypi systemd[1]: Started Update UTMP about System Runlevel Changes.
Sep  2 14:25:14 raspberrypi systemd[1]: Startup finished in 1.660s (kernel) + 18.679s (userspace) = 20.340s.
Sep  2 14:25:23 raspberrypi systemd[1]: Time has been changed
Sep  2 14:25:23 raspberrypi lepresenced[760]: [tid:0] main: Version 0.83 started (device: hci0, listen addr: 0.0.0.0, listen port: 5333, daemonize: 0, legacy mode: 0, rssi threshold: 10, log level: 7, debug: 0).
Sep  2 14:25:23 raspberrypi lepresenced[760]: [tid:0] main::sanity_check: md5 digest of '/usr/sbin/lepresenced' is: dc0db6a06b26acce7739b847c3727fad.
Sep  2 14:25:23 raspberrypi lepresenced[760]: [tid:0] main::sanity_check: hciconfig found at '/bin/hciconfig'.
Sep  2 14:25:23 raspberrypi lepresenced[760]: [tid:0] main::sanity_check: hcitool found at '/usr/bin/hcitool'.
Sep  2 14:25:23 raspberrypi lepresenced[760]: [tid:0] main::sanity_check: hcidump found at '/usr/bin/hcidump'.
Sep  2 14:25:23 raspberrypi lepresenced[760]: [tid:1] main::bluetooth_scan_thread: Received 'LE Scan ...'.
Sep  2 14:25:28 raspberrypi kernel: [   25.449285] uart-pl011 3f201000.serial: no DMA platform data
Sep  2 14:25:30 raspberrypi lepresenced[760]: [tid:0] main: Connection from 127.0.0.1:39390. Connected clients: 1.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main: Connection from 127.0.0.1:39392. Connected clients: 2.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main::handle_command: Received query for mac address 7c:2f:80:97:38:38, interval: 25. Adding client 127.0.0.1:39390 to clients list.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main: Sending update for mac address 7c:2f:80:97:38:38, ages: 0/1, max age: 25, rssi: -73, result: present.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main::handle_command: Received query for mac address 7c:2f:80:97:38:42, interval: 25. Adding client 127.0.0.1:39392 to clients list.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main: Sending update for mac address 7c:2f:80:97:38:42, ages: 1/2, max age: 25, rssi: -75, result: present.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main::handle_command: Received query update for mac address 7c:2f:80:97:38:38, interval: 60 by client 127.0.0.1:39390.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main::handle_command: Received query update for mac address 7c:2f:80:97:38:42, interval: 60 by client 127.0.0.1:39392.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main: Sending update for mac address 7c:2f:80:97:38:38, ages: 0/1, max age: 60, rssi: -73, result: present.
Sep  2 14:25:31 raspberrypi lepresenced[760]: [tid:0] main: Sending update for mac address 7c:2f:80:97:38:42, ages: 1/2, max age: 60, rssi: -75, result: present.
Sep  2 14:26:31 raspberrypi lepresenced[760]: [tid:0] main: Sending update for mac address 7c:2f:80:97:38:38, ages: 1/1, max age: 60, rssi: -74, result: present.
Sep  2 14:26:31 raspberrypi lepresenced[760]: [tid:0] main: Sending update for mac address 7c:2f:80:97:38:42, ages: 1/2, max age: 60, rssi: -76, result: present.


Vielen Dank!!!!!

Noch eine Frage zum Startscript. Damit die Parameter (hci0/hci1, debug, etc) ziehen, müssen sie aber vor den execstart-Befehl, oder??

[Lucky2k12]

Hattest Du vorher das Problem mit der Startreihenfolge?

Ja, wobei nicht immer.
Manchmal hat es auch direkt nach dem booten des Raspi3 funktioniert.
Manchmal musste ich lepresenced restart ausführen, dann ging's wieder

[PatrickR]

Hi!

Noch eine Frage zum Startscript. Damit die Parameter (hci0/hci1, debug, etc) ziehen, müssen sie aber vor den execstart-Befehl, oder??

Bitte weder das Startskript noch lepresenced selbst editieren. Das Device kannst Du in /etc/default/lepresenced ändern.


Von unterwegs gesendet.

[stiefl]

alles klar.

habs nun eh bei hci0 belassen. Dafür BleTagBattery auf hci1. Läuft momentan einwandfrei :-D

[arthur_dent_2015]

Hallo Patrick,
bei mir läuft die Version 0.83 seit Tagen stabil
Danke & Gruß
Arthur

[rastagandalf]

Hallo zusammen,

habe jetzt auch mal PRESENCE mit lepresenced gemäß Wiki aufgesetzt und habe ein ähnliches Problem.
Nach Reboot des RasPi, an dem ein BCM20702A0-Dongle hängt, klappt alles eine weile und der G-Tag (sowie das testhalber mitgetrackte Xiaomi MiBand) wird zuverlässig erkannt, inkl. RSSI.
Aber dann kommt irgendwann nur noch absent.
Versionen:

Code Auswählen Erweitern

pi@fhem:~ $ dpkg -l|egrep -i '(blue|hci)'
ii  bluetooth                      5.23-2+rpi2                       all          Bluetooth support
ii  bluez                          5.23-2+rpi2                       armhf        Bluetooth tools and daemons
ii  bluez-hcidump                  5.23-2+rpi2                       armhf        Analyses Bluetooth HCI packets
ii  lepresenced                    0.83-3                            all          lepresenced to detect the presence of Bluetooth LE devices

/etc/default/lepresenced:

Code Auswählen Erweitern

#
# Default settings for /etc/init.d/lepresenced
#

#Bluetooth device to use for scanning.
#BLUETOOTH_DEVICE="hci0"

#Address to listen for incoming connections. For local connections use 127.0.0.1.
LISTEN_ADDRESS="127.0.0.1"

#Port to listen for incoming connections.
#LISTEN_PORT="5333"

#Syslog level. LOG_EMERG disables logging.
SYSLOG_LEVEL="LOG_DEBUG"

#Additional command line options
#MISC_OPTIONS=""


Code Auswählen Erweitern


pi@fhem:~ $ ps aux | grep lepresenced
root       487  6.3  1.1  33200 11624 ?        Ssl  23:57   0:01 /usr/bin/perl /usr/sbin/lepresenced --device hci0 --listenaddress 127.0.0.1 --listenport 5333 --loglevel LOG_DEBUG
pi         664  0.0  0.1   4280  1864 pts/0    S+   23:58   0:00 grep --color=auto lepresenced


Was könnte ich probieren um das Problem einzugrenzen? Wo genau wird das lepresenence-spezifische Log, das durch LOG_DEBUG beeinflusst wird, abgelegt? Oder tritt das einfach im Syslog auf?
Besten Dank schon mal!

Viele Grüße
Timo

EDIT:
Kleines Update - habe das Log gefunden (ok, Syslog, hätte ich auch gleich draufkommen können...)

19:09 wurde gestartet:

Code Auswählen Erweitern

Dec 14 19:06:24 fhem lepresenced[487]: [tid:0] main::stats_task: Active clients: 2, known devices: 0 (min/max age: %/%), received beacons (hcitool/hcidump/difference): 99859/99857/2
Dec 14 19:06:47 fhem lepresenced[487]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, max age: 60, result: absence.
Dec 14 19:07:22 fhem lepresenced[487]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:07:47 fhem lepresenced[487]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, max age: 60, result: absence.
Dec 14 19:08:22 fhem lepresenced[487]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:08:47 fhem lepresenced[487]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, max age: 60, result: absence.
Dec 14 18:17:04 fhem systemd[1]: Starting lepresenced...
Dec 14 18:17:14 fhem systemd[1]: Started lepresenced.
Dec 14 18:17:15 fhem lepresenced[488]: [tid:0] main: Version 0.83 started (device: hci0, listen addr: 127.0.0.1, listen port: 5333, daemonize: 0, legacy mode: 0, rssi threshold: 10, log level: 7, debug: 0).
Dec 14 18:17:15 fhem lepresenced[488]: [tid:0] main::sanity_check: md5 digest of '/usr/sbin/lepresenced' is: dc0db6a06b26acce7739b847c3727fad.
Dec 14 18:17:15 fhem lepresenced[488]: [tid:0] main::sanity_check: hciconfig found at '/bin/hciconfig'.
Dec 14 18:17:15 fhem lepresenced[488]: [tid:0] main::sanity_check: hcitool found at '/usr/bin/hcitool'.
Dec 14 18:17:15 fhem lepresenced[488]: [tid:0] main::sanity_check: hcidump found at '/usr/bin/hcidump'.
Dec 14 18:17:16 fhem lepresenced[488]: [tid:1] main::bluetooth_scan_thread: Received 'LE Scan ...'.
Dec 14 19:09:33 fhem lepresenced[488]: [tid:0] main::cleanup_task: Deleting device bb:bb:bb:bb:bb:bb.
Dec 14 19:09:33 fhem lepresenced[488]: [tid:0] main::cleanup_task: Cleanup finished, deleted 1 devices in 0 seconds.
Dec 14 19:09:33 fhem lepresenced[488]: [tid:0] main::stats_task: Active clients: 0, known devices: 3 (min/max age: 0/0), received beacons (hcitool/hcidump/difference): 168/166/2
Dec 14 19:09:36 fhem lepresenced[488]: [tid:0] main: Connection from 127.0.0.1:50943. Connected clients: 1.
Dec 14 19:09:36 fhem lepresenced[488]: [tid:0] main: Connection from 127.0.0.1:50944. Connected clients: 2.
Dec 14 19:09:36 fhem lepresenced[488]: [tid:0] main::handle_command: Received query for mac address bb:bb:bb:bb:bb:bb, interval: 60. Adding client 127.0.0.1:50943 to clients list.
Dec 14 19:09:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -80, result: present.
Dec 14 19:09:36 fhem lepresenced[488]: [tid:0] main::handle_command: Received query for mac address aa:aa:aa:aa:aa:aa, interval: 60. Adding client 127.0.0.1:50944 to clients list.
Dec 14 19:09:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 0/0, max age: 60, rssi: -90, result: present.
Dec 14 19:10:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -80, result: present.
Dec 14 19:10:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 1/1, max age: 60, rssi: -89, result: present.
Dec 14 19:11:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -83, result: present.
Dec 14 19:11:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 1/1, max age: 60, rssi: -89, result: present.
Dec 14 19:12:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -75, result: present.
Dec 14 19:12:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 1/1, max age: 60, rssi: -90, result: present.
Dec 14 19:13:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -81, result: present.
Dec 14 19:13:36 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 1/1, max age: 60, rssi: -93, result: present.

19:34 ist er abgeschmiert trotz Anwesenheit:

Code Auswählen Erweitern

Dec 14 19:33:37 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 0/0, max age: 60, rssi: -93, result: present.
Dec 14 19:33:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 12/15, max age: 60, rssi: -89, result: present.
Dec 14 19:34:32 fhem lepresenced[488]: [tid:0] main: Mac address bb:bb:bb:bb:bb:bb needs update due to changed rssi. Old/new rssi: -93/-82, difference: 11, affected clients: 1.
Dec 14 19:34:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -82, result: present.
Dec 14 19:34:38 fhem lepresenced[488]: [tid:0] main::stats_task: Active clients: 2, known devices: 3 (min/max age: 0/60), received beacons (hcitool/hcidump/difference): 32084/32082/2
Dec 14 19:34:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:35:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -82, result: present.
Dec 14 19:35:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:36:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -83, result: present.
Dec 14 19:36:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 3/28, max age: 60, rssi: -96, result: present.
Dec 14 19:37:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 2/2, max age: 60, rssi: -83, result: present.
Dec 14 19:37:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:38:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 0/0, max age: 60, rssi: -89, result: present.
Dec 14 19:38:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 6/7, max age: 60, rssi: -96, result: present.
Dec 14 19:39:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 1/1, max age: 60, rssi: -84, result: present.
Dec 14 19:39:35 fhem lepresenced[488]: [tid:0] main::cleanup_task: Cleanup finished, deleted 0 devices in 0 seconds.
Dec 14 19:39:39 fhem lepresenced[488]: [tid:0] main::stats_task: Active clients: 2, known devices: 3 (min/max age: 0/2), received beacons (hcitool/hcidump/difference): 37770/37768/2
Dec 14 19:39:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, ages: 8/12, max age: 60, rssi: -96, result: present.
Dec 14 19:40:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, ages: 39/39, max age: 60, rssi: -91, result: present.
Dec 14 19:40:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:41:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, max age: 60, result: absence.
Dec 14 19:41:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:42:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, max age: 60, result: absence.
Dec 14 19:42:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:43:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, max age: 60, result: absence.
Dec 14 19:43:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.
Dec 14 19:44:32 fhem lepresenced[488]: [tid:0] main: Sending update for mac address bb:bb:bb:bb:bb:bb, max age: 60, result: absence.
Dec 14 19:44:40 fhem lepresenced[488]: [tid:0] main::stats_task: Active clients: 2, known devices: 3 (min/max age: 287/298), received beacons (hcitool/hcidump/difference): 38016/38014/2
Dec 14 19:44:50 fhem lepresenced[488]: [tid:0] main: Sending update for mac address aa:aa:aa:aa:aa:aa, max age: 60, result: absence.

Warum da beim Start (hatte den Raspi neu gestartet) plötzlich 18:17 auftaucht erschließt sich mir nicht ganz, krumme Zahl, selbst wenn er da noch irgendwie die Systemzeit umstellt...

[PatrickR]

Hi!
Das mit der Systemzeit solltest Du Dir mal anschauen. Sowas ist generell nicht gut. Bei lepresenced führt es dazu, dass um 19:09Uhr (18:17Uhr) ein Tag zu Unrecht rausfliegt.

Mit Deinem Hauptproblem hat das aber nichts zu tun. Leider ist das der ungünstigste Fall eines Fehlers, der auftreten kann. Alles ist prima und verhält sich exakt als seien die G-Tags außer Reichweite: Die Scan-Prozesse (hcitool/hcidump) laufen weiter und haben bis zum Auftreten des Problems die (fast exakt) gleiche Anzahl an Beacons empfangen. Insofern sieht für lepresenced alles wunderbar aus.

Das Debuggen ist entsprechend schwierig:
-Schau doch mal bitte, ob zur relevanten Zeit etwas Spannendes im Syslog steht, was entfernt mit Bluetooth zu tun hat.
-Hast Du irgendwelche anderen Dienste laufen, die auf Bluetooth zugreifen? (Batterieskripte z. B.)
-Wenn das Problem auftritt und Du _nur_ lepresenced neustartest, ist dann wieder alles ok oder musst Du den Pi Durchstarten?

Patrick

/Edit: Um solche Probleme zu detektieren und ggf. zu reagieren müsste man eine Art Heartbeat-G-Tag laufen lassen, d. h. einen Tag, der immer in Reichweite ist. Wird er nicht mehr empfangen, gibt es ein Problem. Das könnte man auch in lepresenced einbauen, aber:
-Man müsste eine Maßnahme finden, die ohne Systemneustart den Scan wieder in Gang setzt - s. o.
-Korrekterweise müsste man stattdessen die Ursache für das Problem finden.

Von unterwegs gesendet.

[digiart]

Ich möchte mich auch einmal hier einklinken.
Ich habe einen Bluetoothdongle an einem Pi Zero laufen, und in FHEM 3 Devices definiert (1 x iTag, 1 x Telefon, 1 x Autobatterieüberwachung).

Der iTag und die Autobatterieüberwachung sind (derzeit) ständig im Umkreis von ca. 1,5m vom Bluetoothdongle.
Nach der Installation lief alles gut an, allerdings bemerkte ich nach einiger Zeit auch, dass die beiden Devices auf absent geschalten wurden. ein Neustart von lepresenced hat die Devices dann wieder auf present geschalten.
Ich habe dann einfach in die crontab um Mitternacht den Dienst neustarten lassen. Hat leider nicht geholfen.
Nun starte ich den Dienst alle 6 Stunden neu, nun läuft die Erkennung stabil.
Für die Logs habe ich noch keine Zeit gehabt, da ich noch weitere (wichtigere) Baustellen zu bearbeiten habe.

[PatrickR]

@digiart: Zumindest nehme ich mal mit, dass ein Neustart von lepresenced hilft. Ich würde aktuell davon ausgehen, dass das auf den Neustart der Scan-Prozesse zurückzuführen ist. Darauf könnte man einen Workaround aufbauen wenn es gelänge, den Zeitpunkt des Ausfalls sicher zu detektieren.


Von unterwegs gesendet.

[rastagandalf]

Hi!
Das mit der Systemzeit solltest Du Dir mal anschauen. Sowas ist generell nicht gut. Bei lepresenced führt es dazu, dass um 19:09Uhr (18:17Uhr) ein Tag zu Unrecht rausfliegt.

Schaue ich mal nach - schon irgendwie komisch. Vielleicht wars aber auch der Neustart und da hatte sich noch irgendwas auf den NTP synchronisiert oder so?

Mit Deinem Hauptproblem hat das aber nichts zu tun. Leider ist das der ungünstigste Fall eines Fehlers, der auftreten kann. Alles ist prima und verhält sich exakt als seien die G-Tags außer Reichweite: Die Scan-Prozesse (hcitool/hcidump) laufen weiter und haben bis zum Auftreten des Problems die (fast exakt) gleiche Anzahl an Beacons empfangen. Insofern sieht für lepresenced alles wunderbar aus.

Das hatte mich auch verwirrt, da ich ja eigentlich noch Infos von lepresenced kriege - da ist also weder was falsch gestartet noch abgestürzt auf der Seite...

Das Debuggen ist entsprechend schwierig:
-Schau doch mal bitte, ob zur relevanten Zeit etwas Spannendes im Syslog steht, was entfernt mit Bluetooth zu tun hat.

Prüfe ich sobald ich wieder zu Hause bin.

-Hast Du irgendwelche anderen Dienste laufen, die auf Bluetooth zugreifen? (Batterieskripte z. B.)

Nein, ich hab Bluetooth generell erst für lepresenced installiert und habe lediglich lepresenced für die Nutzung mit BT installiert.

-Wenn das Problem auftritt und Du _nur_ lepresenced neustartest, ist dann wieder alles ok oder musst Du den Pi Durchstarten?

Genügt hier in Deinen Augen "sudo lepresenced restart" bzw. erst "lepresenced stop", dann "...start"?
Ich meine, ich hatte mal "hciconfig hci0 down" und anschließend wieder "...up" gemacht und es ging wieder (reagiert lepresenced darauf irgendwie? Oder klappt ggf. anschließend einfach der Empfang wieder richtig?), werde aber beides (lepresenced neustarten und hciconf down/up) nochmal probieren wenn es wieder abstürzt.

-Man müsste eine Maßnahme finden, die ohne Systemneustart den Scan wieder in Gang setzt - s. o.

ggf. wäre das bei mir das hciconfig

-Korrekterweise müsste man stattdessen die Ursache für das Problem finden.

Das wäre mir deutlich lieber.

Habe noch versucht im Freundes-/Kollegenkreis so einen zweiten Dongle aufzutreiben, leider nix über BT 3.0 verfügbar...
Ich werde auch hier berichten sobald ich den CSR-Dongle in den Händen halte, ob vielleicht hier das Problem liegt.

Den Tipp von digiart werde ich mal verfolgen und das (wenn alles andere vorerst nicht hilft) halbstündlich den Prozess neustarten.
Ggf. könnte man hier als Workaround einmalig beim Wechsel von "present" auf "absent" einmalig den Prozess neustarten und, wenn danach der Empfang wieder funktioniert, klappt es. Wenn er nicht wieder funktioniert ist von tatsächlicher Abwesenheit auszugehen.