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

RPi 3B bluetooth causes WiFi issues #520

Closed
scop opened this issue Dec 27, 2019 · 9 comments
Closed

RPi 3B bluetooth causes WiFi issues #520

scop opened this issue Dec 27, 2019 · 9 comments

Comments

@scop
Copy link
Member

scop commented Dec 27, 2019

HassOS release with the issue:

3.7 32-bit. Also tested with 3.7 64-bit, 2.5 64-bit, 2.12 32-bit, and 3.6 32-bit.

Supervisor logs:

18-12-21 18:54:04 INFO (MainThread) [__main__] Initialize Hass.io setup
18-12-21 18:54:05 INFO (MainThread) [hassio.docker.network] Can't find Hass.io network, create new network
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Home Assistant configuration folder /data/homeassistant
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io SSL/TLS folder /data/ssl
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io Add-on data folder /data/addons/data
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io Add-on local repository folder /data/addons/local
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io Add-on git repositories folder /data/addons/git
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io temp folder /data/tmp
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io backup folder /data/backup
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io share folder /data/share
18-12-21 18:54:05 INFO (MainThread) [hassio.bootstrap] Create Hass.io DNS folder /data/dns
18-12-21 18:54:05 INFO (SyncWorker_0) [hassio.docker.supervisor] Attach to Supervisor homeassistant/armv7-hassio-supervisor with version 193
18-12-21 18:54:05 INFO (SyncWorker_0) [hassio.docker.supervisor] Connect Supervisor to Hass.io Network
18-12-21 18:54:06 INFO (MainThread) [__main__] Setup HassIO
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Connect to dbus: org.freedesktop.systemd1 - /org/freedesktop/systemd1
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Connect to dbus: org.freedesktop.hostname1 - /org/freedesktop/hostname1
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Connect to dbus: de.pengutronix.rauc - /
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Connect to dbus: org.freedesktop.NetworkManager - /org/freedesktop/NetworkManager/DnsManager
18-12-21 18:54:06 INFO (MainThread) [hassio.host.info] Update local host information
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Call org.freedesktop.DBus.Properties.GetAll on /org/freedesktop/hostname1
18-12-21 18:54:06 INFO (MainThread) [hassio.host.services] Update service information
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Call org.freedesktop.systemd1.Manager.ListUnits on /org/freedesktop/systemd1
18-12-21 18:54:06 INFO (MainThread) [hassio.host.network] Update local network DNS information
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Call org.freedesktop.DBus.Properties.GetAll on /org/freedesktop/NetworkManager/DnsManager
18-12-21 18:54:06 INFO (MainThread) [hassio.host.apparmor] Load AppArmor Profiles: {'hassio-supervisor'}
18-12-21 18:54:06 INFO (MainThread) [hassio.host.services] Reload local service hassos-apparmor.service
18-12-21 18:54:06 INFO (MainThread) [hassio.utils.gdbus] Call org.freedesktop.systemd1.Manager.ReloadOrRestartUnit on /org/freedesktop/systemd1
18-12-21 18:54:06 INFO (MainThread) [hassio.dns] No CoreDNS plugin Docker image homeassistant/armv7-hassio-dns found.
18-12-21 18:54:06 INFO (MainThread) [hassio.dns] Setup CoreDNS plugin
18-12-21 18:54:06 INFO (MainThread) [hassio.updater] Fetch update data from https://version.home-assistant.io/stable.json
18-12-21 18:54:07 WARNING (MainThread) [hassio.updater] Can't fetch versions from https://version.home-assistant.io/stable.json: Cannot connect to host version.home-assistant.io:443 ssl:None [Address not available]
18-12-21 18:54:07 WARNING (MainThread) [hassio.dns] Error on install CoreDNS plugin. Retry in 30sec
19-12-27 07:32:22 INFO (MainThread) [hassio.updater] Fetch update data from https://version.home-assistant.io/stable.json
19-12-27 07:32:22 INFO (SyncWorker_0) [hassio.docker.interface] Pull image homeassistant/armv7-hassio-dns tag 1.
19-12-27 07:32:42 INFO (MainThread) [hassio.dns] CoreDNS plugin now installed
19-12-27 07:32:42 INFO (MainThread) [hassio.dns] Update resolv from Supervisor
19-12-27 07:32:42 INFO (MainThread) [hassio.misc.forwarder] Start DNS port forwarding to 172.30.32.3
19-12-27 07:32:42 INFO (MainThread) [hassio.dns] Start CoreDNS plugin
19-12-27 07:32:51 INFO (SyncWorker_2) [hassio.docker.dns] Start DNS homeassistant/armv7-hassio-dns with version 1
19-12-27 07:32:51 INFO (MainThread) [hassio.homeassistant] No Home Assistant Docker image homeassistant/raspberrypi3-homeassistant found.
19-12-27 07:32:51 INFO (MainThread) [hassio.homeassistant] Setup HomeAssistant landingpage
19-12-27 07:32:51 INFO (SyncWorker_1) [hassio.docker.interface] Pull image homeassistant/raspberrypi3-homeassistant tag landingpage.
19-12-27 07:33:06 INFO (MainThread) [hassio.hassos] Detect HassOS 3.7 on host system
19-12-27 07:33:06 INFO (SyncWorker_5) [hassio.docker.hassos_cli] Found HassOS CLI homeassistant/armv7-hassio-cli with version 15
19-12-27 07:33:06 INFO (MainThread) [hassio.store.git] Clone add-on https://github.com/hassio-addons/repository repository
19-12-27 07:33:06 INFO (MainThread) [hassio.store.git] Clone add-on https://github.com/home-assistant/hassio-addons repository
19-12-27 07:33:10 INFO (MainThread) [hassio.store] Load add-ons from store: 62 all - 62 new - 0 remove
19-12-27 07:33:10 INFO (MainThread) [hassio.addons] Found 0 installed add-ons
19-12-27 07:33:10 INFO (MainThread) [hassio.snapshots] Found 0 snapshot files
19-12-27 07:33:10 INFO (MainThread) [hassio.discovery] Load 0 messages
19-12-27 07:33:10 INFO (MainThread) [hassio.ingress] Load 0 ingress session
19-12-27 07:33:10 INFO (MainThread) [hassio.secrets] Load Home Assistant secrets: 0
19-12-27 07:33:10 INFO (MainThread) [__main__] Run Hass.io
19-12-27 07:33:10 INFO (MainThread) [hassio.api] Start API on 172.30.32.2
19-12-27 07:33:10 INFO (MainThread) [hassio.addons] Phase 'initialize' start 0 add-ons
19-12-27 07:33:10 INFO (MainThread) [hassio.addons] Phase 'system' start 0 add-ons
19-12-27 07:33:10 INFO (MainThread) [hassio.addons] Phase 'services' start 0 add-ons
19-12-27 07:33:18 INFO (SyncWorker_9) [hassio.docker.homeassistant] Start homeassistant homeassistant/raspberrypi3-homeassistant with version landingpage
19-12-27 07:33:23 INFO (MainThread) [hassio.homeassistant] Detect a running Home Assistant instance
19-12-27 07:33:23 INFO (MainThread) [hassio.addons] Phase 'application' start 0 add-ons
19-12-27 07:33:24 INFO (MainThread) [hassio.tasks] All core tasks are scheduled
19-12-27 07:33:24 INFO (MainThread) [hassio.core] Hass.io is up and running
19-12-27 07:33:24 INFO (MainThread) [hassio.homeassistant] Setup Home Assistant
19-12-27 07:33:24 INFO (SyncWorker_11) [hassio.docker.interface] Update image homeassistant/raspberrypi3-homeassistant:landingpage to homeassistant/raspberrypi3-homeassistant:0.103.4
19-12-27 07:33:24 INFO (SyncWorker_11) [hassio.docker.interface] Pull image homeassistant/raspberrypi3-homeassistant tag 0.103.4.
19-12-27 07:42:38 INFO (SyncWorker_11) [hassio.docker.interface] Stop homeassistant application
19-12-27 07:42:43 INFO (SyncWorker_11) [hassio.docker.interface] Clean homeassistant application
19-12-27 07:42:43 INFO (MainThread) [hassio.homeassistant] Home Assistant docker now installed
19-12-27 07:42:43 INFO (MainThread) [hassio.homeassistant] Start Home Assistant
19-12-27 07:42:46 INFO (SyncWorker_16) [hassio.docker.homeassistant] Start homeassistant homeassistant/raspberrypi3-homeassistant with version 0.103.4
19-12-27 07:43:16 INFO (MainThread) [hassio.homeassistant] Detect a running Home Assistant instance
19-12-27 07:43:16 INFO (SyncWorker_19) [hassio.docker.interface] Cleanup images: ['homeassistant/raspberrypi3-homeassistant:landingpage']
19-12-27 07:43:46 INFO (MainThread) [hassio.addons] Create Home Assistant add-on data folder /data/addons/data/core_configurator
19-12-27 07:43:46 INFO (SyncWorker_12) [hassio.docker.interface] Pull image homeassistant/armv7-addon-configurator tag 4.2.
19-12-27 07:43:57 INFO (MainThread) [hassio.addons] Add-on 'core_configurator' successfully installed
19-12-27 07:44:44 INFO (MainThread) [hassio.addons] Create Home Assistant add-on data folder /data/addons/data/core_ssh
19-12-27 07:44:44 INFO (SyncWorker_8) [hassio.docker.interface] Pull image homeassistant/armv7-addon-ssh tag 7.1.
19-12-27 07:45:24 INFO (MainThread) [hassio.addons] Add-on 'core_ssh' successfully installed
19-12-27 07:46:13 INFO (SyncWorker_2) [hassio.docker.addon] Start Docker add-on homeassistant/armv7-addon-configurator with version 4.2
19-12-27 07:46:13 INFO (SyncWorker_18) [hassio.docker.addon] Start Docker add-on homeassistant/armv7-addon-ssh with version 7.1
19-12-27 07:46:15 ERROR (MainThread) [hassio.api.ingress] Ingress error: Cannot connect to host 172.30.33.1:8099 ssl:None [Connection refused]
19-12-27 07:46:19 INFO (MainThread) [hassio.homeassistant] Updated Home Assistant API token
19-12-27 07:46:52 INFO (SyncWorker_13) [hassio.docker.interface] Restart homeassistant/raspberrypi3-homeassistant
19-12-27 07:47:30 INFO (MainThread) [hassio.homeassistant] Detect a running Home Assistant instance
19-12-27 07:50:58 INFO (MainThread) [hassio.api.security] /supervisor/logs access from core_ssh

Journal logs:

core-ssh:~# journalctl
-bash: journalctl: command not found

Kernel logs:

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.88-v7 (builder@20b9e944c217) (gcc version 7.4.0 (Buildroot 2019.02.3-gfe3260e3)) #1 SMP Mon Dec 16 19:45:35 UTC 2019
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 8 MiB at 0x3ac00000
[    0.000000] On node 0 totalpages: 242688
[    0.000000]   Normal zone: 2133 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 242688 pages, LIFO batch:63
[    0.000000] random: get_random_bytes called from start_kernel+0xb0/0x4b4 with crng_init=0
[    0.000000] percpu: Embedded 17 pages/cpu s36940 r8192 d24500 u69632
[    0.000000] pcpu-alloc: s36940 r8192 d24500 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
[    0.000000] Kernel command line: zram.enabled=1 zram.num_devices=3 apparmor=1 security=apparmor rootwait cgroup_enable=memory coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=8d3d53e3-6d49-4c38-8349-aff6859e82fd rootfstype=squashfs ro rauc.slot=A
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 936960K/970752K available (9216K kernel code, 691K rwdata, 2400K rodata, 1024K init, 835K bss, 25600K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xbb800000 - 0xff800000   (1088 MB)
[    0.000000]     lowmem  : 0x80000000 - 0xbb400000   ( 948 MB)
[    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
[    0.000000]       .text : 0x(ptrval) - 0x(ptrval)   (10208 kB)
[    0.000000]       .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
[    0.000000]       .data : 0x(ptrval) - 0x(ptrval)   ( 692 kB)
[    0.000000]        .bss : 0x(ptrval) - 0x(ptrval)   ( 836 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 30135 entries in 89 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000022] Switching to timer-based delay loop, resolution 52ns
[    0.000283] Console: colour dummy device 80x30
[    0.000925] console [tty1] enabled
[    0.000980] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.001024] pid_max: default: 32768 minimum: 301
[    0.001204] Security Framework initialized
[    0.001308] AppArmor: AppArmor initialized
[    0.001530] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001566] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.002533] CPU: Testing write buffer coherency: ok
[    0.003025] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.003708] Setting up static identity map for 0x100000 - 0x10003c
[    0.003874] rcu: Hierarchical SRCU implementation.
[    0.004699] smp: Bringing up secondary CPUs ...
[    0.005574] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.006504] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.007360] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.007485] smp: Brought up 1 node, 4 CPUs
[    0.007566] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.007591] CPU: All CPU(s) started in HYP mode.
[    0.007612] CPU: Virtualization extensions available.
[    0.008646] devtmpfs: initialized
[    0.021712] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.021978] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.022025] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.022731] pinctrl core: initialized pinctrl subsystem
[    0.023582] NET: Registered protocol family 16
[    0.026726] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.031261] audit: initializing netlink subsys (disabled)
[    0.031470] audit: type=2000 audit(0.030:1): state=initialized audit_enabled=0 res=1
[    0.032672] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.032707] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.032919] Serial: AMBA PL011 UART driver
[    0.035197] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.071069] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.072710] SCSI subsystem initialized
[    0.072975] usbcore: registered new interface driver usbfs
[    0.073056] usbcore: registered new interface driver hub
[    0.073174] usbcore: registered new device driver usb
[    0.090290] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-12-05 14:43, variant start
[    0.100122] raspberrypi-firmware soc:firmware: Firmware hash is 620e8a436f18c378f8b109a73972b44f9822961d
[    0.112042] clocksource: Switched to clocksource arch_sys_counter
[    0.207616] VFS: Disk quotas dquot_6.6.0
[    0.207745] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.207949] FS-Cache: Loaded
[    0.208185] CacheFiles: Loaded
[    0.208741] AppArmor: AppArmor Filesystem Enabled
[    0.218896] NET: Registered protocol family 2
[    0.219694] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
[    0.219759] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.219890] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.220095] TCP: Hash tables configured (established 8192 bind 8192)
[    0.220258] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.220323] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.220570] NET: Registered protocol family 1
[    0.221177] RPC: Registered named UNIX socket transport module.
[    0.221205] RPC: Registered udp transport module.
[    0.221228] RPC: Registered tcp transport module.
[    0.221250] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.222765] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.225879] Initialise system trusted keyrings
[    0.226110] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.235895] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.236187] FS-Cache: Netfs 'nfs' registered for caching
[    0.236784] NFS: Registering the id_resolver key type
[    0.236845] Key type id_resolver registered
[    0.236867] Key type id_legacy registered
[    0.236898] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.239915] Key type asymmetric registered
[    0.239945] Asymmetric key parser 'x509' registered
[    0.240014] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.240208] io scheduler noop registered
[    0.240232] io scheduler deadline registered
[    0.240435] io scheduler cfq registered (default)
[    0.240460] io scheduler mq-deadline registered
[    0.240483] io scheduler kyber registered
[    0.243921] bcm2708_fb soc:fb: FB found 1 display(s)
[    0.252142] Console: switching to colour frame buffer device 82x26
[    0.258492] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
[    0.265260] bcm2835-rng 3f104000.rng: hwrng registered
[    0.268047] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.273627] vc-sm: Videocore shared memory driver
[    0.276445] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    0.292239] brd: module loaded
[    0.304699] loop: module loaded
[    0.307771] zram: Added device: zram0
[    0.310745] zram: Added device: zram1
[    0.313686] zram: Added device: zram2
[    0.316576] Loading iSCSI transport class v2.0-870.
[    0.319591] libphy: Fixed MDIO Bus: probed
[    0.321888] tun: Universal TUN/TAP device driver, 1.6
[    0.324468] usbcore: registered new interface driver lan78xx
[    0.326746] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.329198] dwc_otg 3f980000.usb: base=(ptrval)
[    0.531664] Core Release: 2.80a
[    0.533950] Setting default values for core params
[    0.536253] Finished setting default values for core params
[    0.738865] Using Buffer DMA mode
[    0.741205] Periodic Transfer Interrupt Enhancement - disabled
[    0.743628] Multiprocessor Interrupt Enhancement - disabled
[    0.746024] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.748379] Dedicated Tx FIFOs mode
[    0.751094] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = bad04000 dma = 0xfad04000 len=9024
[    0.755771] FIQ FSM acceleration enabled for :
[    0.755771] Non-periodic Split Transactions
[    0.755771] Periodic Split Transactions
[    0.755771] High-Speed Isochronous Endpoints
[    0.755771] Interrupt/Control Split Transaction hack enabled
[    0.766610] dwc_otg: Microframe scheduler enabled
[    0.766667] WARN::hcd_init_fiq:457: FIQ on core 1
[    0.768853] WARN::hcd_init_fiq:458: FIQ ASM at 806dad9c length 36
[    0.771065] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
[    0.773326] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.775674] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    0.778078] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    0.780468] Init: Port Power? op_state=1
[    0.782807] Init: Power Port (0)
[    0.785312] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.789986] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.792509] usb usb1: Product: DWC OTG Controller
[    0.794989] usb usb1: Manufacturer: Linux 4.19.88-v7 dwc_otg_hcd
[    0.797487] usb usb1: SerialNumber: 3f980000.usb
[    0.800541] hub 1-0:1.0: USB hub found
[    0.803018] hub 1-0:1.0: 1 port detected
[    0.805954] dwc_otg: FIQ enabled
[    0.805960] dwc_otg: NAK holdoff enabled
[    0.805966] dwc_otg: FIQ split-transaction FSM enabled
[    0.805976] Module dwc_common_port init
[    0.806263] usbcore: registered new interface driver usb-storage
[    0.808777] usbcore: registered new interface driver usbserial_generic
[    0.811201] usbserial: USB Serial support registered for generic
[    0.813783] mousedev: PS/2 mouse device common for all mice
[    0.816935] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    0.819523] bcm2835-cpufreq: min=600000 max=1200000
[    0.822373] sdhci: Secure Digital Host Controller Interface driver
[    0.824794] sdhci: Copyright(c) Pierre Ossman
[    0.827590] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[    0.830486] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    0.833161] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.835665] ledtrig-cpu: registered to indicate activity on CPUs
[    0.837080] hidraw: raw HID events driver (C) Jiri Kosina
[    0.838490] usbcore: registered new interface driver usbhid
[    0.839787] usbhid: USB HID core driver
[    0.841482] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    0.843878] [vc_sm_connected_init]: start
[    0.851595] [vc_sm_connected_init]: end - returning 0
[    0.853894] IPVS: Registered protocols (TCP, UDP, SCTP, AH, ESP)
[    0.855211] IPVS: Connection hash table configured (size=4096, memory=32Kbytes)
[    0.856767] IPVS: ipvs loaded.
[    0.858012] IPVS: [rr] scheduler registered.
[    0.859991] NET: Registered protocol family 10
[    0.861894] Segment Routing with IPv6
[    0.863236] NET: Registered protocol family 17
[    0.864537] Bridge firewalling registered
[    0.865824] Key type dns_resolver registered
[    0.867396] Registering SWP/SWPB emulation handler
[    0.869031] registered taskstats version 1
[    0.870269] Loading compiled-in X.509 certificates
[    0.871523] AppArmor: AppArmor sha1 policy hashing enabled
[    0.876497] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    0.877803] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    0.881393] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    0.882688] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    0.909977] sdhost: log_buf @ (ptrval) (fad07000)
[    0.948102] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    0.952105] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.956020] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.960363] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    0.964331] console [netcon0] enabled
[    0.965883] netconsole: network logging started
[    0.967007] of_cfs_init
[    0.968173] of_cfs_init: OK
[    0.969595] Waiting for root device PARTUUID=8d3d53e3-6d49-4c38-8349-aff6859e82fd...
[    0.983120] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.018987] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.023926] Indeed it is in host mode hprt0 = 00021501
[    1.087405] mmc0: new high speed SDHC card at address 0001
[    1.089866] mmcblk0: mmc0:0001 EB1QT 29.8 GiB
[    1.091110] random: fast init done
[    1.097785] GPT:Primary header thinks Alt. header is not at the end of the disk.
[    1.100289] GPT:4194303 != 62521343
[    1.101523] GPT:Alternate GPT header not at the end of the disk.
[    1.102785] GPT:4194303 != 62521343
[    1.103977] GPT: Use GNU Parted to correct GPT errors.
[    1.105198]  mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8
[    1.114748] VFS: Mounted root (squashfs filesystem) readonly on device 179:3.
[    1.117732] devtmpfs: mounted
[    1.122702] Freeing unused kernel memory: 1024K
[    1.152554] Run /sbin/init as init process
[    1.155470] mmc1: new high speed SDIO card at address 0001
[    1.232088] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.233544] Indeed it is in host mode hprt0 = 00001101
[    1.424707] systemd[1]: System time before build time, advancing clock.
[    1.437585] systemd[1]: systemd 240 running in system mode. (-PAM -AUDIT -SELINUX -IMA -APPARMOR -SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP +GCRYPT -GNUTLS -ACL -XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid)
[    1.442403] systemd[1]: Detected architecture arm.
[    1.463647] systemd[1]: Set hostname to <hassio>.
[    1.472282] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
[    1.475015] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.475838] random: systemd: uninitialized urandom read (16 bytes read)
[    1.477962] systemd[1]: Initializing machine ID from random generator.
[    1.477992] hub 1-1:1.0: USB hub found
[    1.479527] systemd[1]: Installed transient /etc/machine-id file.
[    1.482267] hub 1-1:1.0: 5 ports detected
[    1.483301] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument
[    1.802097] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    1.807931] random: systemd: uninitialized urandom read (16 bytes read)
[    1.816643] random: systemd: uninitialized urandom read (16 bytes read)
[    1.823821] systemd[1]: Starting HassOS ZRAM tmp...
[    1.827423] systemd[1]: Reached target Slices.
[    1.831691] systemd[1]: Listening on udev Control Socket.
[    1.835651] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    1.888445] zram2: detected capacity change from 0 to 16777216
[    1.888507] zram0: detected capacity change from 0 to 242221056
[    1.892594] zram1: detected capacity change from 0 to 33554432
[    1.932600] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
[    1.935420] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.128212] smsc95xx v1.0.6
[    2.224718] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:81:21:0f
[    2.227566] usbcore: registered new interface driver smsc95xx
[    2.267594] media: Linux media interface: v0.10
[    2.271433] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    2.282496] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    2.283991] [vc_sm_connected_init]: start
[    2.287049] [vc_sm_connected_init]: installed successfully
[    2.287869] videodev: Linux video capture interface: v2.00
[    2.310145] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    2.329138] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    2.333666] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    2.338131] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    2.340074] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    2.346806] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    2.348436] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    2.359058] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    2.360599] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    2.598468] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    2.642643] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    2.677964] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    2.679650] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[    2.682897] cfg80211: failed to load regulatory.db
[    2.684846] bcm2835_audio soc:audio: card created with 8 channels
[    2.720044] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[    2.733935] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[    2.737086] usbcore: registered new interface driver brcmfmac
[    2.911918] EXT4-fs (mmcblk0p7): mounted filesystem with ordered data mode. Opts: (null)
[    2.934787] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[    2.937770] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
[    2.941391] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: Oct 23 2017 03:55:53 version 7.45.98.38 (r674442 CY) FWID 01-e58d219f
[    3.021922] Adding 236540k swap on /dev/zram0.  Priority:-2 extents:1 across:236540k SSFS
[    3.974454] EXT4-fs (zram1): mounted filesystem without journal. Opts: nobarrier
[    3.984928] EXT4-fs (zram2): mounted filesystem without journal. Opts: nobarrier
[    4.103433] systemd-journald[114]: Received request to flush runtime journal from PID 1
[    9.857712] EXT4-fs (mmcblk0p8): mounted filesystem with ordered data mode. Opts: (null)
[   10.537908] random: crng init done
[   10.539014] random: 7 urandom warning(s) missed due to ratelimiting
[   10.618124] uart-pl011 3f201000.serial: no DMA platform data
[   11.415562] Bluetooth: Core ver 2.22
[   11.416707] NET: Registered protocol family 31
[   11.417737] Bluetooth: HCI device and connection manager initialized
[   11.418795] Bluetooth: HCI socket layer initialized
[   11.419839] Bluetooth: L2CAP socket layer initialized
[   11.420894] Bluetooth: SCO socket layer initialized
[   11.435396] Bluetooth: HCI UART driver ver 2.3
[   11.436493] Bluetooth: HCI UART protocol H4 registered
[   11.437612] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   11.438799] Bluetooth: HCI UART protocol Broadcom registered
[   11.705168] audit: type=1400 audit(1545418423.269:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor" pid=293 comm="apparmor_parser"
[   11.708874] audit: type=1300 audit(1545418423.269:2): arch=40000028 syscall=4 per=800000 success=yes exit=21841 a0=6 a1=e07280 a2=5551 a3=0 items=0 ppid=290 pid=293 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="apparmor_parser" exe="/usr/sbin/apparmor_parser" subj==unconfined key=(null)
[   11.715526] audit: type=1327 audit(1545418423.269:2): proctitle=61707061726D6F725F706172736572002D72002D57002D4C002F6D6E742F646174612F73757065727669736F722F61707061726D6F722F6361636865002F6D6E742F646174612F73757065727669736F722F61707061726D6F722F68617373696F2D73757065727669736F72
[   11.721570] audit: type=1400 audit(1545418423.289:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/gdbus" pid=293 comm="apparmor_parser"
[   11.726443] audit: type=1300 audit(1545418423.289:3): arch=40000028 syscall=4 per=800000 success=yes exit=14673 a0=6 a1=ec5460 a2=3951 a3=0 items=0 ppid=290 pid=293 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="apparmor_parser" exe="/usr/sbin/apparmor_parser" subj==unconfined key=(null)
[   11.735308] audit: type=1327 audit(1545418423.289:3): proctitle=61707061726D6F725F706172736572002D72002D57002D4C002F6D6E742F646174612F73757065727669736F722F61707061726D6F722F6361636865002F6D6E742F646174612F73757065727669736F722F61707061726D6F722F68617373696F2D73757065727669736F72
[   11.735327] audit: type=1400 audit(1545418423.289:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/git" pid=293 comm="apparmor_parser"
[   11.748528] audit: type=1300 audit(1545418423.289:4): arch=40000028 syscall=4 per=800000 success=yes exit=15265 a0=6 a1=ec5460 a2=3ba1 a3=0 items=0 ppid=290 pid=293 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="apparmor_parser" exe="/usr/sbin/apparmor_parser" subj==unconfined key=(null)
[   11.748545] audit: type=1327 audit(1545418423.289:4): proctitle=61707061726D6F725F706172736572002D72002D57002D4C002F6D6E742F646174612F73757065727669736F722F61707061726D6F722F6361636865002F6D6E742F646174612F73757065727669736F722F61707061726D6F722F68617373696F2D73757065727669736F72
[   11.755946] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   11.755952] Bluetooth: BNEP filters: protocol multicast
[   11.755965] Bluetooth: BNEP socket layer initialized
[   11.762185] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   11.766311] audit: type=1400 audit(1545418423.289:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/socat" pid=293 comm="apparmor_parser"
[   11.854302] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   11.857871] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   11.884449] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   11.928254] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   11.929816] brcmfmac: power management disabled
[   12.460579] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   12.464702] brcmfmac: power management disabled
[   12.654496] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   13.700625] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   13.703433] brcmfmac: power management disabled
[   14.736891] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   20.726039] kauditd_printk_skb: 2 callbacks suppressed
[   20.726044] audit: type=1400 audit(1545418432.289:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="docker-default" pid=381 comm="apparmor_parser"
[   20.730875] audit: type=1300 audit(1545418432.289:6): arch=40000028 syscall=4 per=800000 success=yes exit=7945 a0=4 a1=14c1630 a2=1f09 a3=0 items=0 ppid=380 pid=381 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="apparmor_parser" exe="/usr/sbin/apparmor_parser" subj==unconfined key=(null)
[   20.737678] audit: type=1327 audit(1545418432.289:6): proctitle=61707061726D6F725F706172736572002D4B72002F6D6E742F646174612F646F636B65722F746D702F646F636B65722D64656661756C74333537313235393832
[   21.297906] audit: type=1325 audit(1545418432.859:7): table=nat family=2 entries=5
[   21.301072] audit: type=1300 audit(1545418432.859:7): arch=40000028 syscall=294 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=30f848 items=0 ppid=350 pid=404 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[   21.309669] audit: type=1327 audit(1545418432.859:7): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4E00444F434B4552
[   21.313434] audit: type=1325 audit(1545418432.879:8): table=filter family=2 entries=4
[   21.317123] audit: type=1300 audit(1545418432.879:8): arch=40000028 syscall=294 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=18f2738 items=0 ppid=350 pid=406 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[   21.326898] audit: type=1327 audit(1545418432.879:8): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D740066696C746572002D4E00444F434B4552
[   21.330861] audit: type=1325 audit(1545418432.889:9): table=filter family=2 entries=6
[   21.395499] Initializing XFRM netlink socket
[   21.642241] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready
[   25.926573] docker0: port 1(vethb76ffbc) entered blocking state
[   25.928222] docker0: port 1(vethb76ffbc) entered disabled state
[   25.930269] device vethb76ffbc entered promiscuous mode
[   25.931968] kauditd_printk_skb: 110 callbacks suppressed
[   25.931972] audit: type=1700 audit(1545418437.489:46): dev=vethb76ffbc prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[   25.932623] IPv6: ADDRCONF(NETDEV_UP): vethb76ffbc: link is not ready
[   25.933734] audit: type=1300 audit(1545418437.489:46): arch=40000028 syscall=290 per=800000 success=yes exit=40 a0=c a1=4008e40 a2=28 a3=0 items=0 ppid=1 pid=350 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dockerd" exe="/usr/bin/dockerd" subj==unconfined key=(null)
[   25.950148] audit: type=1327 audit(1545418437.489:46): proctitle=2F7573722F62696E2F646F636B657264002D480066643A2F2F002D2D73746F726167652D6472697665723D6F7665726C617932002D2D6C6F672D6472697665723D6A6F75726E616C64002D2D646174612D726F6F74002F6D6E742F646174612F646F636B6572
[   27.136477] eth0: renamed from veth7803967
[   27.204403] IPv6: ADDRCONF(NETDEV_CHANGE): vethb76ffbc: link becomes ready
[   27.207544] docker0: port 1(vethb76ffbc) entered blocking state
[   27.210505] docker0: port 1(vethb76ffbc) entered forwarding state
[   27.213841] IPv6: ADDRCONF(NETDEV_CHANGE): docker0: link becomes ready
[   27.600669] udevd[6]: starting version 3.2.8
[   27.637210] udevd[7]: starting eudev-3.2.8
[   33.463896] audit: type=1325 audit(1545418445.029:47): table=nat family=2 entries=11
[   33.467105] audit: type=1300 audit(1545418445.029:47): arch=40000028 syscall=294 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=23e7d8 items=0 ppid=350 pid=661 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[   33.475652] audit: type=1327 audit(1545418445.029:47): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4900504F5354524F5554494E47002D73003137322E33302E33322E302F32330000002D6F0068617373696F002D6A004D415351554552414445
[   33.482689] audit: type=1325 audit(1545418445.039:48): table=nat family=2 entries=12
[   33.486201] audit: type=1300 audit(1545418445.039:48): arch=40000028 syscall=294 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=9685b0 items=0 ppid=350 pid=663 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[   33.495014] audit: type=1327 audit(1545418445.039:48): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4900444F434B4552002D690068617373696F002D6A0052455455524E
[   33.505007] audit: type=1325 audit(1545418445.069:49): table=filter family=2 entries=23
[   33.508753] audit: type=1300 audit(1545418445.069:49): arch=40000028 syscall=294 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=1d5f2d0 items=0 ppid=350 pid=666 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[   33.518637] audit: type=1327 audit(1545418445.069:49): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D4900464F5257415244002D690068617373696F002D6F0068617373696F002D6A00414343455054
[   33.524507] audit: type=1325 audit(1545418445.079:50): table=filter family=2 entries=24
[   33.630260] IPv6: ADDRCONF(NETDEV_UP): hassio: link is not ready
[   34.101187] hassio: port 1(veth296cf0f) entered blocking state
[   34.103170] hassio: port 1(veth296cf0f) entered disabled state
[   34.105224] device veth296cf0f entered promiscuous mode
[   34.122482] IPv6: ADDRCONF(NETDEV_UP): veth296cf0f: link is not ready
[   34.124367] hassio: port 1(veth296cf0f) entered blocking state
[   34.126177] hassio: port 1(veth296cf0f) entered forwarding state
[   34.142200] hassio: port 1(veth296cf0f) entered disabled state
[   34.505152] eth1: renamed from veth7612ce4
[   34.544011] IPv6: ADDRCONF(NETDEV_CHANGE): veth296cf0f: link becomes ready
[   34.547443] hassio: port 1(veth296cf0f) entered blocking state
[   34.550575] hassio: port 1(veth296cf0f) entered forwarding state
[   34.554257] IPv6: ADDRCONF(NETDEV_CHANGE): hassio: link becomes ready
[   92.700029] hassio: port 2(veth4d15902) entered blocking state
[   92.701676] hassio: port 2(veth4d15902) entered disabled state
[   92.703785] device veth4d15902 entered promiscuous mode
[   92.705554] kauditd_printk_skb: 65 callbacks suppressed
[   92.705560] audit: type=1700 audit(1577431969.068:71): dev=veth4d15902 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[   92.706076] IPv6: ADDRCONF(NETDEV_UP): veth4d15902: link is not ready
[   92.707108] audit: type=1300 audit(1577431969.068:71): arch=40000028 syscall=290 per=800000 success=yes exit=40 a0=c a1=3d0f920 a2=28 a3=0 items=0 ppid=1 pid=350 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dockerd" exe="/usr/bin/dockerd" subj==unconfined key=(null)
[   92.717747] audit: type=1327 audit(1577431969.068:71): proctitle=2F7573722F62696E2F646F636B657264002D480066643A2F2F002D2D73746F726167652D6472697665723D6F7665726C617932002D2D6C6F672D6472697665723D6A6F75726E616C64002D2D646174612D726F6F74002F6D6E742F646174612F646F636B6572
[   94.463939] audit: type=1325 audit(1577431970.839:72): table=filter family=2 entries=0
[   94.467114] audit: type=1300 audit(1577431970.839:72): arch=40000028 syscall=295 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=7eb49a6c items=0 ppid=863 pid=875 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[   94.475597] audit: type=1327 audit(1577431970.839:72): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D4C002D6E
[   94.479187] audit: type=1325 audit(1577431970.849:73): table=nat family=2 entries=0
[   94.482841] audit: type=1300 audit(1577431970.849:73): arch=40000028 syscall=295 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=7ecb1a2c items=0 ppid=863 pid=877 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[   94.492488] audit: type=1327 audit(1577431970.849:73): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D43004F5554505554002D64003132372E302E302E3131002D6A00444F434B45525F4F5554505554
[   94.498480] audit: type=1325 audit(1577431970.849:74): table=nat family=2 entries=5
[   94.584821] eth0: renamed from veth6ec61b7
[   94.624538] IPv6: ADDRCONF(NETDEV_CHANGE): veth4d15902: link becomes ready
[   94.628383] hassio: port 2(veth4d15902) entered blocking state
[   94.631960] hassio: port 2(veth4d15902) entered forwarding state
[  690.044555] udevd[7]: starting version 3.2.8
[  690.078042] udevd[8]: starting eudev-3.2.8
[  893.260681] hassio: port 3(veth2ad5b8b) entered blocking state
[  893.262627] hassio: port 3(veth2ad5b8b) entered disabled state
[  893.265232] device veth2ad5b8b entered promiscuous mode
[  893.267024] kauditd_printk_skb: 23 callbacks suppressed
[  893.267030] audit: type=1700 audit(1577432769.630:82): dev=veth2ad5b8b prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[  893.267897] IPv6: ADDRCONF(NETDEV_UP): veth2ad5b8b: link is not ready
[  893.268921] audit: type=1300 audit(1577432769.630:82): arch=40000028 syscall=290 per=800000 success=yes exit=40 a0=c a1=40081e0 a2=28 a3=0 items=0 ppid=1 pid=350 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dockerd" exe="/usr/bin/dockerd" subj==unconfined key=(null)
[  893.280413] audit: type=1327 audit(1577432769.630:82): proctitle=2F7573722F62696E2F646F636B657264002D480066643A2F2F002D2D73746F726167652D6472697665723D6F7665726C617932002D2D6C6F672D6472697665723D6A6F75726E616C64002D2D646174612D726F6F74002F6D6E742F646174612F646F636B6572
[  894.030897] audit: type=1325 audit(1577432770.400:83): table=nat family=2 entries=13
[  894.034211] audit: type=1300 audit(1577432770.400:83): arch=40000028 syscall=294 per=800000 success=yes exit=0 a0=4 a1=0 a2=40 a3=12aabc8 items=0 ppid=350 pid=1615 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" subj==unconfined key=(null)
[  894.043008] audit: type=1327 audit(1577432770.400:83): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4100444F434B4552002D7000746370002D6400302F30002D2D64706F7274003232002D6A00444E4154002D2D746F2D64657374696E6174696F6E003137322E33302E33332E303A32320000002D690068617373696F
[  894.053345] hassio: port 4(veth1fc71fc) entered blocking state
[  894.055165] hassio: port 4(veth1fc71fc) entered disabled state
[  894.057346] device veth1fc71fc entered promiscuous mode
[  894.059314] audit: type=1700 audit(1577432770.430:84): dev=veth1fc71fc prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[  894.067319] audit: type=1300 audit(1577432770.430:84): arch=40000028 syscall=290 per=800000 success=yes exit=40 a0=c a1=3f77c50 a2=28 a3=0 items=0 ppid=1 pid=350 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dockerd" exe="/usr/bin/dockerd" subj==unconfined key=(null)
[  894.073220] IPv6: ADDRCONF(NETDEV_UP): veth1fc71fc: link is not ready
[  894.075071] audit: type=1327 audit(1577432770.430:84): proctitle=2F7573722F62696E2F646F636B657264002D480066643A2F2F002D2D73746F726167652D6472697665723D6F7665726C617932002D2D6C6F672D6472697665723D6A6F75726E616C64002D2D646174612D726F6F74002F6D6E742F646174612F646F636B6572
[  894.076742] hassio: port 4(veth1fc71fc) entered blocking state
[  894.076749] hassio: port 4(veth1fc71fc) entered forwarding state
[  894.100331] audit: type=1325 audit(1577432770.470:85): table=filter family=2 entries=29
[  894.262735] hassio: port 4(veth1fc71fc) entered disabled state
[  896.555319] eth0: renamed from vethf03dd10
[  896.604959] IPv6: ADDRCONF(NETDEV_CHANGE): veth1fc71fc: link becomes ready
[  896.608625] hassio: port 4(veth1fc71fc) entered blocking state
[  896.611888] hassio: port 4(veth1fc71fc) entered forwarding state
[  896.704625] eth0: renamed from vethc84bf2d
[  896.763530] IPv6: ADDRCONF(NETDEV_CHANGE): veth2ad5b8b: link becomes ready
[  896.766897] hassio: port 3(veth2ad5b8b) entered blocking state
[  896.770015] hassio: port 3(veth2ad5b8b) entered forwarding state
[  943.471118] udevd[7]: starting version 3.2.8
[  943.482818] udevd[8]: starting eudev-3.2.8

Description of problem:

Enabling bluetooth scan nearly kills wifi. The connection doesn't drop entirely, but seemingly always whenever there is a bluetooth scan going on, wifi ping times go to several seconds. Bluetooth and otherwise config is minimal, fresh hass.io image setup with just onboarding done and this added to configuration.yaml (via configurator or ssh addon), no other addons or hardware:

device_tracker:
  - platform: bluetooth_tracker

Normally when bluetooth scanning is not enabled pings look like:

64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1755 ttl=64 time=15.3 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1756 ttl=64 time=13.9 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1757 ttl=64 time=12.8 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1758 ttl=64 time=10.7 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1759 ttl=64 time=8.84 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1760 ttl=64 time=7.01 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1761 ttl=64 time=7.21 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1762 ttl=64 time=6.67 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1763 ttl=64 time=12.7 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1764 ttl=64 time=11.0 ms

After enabling bluetooth, they start to go like:

64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1802 ttl=64 time=5.76 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1803 ttl=64 time=5.70 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1804 ttl=64 time=10.3 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1805 ttl=64 time=1434 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1806 ttl=64 time=435 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1807 ttl=64 time=2507 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1808 ttl=64 time=3124 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1809 ttl=64 time=2100 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1810 ttl=64 time=1099 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1811 ttl=64 time=1618 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1812 ttl=64 time=617 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1813 ttl=64 time=1605 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1814 ttl=64 time=601 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1815 ttl=64 time=79.3 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1816 ttl=64 time=12.6 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1817 ttl=64 time=1541 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1818 ttl=64 time=2153 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1819 ttl=64 time=2793 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1820 ttl=64 time=3314 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1821 ttl=64 time=2314 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1822 ttl=64 time=2848 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1823 ttl=64 time=3376 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1824 ttl=64 time=3117 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1825 ttl=64 time=2119 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1826 ttl=64 time=1120 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1827 ttl=64 time=121 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1828 ttl=64 time=4.27 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1829 ttl=64 time=1360 ms
64 bytes from 192.168.100.254 (192.168.100.254): icmp_seq=1830 ttl=64 time=333 ms

...and sometimes ping loss, and even higher times. Naturally, net access of HA including SSH and web is very shaky in this state.

I have tested this with three different RPi 3B's, and happens the same with all of them. Booting off USB SSD vs SD (and no other USB devices plugged) makes nSSH and web accesso difference. All three RPis have been USB boot enabled, i.e. program_usb_boot_mode=1.

I have successfully used bluetooth on some of these RPis before. But it is possible that at that time they have been connected via ethernet, not wifi. Can't remember. And it could have been even pre-HassOS (i.e. ResinOS) times.

I've found a couple of things that I could try out, but I'm not sure how do I go about it in a RPi3 HassOS setup, i.e. where exactly on the SD card to add the files:
raspberrypi/linux#1552 (comment)
greg-erskine/pCP-github@0083f17
I suppose the modprobe option would be doable via cmdline.txt, will try that out.

Will also try with ethernet soon and report back.

Anyway, help and debugging instructions including where to try out the above settings would be welcome.

@scop
Copy link
Member Author

scop commented Dec 27, 2019

Also: nothing in home-assistant.log

@scop
Copy link
Member Author

scop commented Dec 27, 2019

brcmfmac.feature_disable=0x96 in cmdline.txt makes no difference.

@scop
Copy link
Member Author

scop commented Dec 27, 2019

No problems with bluetooth+ethernet, so it's definitely the bluetooth+wifi combo that has issues.

@smoke007
Copy link

Just throwing in my 2 cents on personal experience with the same issue. I agree that I've also had this same wifi problem with RP3 and RP zero w when bluetooth_tracker is enabled. Turning off bluetooth_track resolves the network connectivity problem. I've found bluetooth_tracker is best used with a wired network connection, so you don't have network connectivity issues.

I also experienced the same wifi issues trying to do bluetooth tracking with this other project called Monitor on a RP zero w and RP3. https://github.com/andrewjfreyer/monitor I think it's either a hardware related issue with trying to use BT and wifi at the same time or both projects are using the same wifi and BT driver with the same bug.

@scop
Copy link
Member Author

scop commented Jan 30, 2020

I've moved on to Ethernet with the setup I saw this with, but I plan to try this out with HassOS 3.8 soon with another.

@stale
Copy link

stale bot commented Mar 30, 2020

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the wontfix label Mar 30, 2020
@scop
Copy link
Member Author

scop commented Apr 4, 2020

Still going to have a look sometime.

@stale stale bot removed the wontfix label Apr 4, 2020
@pvizeli
Copy link
Member

pvizeli commented May 8, 2020

You see the issue that I all time said, RaspberryPi is bad hardware. There are much better chip manufacturers around as Broadcom. On data paper, the RPi looks fine but most people don't know the price which this data papers have. You can never use all resources at the same time.

@pvizeli pvizeli closed this as completed May 8, 2020
@scop
Copy link
Member Author

scop commented May 9, 2020

I'm still not using bluetooth+wifi, but bluetooth was broken even with ethernet for a long time. It works again with 3.13, so now's again a time when it would make sense to test this again if someone feels like it. I don't have plans to move to wifi any time soon though.

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

No branches or pull requests

3 participants