nisargjhaveri/WirelessAndroidAutoDongle

Ford Sync 3 no connection on cold boot/first vehicle start

Opened this issue ยท 27 comments

cr08 commented

As requested in the other issue, I'm adding this here along with my log files.

Came across this repo a few days ago and decided to give it a go. Went straight to the latest artifact as of the time of writing: https://github.com/nisargjhaveri/AAWirelessDongle/actions/runs/7856371400

This is on a 0w (not a '2' model) and connecting to a stock Pixel 4a with Android 13.

Leaving the Pi plugged in to the vehicle before powering up, when the vehicle/headunit starts up, there's no visible connection on the headunit. The phone is ready and has the telltale 'looking for AA connection' and actively connected to the Pi's SSID. Not until I powercycle the Pi with the vehicle running does it come up and seems to do so pretty reliably.

Attached my messages log file from that attempt:
messages.zip

I also have log files from the headunit itself if needed, although they are a bit verbose and I need to redact some stuff like the GPS location that appears in numerous spots. Skimming over it I don't see anything obvious other than a 'not supported' USB message every 10-15 seconds or so. But I'm also not sure what I'd be looking for.

Side note during this most recent test and I can move this to its own issue if you'd like: I tried to use the assistant and it didn't seem to want to pick up my voice. The little animation at the bottom of the screen just stayed until it timed out. Using the native wired connection I've had zero issues with this. A quick search here and I don't readily see anything mentioned about this (unless I'm using the wrong search terms).

'Specs':

Pi zero w
Pixel 4a - stock Android 13
Ford C-Max Energi w/ Sync 3 v3.4.23188 (latest version available as of this writing)

My Pi 0 W is coming tomorrow, I will see if I observe the same behaviour in my 2019 Escape with Sync 3.4.23188 as well.

Hmm was going to try out my Pi with a Ford Ka+ Active, but now reading this I dunno...

Can confirm, Same issue with my Escape running Sync v3.4.23188.

It also doesn't re-connect if you walk away from the car while it's running and then come back.

Looks like some exception while connecting usb.

Is this an issue only with Pi 0w or other models as well?

Jan  1 00:00:20 buildroot kern.warn kernel: [   20.869054] ------------[ cut here ]------------
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.871552] WARNING: CPU: 0 PID: 0 at drivers/usb/dwc2/gadget.c:3127 dwc2_hsotg_epint+0xe84/0xf90 [dwc2]
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.876889] Modules linked in: rfcomm usb_f_fs usb_f_accessory ipv6 cmac algif_hash aes_arm aes_generic ecb algif_skcipher af_alg libcomposite dwc2 roles hci_uart btbcm bluetooth ecdh_generic ecc libaes brcmfmac brcmutil sha2
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.885519] CPU: 0 PID: 0 Comm: swapper Not tainted 6.1.61 #1
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.888467] Hardware name: BCM2835
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.891312]  unwind_backtrace from show_stack+0x10/0x14
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.894192]  show_stack from dump_stack_lvl+0x24/0x3c
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.897072]  dump_stack_lvl from __warn+0x78/0xc0
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.899964]  __warn from warn_slowpath_fmt+0x6c/0xc8
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.902908]  warn_slowpath_fmt from dwc2_hsotg_epint+0xe84/0xf90 [dwc2]
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.906177]  dwc2_hsotg_epint [dwc2] from dwc2_hsotg_irq+0x880/0xc40 [dwc2]
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.909623]  dwc2_hsotg_irq [dwc2] from __handle_irq_event_percpu+0x44/0x134
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.913011]  __handle_irq_event_percpu from handle_irq_event+0x28/0x68
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.916194]  handle_irq_event from handle_level_irq+0x9c/0x170
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.919430]  handle_level_irq from generic_handle_domain_irq+0x24/0x34
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.922775]  generic_handle_domain_irq from bcm2835_handle_irq+0x20/0x28
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.926204]  bcm2835_handle_irq from generic_handle_arch_irq+0x28/0x3c
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.929582]  generic_handle_arch_irq from __irq_svc+0x70/0x90
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.932883] Exception stack(0xc0a55f30 to 0xc0a55f78)
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.936208] 5f20:                                     00000000 00000000 00000001 00000000
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.942824] 5f40: c0a5a080 00000000 c0a570a0 d9bffc00 ffffffff 00000000 c0a42a64 00000000
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.949619] 5f60: 0020c49c c0a55f80 c000f298 c000f29c 60000013 ffffffff
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.953083]  __irq_svc from arch_cpu_idle+0x28/0x30
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.956522]  arch_cpu_idle from do_idle+0xb4/0xe8
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.959873]  do_idle from cpu_startup_entry+0x1c/0x20
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.963143]  cpu_startup_entry from rest_init+0x78/0x94
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.966323]  rest_init from arch_post_acpi_subsys_init+0x0/0x8
Jan  1 00:00:20 buildroot kern.warn kernel: [   20.969538] ---[ end trace 0000000000000000 ]---
cr08 commented

Only tested with the 0w so far here. I need to see what full size Pi models I have on hand I can try to test with. I also live near a Microcenter so I can try picking up a 02w later and test with that.

I built an image for my Pi 0 W with the pull request for reconnecting last night, will report if it works when I get in my car after work today.

I do have a Pi 4 I can try today as well.

Alright, I did some testing.

Firstly, I realized that running my own build of the pull request was pointless because it looks like the latest artifact on here includes that code already. I ran the latest artifact build on my Pi 4 to see if the same issue (and that exception) occurred.

  1. The same connection issues apply. It does sometimes connect from a cold boot but I think the problem is related to the fact that when you open the door, the head unit powers up and sits on a ford logo until you turn the car on, so it's providing power to the Pi but it doesn't start looking for AA devices until Sync 3 actually boots. It seems like if I get in the car and immediately start it so Sync boots, it will usually connect but if I get in and wait a minute or two before starting the car, it will not connect unless I power cycle the Pi. This happens on both my Zero W and my 4B.
  2. On either device, if I leave the range of the car and lose connection, when I come back to the car it will not ever re-connect, I just get "Looking for Android Auto" looping forever on my phone until I power cycle the Pi, and then it will connect.
  3. I pulled the logs (below) from the Pi 4 after a failed attempt to connect and I do not see any exception like what was in the other user's Zero W logs.
  4. I noticed that when it does work, the Pi 4 connects WAY faster than the Zero W. Is this because it uses 5 GHz?

Ultimately, this is basically useless for me now as I have no interest in power cycling the Pi every single time I get in my car, or if I leave my car running and go out of range. I haven't tested it but I assume if I remote start the car and don't come into range immediately, it will probably also fail to connect the same way as if I left and came back, and this is something I do often for at least 6 months of the year because I live in Canada and command start my car most days in the winter to warm it up.

I'm trying to get myself familiar enough with the code to try a few things, but what I don't quite understand is how the communication works. I see people mentioning that the car sends a request to look for an AA device, but unless I'm mistaken, is it not the other way around? Doesn't the device (phone or adapter) notify the car that it is AA capable when it's connected? It would make sense to me if it worked that way, and what I assume is happening is that the adapter in this case is only sending that report one time on boot and the head unit is missing it because it's being sent before it can actually listen for it.

I looked through the code for the reconnect pull request and I don't fully understand it, however could we just code such that whenever a phone connects to the Pi's Wi-Fi network, the Pi triggers a new connection to the head unit?

This isn't only a Ford problem, if you skim through the issues it looks like it's happening on at least Suzuki and Renault vehicles as well.

Pi 4 Log:

Jan  1 00:00:04 buildroot syslog.info syslogd started: BusyBox v1.36.1
Jan  1 00:00:04 buildroot kern.notice kernel: klogd started: BusyBox v1.36.1 (2024-02-11 10:29:05 UTC)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Booting Linux on physical CPU 0x0
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.000000] Linux version 6.1.61-v7l (runner@fv-az979-539) (arm-buildroot-linux-gnueabihf-gcc.br_real (Buildroot -g7a59c3a4) 12.3.0, GNU ld (GNU Binutils) 2.40) #1 SMP Sun Feb 11 11:02:21 UTC 2024
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] CPU: div instructions available: patching division code
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.2
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.000000] random: crng init done
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Memory policy: Data cache writealloc
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Reserved memory: created CMA memory pool at 0x000000002ac00000, size 64 MiB
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Zone ranges:
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000]   DMA      [mem 0x0000000000000000-0x000000002fffffff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000]   Normal   empty
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000]   HighMem  [mem 0x0000000030000000-0x00000000fbffffff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Movable zone start for each node
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Early memory node ranges
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000]   node   0: [mem 0x0000000000000000-0x0000000039bfffff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000]   node   0: [mem 0x0000000040000000-0x00000000fbffffff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] percpu: Embedded 12 pages/cpu s18004 r8192 d22956 u49152
Jan  1 00:00:04 buildroot kern.debug kernel: [    0.000000] pcpu-alloc: s18004 r8192 d22956 u49152 alloc=12*4096
Jan  1 00:00:04 buildroot kern.debug kernel: [    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1004864
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbswap=1 smsc95xx.macaddr=E4:5F:01:01:E0:A6 vc_mem.mem_base=0x3ec00000 vc
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] mem auto-init: stack:all(zero), heap alloc:off, heap free:offJan  1 00:00:04 buildroot kern.info kernel: [    0.000000] software IO TLB: area num 4.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] software IO TLB: mapped [mem 0x0000000024890000-0x0000000028890000] (64MB)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] Memory: 3840368K/4026368K available (10240K kernel code, 750K rwdata, 2528K rodata, 2048K init, 545K bss, 120464K reserved, 65536K cma-reserved, 3239936K highmem)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] rcu: Hierarchical RCU implementation.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000]      Tracing variant of Tasks RCU enabled.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] GIC: Using split EOI/Deactivate mode
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000000] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000015] Switching to timer-based delay loop, resolution 18ns
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000307] Console: colour dummy device 80x30
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000771] printk: console [tty1] enabled
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000819] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000854] CPU: Testing write buffer coherency: ok
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000905] CPU0: Spectre BHB: enabling loop workaround for all CPUs
Jan  1 00:00:04 buildroot kern.info kernel: [    0.000924] pid_max: default: 32768 minimum: 301
Jan  1 00:00:04 buildroot kern.info kernel: [    0.001014] LSM: Security Framework initializing
Jan  1 00:00:04 buildroot kern.info kernel: [    0.001113] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.001147] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.002118] cgroup: Disabling memory control group subsystem
Jan  1 00:00:04 buildroot kern.info kernel: [    0.002539] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Jan  1 00:00:04 buildroot kern.info kernel: [    0.003215] cblist_init_generic: Setting adjustable number of callback queues.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.003240] cblist_init_generic: Setting shift to 2 and lim to 1.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.003349] Setting up static identity map for 0x200000 - 0x20003c
Jan  1 00:00:04 buildroot kern.info kernel: [    0.003467] rcu: Hierarchical SRCU implementation.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.003486] rcu:         Max phase no-delay instances is 1000.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.004048] smp: Bringing up secondary CPUs ...
Jan  1 00:00:04 buildroot kern.info kernel: [    0.004738] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
Jan  1 00:00:04 buildroot kern.info kernel: [    0.005470] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
Jan  1 00:00:04 buildroot kern.info kernel: [    0.006193] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
Jan  1 00:00:04 buildroot kern.info kernel: [    0.006282] smp: Brought up 1 node, 4 CPUs
Jan  1 00:00:04 buildroot kern.info kernel: [    0.006337] SMP: Total of 4 processors activated (432.00 BogoMIPS).
Jan  1 00:00:04 buildroot kern.info kernel: [    0.006357] CPU: All CPU(s) started in HYP mode.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.006372] CPU: Virtualization extensions available.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.006884] devtmpfs: initialized
Jan  1 00:00:04 buildroot kern.info kernel: [    0.016871] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
Jan  1 00:00:04 buildroot kern.info kernel: [    0.017055] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
Jan  1 00:00:04 buildroot kern.info kernel: [    0.017094] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.018608] pinctrl core: initialized pinctrl subsystem
Jan  1 00:00:04 buildroot kern.info kernel: [    0.019328] NET: Registered PF_NETLINK/PF_ROUTE protocol family
Jan  1 00:00:04 buildroot kern.info kernel: [    0.021270] DMA: preallocated 1024 KiB pool for atomic coherent allocations
Jan  1 00:00:04 buildroot kern.info kernel: [    0.021844] audit: initializing netlink subsys (disabled)
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.022011] audit: type=2000 audit(0.020:1): state=initialized audit_enabled=0 res=1
Jan  1 00:00:04 buildroot kern.info kernel: [    0.022450] thermal_sys: Registered thermal governor 'step_wise'
Jan  1 00:00:04 buildroot kern.info kernel: [    0.022651] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.022691] hw-breakpoint: maximum watchpoint size is 8 bytes.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.023018] Serial: AMBA PL011 UART driver
Jan  1 00:00:04 buildroot kern.info kernel: [    0.029059] bcm2835-mbox fe00b880.mailbox: mailbox enabled
Jan  1 00:00:04 buildroot kern.info kernel: [    0.049970] raspberrypi-firmware soc:firmware: Attached to firmware from 2023-10-17T15:39:16, variant start
Jan  1 00:00:04 buildroot kern.info kernel: [    0.059990] raspberrypi-firmware soc:firmware: Firmware hash is 30f0c5e4d076da3ab4f341d88e7d505760b93ad7
Jan  1 00:00:04 buildroot kern.info kernel: [    0.097232] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.098714] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.101593] SCSI subsystem initialized
Jan  1 00:00:04 buildroot kern.info kernel: [    0.101764] usbcore: registered new interface driver usbfs
Jan  1 00:00:04 buildroot kern.info kernel: [    0.101821] usbcore: registered new interface driver hub
Jan  1 00:00:04 buildroot kern.info kernel: [    0.101873] usbcore: registered new device driver usb
Jan  1 00:00:04 buildroot kern.warn kernel: [    0.102020] usb_phy_generic phy: supply vcc not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.info kernel: [    0.102298] pps_core: LinuxPPS API ver. 1 registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.102318] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
Jan  1 00:00:04 buildroot kern.info kernel: [    0.102358] PTP clock support registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.103190] vgaarb: loaded
Jan  1 00:00:04 buildroot kern.info kernel: [    0.103517] clocksource: Switched to clocksource arch_sys_counter
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.103782] VFS: Disk quotas dquot_6.6.0
Jan  1 00:00:04 buildroot kern.info kernel: [    0.103845] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.103963] FS-Cache: Loaded
Jan  1 00:00:04 buildroot kern.info kernel: [    0.104092] CacheFiles: Loaded
Jan  1 00:00:04 buildroot kern.info kernel: [    0.111028] NET: Registered PF_INET protocol family
Jan  1 00:00:04 buildroot kern.info kernel: [    0.111244] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113080] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113122] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113153] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113222] TCP bind hash table entries: 8192 (order: 5, 131072 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113364] TCP: Hash tables configured (established 8192 bind 8192)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113479] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113677] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.113863] NET: Registered PF_UNIX/PF_LOCAL protocol family
Jan  1 00:00:04 buildroot kern.info kernel: [    0.114271] RPC: Registered named UNIX socket transport module.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.114294] RPC: Registered udp transport module.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.114311] RPC: Registered tcp transport module.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.114326] RPC: Registered tcp NFSv4.1 backchannel transport module.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.114350] PCI: CLS 0 bytes, default 64
Jan  1 00:00:04 buildroot kern.info kernel: [    0.115493] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.116403] Initialise system trusted keyrings
Jan  1 00:00:04 buildroot kern.info kernel: [    0.116546] workingset: timestamp_bits=14 max_order=20 bucket_order=6
Jan  1 00:00:04 buildroot kern.info kernel: [    0.121264] zbud: loaded
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.122832] NFS: Registering the id_resolver key type
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.122875] Key type id_resolver registered
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.122892] Key type id_legacy registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.122978] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
Jan  1 00:00:04 buildroot kern.info kernel: [    0.123000] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.123948] Key type asymmetric registered
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.123971] Asymmetric key parser 'x509' registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.124106] bounce: pool size: 64 pages
Jan  1 00:00:04 buildroot kern.info kernel: [    0.124222] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.124376] io scheduler mq-deadline registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.124397] io scheduler kyber registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.128539] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
Jan  1 00:00:04 buildroot kern.info kernel: [    0.128586] brcm-pcie fd500000.pcie:   No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.128644] brcm-pcie fd500000.pcie:      MEM 0x0600000000..0x063fffffff -> 0x00c0000000
Jan  1 00:00:04 buildroot kern.info kernel: [    0.128696] brcm-pcie fd500000.pcie:   IB MEM 0x0000000000..0x00bfffffff -> 0x0400000000
Jan  1 00:00:04 buildroot kern.info kernel: [    0.129205] brcm-pcie fd500000.pcie: setting SCB_ACCESS_EN, READ_UR_MODE, MAX_BURST_SIZE
Jan  1 00:00:04 buildroot kern.info kernel: [    0.129443] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
Jan  1 00:00:04 buildroot kern.info kernel: [    0.129469] pci_bus 0000:00: root bus resource [bus 00-ff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.129493] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])
Jan  1 00:00:04 buildroot kern.info kernel: [    0.129550] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
Jan  1 00:00:04 buildroot kern.info kernel: [    0.129648] pci 0000:00:00.0: PME# supported from D0 D3hot
Jan  1 00:00:04 buildroot kern.info kernel: [    0.132535] PCI: bus0: Fast back to back transfers disabled
Jan  1 00:00:04 buildroot kern.warn kernel: [    0.132671] pci_bus 0000:01: supply vpcie3v3 not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.warn kernel: [    0.132768] pci_bus 0000:01: supply vpcie3v3aux not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.warn kernel: [    0.132807] pci_bus 0000:01: supply vpcie12v not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.info kernel: [    0.235600] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.235747] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
Jan  1 00:00:04 buildroot kern.info kernel: [    0.235855] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]Jan  1 00:00:04 buildroot kern.info kernel: [    0.236152] pci 0000:01:00.0: PME# supported from D0 D3cold
Jan  1 00:00:04 buildroot kern.info kernel: [    0.236585] PCI: bus1: Fast back to back transfers disabled
Jan  1 00:00:04 buildroot kern.info kernel: [    0.236631] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.236661] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.236740] pci 0000:00:00.0: PCI bridge to [bus 01]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.236763] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
Jan  1 00:00:04 buildroot kern.info kernel: [    0.236947] pcieport 0000:00:00.0: enabling device (0000 -> 0002)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.237099] pcieport 0000:00:00.0: PME: Signaling with IRQ 45
Jan  1 00:00:04 buildroot kern.err kernel: [    0.237840] bcm2708_fb soc:fb: Unable to determine number of FBs. Disabling driver.
Jan  1 00:00:04 buildroot kern.warn kernel: [    0.237868] bcm2708_fb: probe of soc:fb failed with error -2
Jan  1 00:00:04 buildroot kern.info kernel: [    0.244988] iproc-rng200 fe104000.rng: hwrng registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.245140] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.253741] brd: module loaded
Jan  1 00:00:04 buildroot kern.info kernel: [    0.257810] loop: module loaded
Jan  1 00:00:04 buildroot kern.info kernel: [    0.258248] Loading iSCSI transport class v2.0-870.
Jan  1 00:00:04 buildroot kern.info kernel: [    0.261509] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
Jan  1 00:00:04 buildroot kern.info kernel: [    0.413587] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
Jan  1 00:00:04 buildroot kern.info kernel: [    0.414436] usbcore: registered new interface driver r8152
Jan  1 00:00:04 buildroot kern.info kernel: [    0.414513] usbcore: registered new interface driver lan78xx
Jan  1 00:00:04 buildroot kern.info kernel: [    0.414569] usbcore: registered new interface driver smsc95xx
Jan  1 00:00:04 buildroot kern.info kernel: [    0.415889] xhci_hcd 0000:01:00.0: enabling device (0140 -> 0142)
Jan  1 00:00:04 buildroot kern.info kernel: [    0.416027] xhci_hcd 0000:01:00.0: xHCI Host Controller
Jan  1 00:00:04 buildroot kern.info kernel: [    0.416066] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
Jan  1 00:00:04 buildroot kern.info kernel: [    0.419329] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0b00040000000890
Jan  1 00:00:04 buildroot kern.info kernel: [    0.419744] xhci_hcd 0000:01:00.0: xHCI Host Controller
Jan  1 00:00:04 buildroot kern.info kernel: [    0.419774] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
Jan  1 00:00:04 buildroot kern.info kernel: [    0.419803] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
Jan  1 00:00:04 buildroot kern.info kernel: [    0.420029] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.01
Jan  1 00:00:04 buildroot kern.info kernel: [    0.420061] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jan  1 00:00:04 buildroot kern.info kernel: [    0.420086] usb usb1: Product: xHCI Host Controller
Jan  1 00:00:04 buildroot kern.info kernel: [    0.420104] usb usb1: Manufacturer: Linux 6.1.61-v7l xhci-hcd
Jan  1 00:00:04 buildroot kern.info kernel: [    0.420123] usb usb1: SerialNumber: 0000:01:00.0
Jan  1 00:00:04 buildroot kern.info kernel: [    0.420618] hub 1-0:1.0: USB hub found
Jan  1 00:00:04 buildroot kern.info kernel: [    0.420692] hub 1-0:1.0: 1 port detected
Jan  1 00:00:04 buildroot kern.info kernel: [    0.421213] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.01
Jan  1 00:00:04 buildroot kern.info kernel: [    0.421245] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jan  1 00:00:04 buildroot kern.info kernel: [    0.421270] usb usb2: Product: xHCI Host Controller
Jan  1 00:00:04 buildroot kern.info kernel: [    0.421288] usb usb2: Manufacturer: Linux 6.1.61-v7l xhci-hcd
Jan  1 00:00:04 buildroot kern.info kernel: [    0.421307] usb usb2: SerialNumber: 0000:01:00.0
Jan  1 00:00:04 buildroot kern.info kernel: [    0.421732] hub 2-0:1.0: USB hub found
Jan  1 00:00:04 buildroot kern.info kernel: [    0.421801] hub 2-0:1.0: 4 ports detected
Jan  1 00:00:04 buildroot kern.info kernel: [    0.422796] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Jan  1 00:00:04 buildroot kern.debug kernel: [    0.422905] dwc_otg: FIQ enabled
Jan  1 00:00:04 buildroot kern.debug kernel: [    0.422912] dwc_otg: NAK holdoff enabled
Jan  1 00:00:04 buildroot kern.debug kernel: [    0.422919] dwc_otg: FIQ split-transaction FSM enabled
Jan  1 00:00:04 buildroot kern.debug kernel: [    0.422930] Module dwc_common_port init
Jan  1 00:00:04 buildroot kern.info kernel: [    0.423217] usbcore: registered new interface driver uas
Jan  1 00:00:04 buildroot kern.info kernel: [    0.423297] usbcore: registered new interface driver usb-storage
Jan  1 00:00:04 buildroot kern.info kernel: [    0.423465] mousedev: PS/2 mouse device common for all mice
Jan  1 00:00:04 buildroot kern.info kernel: [    0.425192] sdhci: Secure Digital Host Controller Interface driver
Jan  1 00:00:04 buildroot kern.info kernel: [    0.425216] sdhci: Copyright(c) Pierre Ossman
Jan  1 00:00:04 buildroot kern.info kernel: [    0.425419] sdhci-pltfm: SDHCI platform and OF driver helper
Jan  1 00:00:04 buildroot kern.info kernel: [    0.427729] ledtrig-cpu: registered to indicate activity on CPUs
Jan  1 00:00:04 buildroot kern.info kernel: [    0.427977] hid: raw HID events driver (C) Jiri Kosina
Jan  1 00:00:04 buildroot kern.info kernel: [    0.428076] usbcore: registered new interface driver usbhid
Jan  1 00:00:04 buildroot kern.info kernel: [    0.428095] usbhid: USB HID core driver
Jan  1 00:00:04 buildroot kern.info kernel: [    0.431837] Initializing XFRM netlink socket
Jan  1 00:00:04 buildroot kern.info kernel: [    0.431888] NET: Registered PF_PACKET protocol family
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.431973] Key type dns_resolver registered
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.432089] Registering SWP/SWPB emulation handler
Jan  1 00:00:04 buildroot kern.info kernel: [    0.432244] registered taskstats version 1
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.432282] Loading compiled-in X.509 certificates
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.432846] Key type .fscrypt registered
Jan  1 00:00:04 buildroot kern.notice kernel: [    0.432867] Key type fscrypt-provisioning registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.436581] uart-pl011 fe201000.serial: there is not valid maps for state default
Jan  1 00:00:04 buildroot kern.info kernel: [    0.436917] uart-pl011 fe201000.serial: cts_event_workaround enabled
Jan  1 00:00:04 buildroot kern.info kernel: [    0.437019] fe201000.serial: ttyAMA1 at MMIO 0xfe201000 (irq = 50, base_baud = 0) is a PL011 rev2
Jan  1 00:00:04 buildroot kern.info kernel: [    0.437195] serial serial0: tty port ttyAMA1 registered
Jan  1 00:00:04 buildroot kern.info kernel: [    0.443714] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
Jan  1 00:00:04 buildroot kern.info kernel: [    0.443951] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
Jan  1 00:00:04 buildroot kern.info kernel: [    0.444637] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
Jan  1 00:00:04 buildroot kern.info kernel: [    0.444665] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
Jan  1 00:00:04 buildroot kern.info kernel: [    0.471420] of_cfs_init
Jan  1 00:00:04 buildroot kern.info kernel: [    0.471571] of_cfs_init: OK
Jan  1 00:00:04 buildroot kern.info kernel: [    0.508500] mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA
Jan  1 00:00:04 buildroot kern.info kernel: [    0.508770] Waiting for root device /dev/mmcblk0p2...
Jan  1 00:00:04 buildroot kern.info kernel: [    0.551339] mmc1: new high speed SDIO card at address 0001
Jan  1 00:00:04 buildroot kern.info kernel: [    0.608150] mmc0: new ultra high speed DDR50 SDHC card at address 1234
Jan  1 00:00:04 buildroot kern.info kernel: [    0.608772] mmcblk0: mmc0:1234 SA32G 28.9 GiB
Jan  1 00:00:04 buildroot kern.info kernel: [    0.610623]  mmcblk0: p1 p2
Jan  1 00:00:04 buildroot kern.info kernel: [    0.610998] mmcblk0: mmc0:1234 SA32G 28.9 GiB
Jan  1 00:00:04 buildroot kern.info kernel: [    0.627876] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
Jan  1 00:00:04 buildroot kern.info kernel: [    0.627908] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
Jan  1 00:00:04 buildroot kern.info kernel: [    0.703539] usb 1-1: new high-speed USB device number 2 using xhci_hcd
Jan  1 00:00:04 buildroot kern.info kernel: [    0.886106] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
Jan  1 00:00:04 buildroot kern.info kernel: [    0.886143] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
Jan  1 00:00:04 buildroot kern.info kernel: [    0.886166] usb 1-1: Product: USB2.0 Hub
Jan  1 00:00:04 buildroot kern.info kernel: [    0.887707] hub 1-1:1.0: USB hub found
Jan  1 00:00:04 buildroot kern.info kernel: [    0.887991] hub 1-1:1.0: 4 ports detected
Jan  1 00:00:04 buildroot kern.info kernel: [    2.132579] EXT4-fs (mmcblk0p2): orphan cleanup on readonly fs
Jan  1 00:00:04 buildroot kern.info kernel: [    2.132683] EXT4-fs (mmcblk0p2): recovery complete
Jan  1 00:00:04 buildroot kern.info kernel: [    2.644231] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Quota mode: none.
Jan  1 00:00:04 buildroot kern.info kernel: [    2.644309] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.Jan  1 00:00:04 buildroot kern.info kernel: [    2.644925] devtmpfs: mounted
Jan  1 00:00:04 buildroot kern.info kernel: [    2.647374] Freeing unused kernel image (initmem) memory: 2048K
Jan  1 00:00:04 buildroot kern.info kernel: [    2.647656] Run /sbin/init as init process
Jan  1 00:00:04 buildroot kern.debug kernel: [    2.647674]   with arguments:
Jan  1 00:00:04 buildroot kern.debug kernel: [    2.647680]     /sbin/init
Jan  1 00:00:04 buildroot kern.debug kernel: [    2.647687]   with environment:
Jan  1 00:00:04 buildroot kern.debug kernel: [    2.647693]     HOME=/
Jan  1 00:00:04 buildroot kern.debug kernel: [    2.647699]     TERM=linux
Jan  1 00:00:04 buildroot kern.info kernel: [    3.024877] EXT4-fs (mmcblk0p2): re-mounted. Quota mode: none.
Jan  1 00:00:04 buildroot kern.notice kernel: [    3.280930] cfg80211: Loading compiled-in X.509 certificates for regulatory database
Jan  1 00:00:04 buildroot kern.notice kernel: [    3.304850] cfg80211: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf'
Jan  1 00:00:04 buildroot kern.notice kernel: [    3.306285] cfg80211: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328'
Jan  1 00:00:04 buildroot kern.notice kernel: [    3.307714] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
Jan  1 00:00:04 buildroot kern.debug kernel: [    3.394241] brcmfmac: F1 signature read @0x18000000=0x15264345
Jan  1 00:00:04 buildroot kern.info kernel: [    3.399583] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
Jan  1 00:00:04 buildroot kern.info kernel: [    3.400102] usbcore: registered new interface driver brcmfmac
Jan  1 00:00:04 buildroot kern.warn kernel: [    3.400890] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43455-sdio.raspberrypi,4-model-b.bin failed with error -2
Jan  1 00:00:04 buildroot kern.info kernel: [    3.558250] Bluetooth: Core ver 2.22
Jan  1 00:00:04 buildroot kern.info kernel: [    3.558312] NET: Registered PF_BLUETOOTH protocol family
Jan  1 00:00:04 buildroot kern.info kernel: [    3.558330] Bluetooth: HCI device and connection manager initialized
Jan  1 00:00:04 buildroot kern.info kernel: [    3.558359] Bluetooth: HCI socket layer initialized
Jan  1 00:00:04 buildroot kern.info kernel: [    3.558381] Bluetooth: L2CAP socket layer initialized
Jan  1 00:00:04 buildroot kern.info kernel: [    3.558401] Bluetooth: SCO socket layer initialized
Jan  1 00:00:04 buildroot kern.info kernel: [    3.576665] Bluetooth: HCI UART driver ver 2.3
Jan  1 00:00:04 buildroot kern.info kernel: [    3.576706] Bluetooth: HCI UART protocol H4 registered
Jan  1 00:00:04 buildroot kern.info kernel: [    3.576891] Bluetooth: HCI UART protocol Three-wire (H5) registered
Jan  1 00:00:04 buildroot kern.info kernel: [    3.577275] Bluetooth: HCI UART protocol Broadcom registered
Jan  1 00:00:04 buildroot kern.warn kernel: [    3.578691] hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.warn kernel: [    3.578822] hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.info kernel: [    3.629370] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Nov  1 2021 00:37:25 version 7.45.241 (1a2f2fa CY) FWID 01-703fd60
Jan  1 00:00:04 buildroot kern.info kernel: [    3.683722] uart-pl011 fe201000.serial: no DMA platform data
Jan  1 00:00:04 buildroot kern.warn kernel: [    3.882598] dwc2 fe980000.usb: supply vusb_d not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.warn kernel: [    3.882734] dwc2 fe980000.usb: supply vusb_a not found, using dummy regulator
Jan  1 00:00:04 buildroot kern.info kernel: [    3.934073] Bluetooth: hci0: BCM: chip id 107
Jan  1 00:00:04 buildroot kern.info kernel: [    3.934364] Bluetooth: hci0: BCM: features 0x2f
Jan  1 00:00:04 buildroot kern.info kernel: [    3.935459] Bluetooth: hci0: BCM4345C0
Jan  1 00:00:04 buildroot kern.info kernel: [    3.935481] Bluetooth: hci0: BCM4345C0 (003.001.025) build 0000
Jan  1 00:00:04 buildroot kern.info kernel: [    3.938729] Bluetooth: hci0: BCM4345C0 'brcm/BCM4345C0.hcd' Patch
Jan  1 00:00:04 buildroot kern.info kernel: [    3.983577] dwc2 fe980000.usb: EPs: 8, dedicated fifos, 4080 entries in SPRAM
Jan  1 00:00:04 buildroot daemon.notice haveged: haveged starting up
Jan  1 00:00:04 buildroot daemon.info rngd: Initializing available sources
Jan  1 00:00:04 buildroot daemon.info rngd: [hwrng ]: Initialized
Jan  1 00:00:04 buildroot daemon.info rngd: [jitter]: JITTER timeout set to 5 sec
Jan  1 00:00:04 buildroot kern.info kernel: [    4.614487] Bluetooth: hci0: BCM: features 0x2f
Jan  1 00:00:04 buildroot kern.info kernel: [    4.615874] Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+
Jan  1 00:00:04 buildroot kern.info kernel: [    4.615910] Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342
Jan  1 00:00:04 buildroot daemon.info bluetoothd[171]: Bluetooth daemon 5.68
Jan  1 00:00:04 buildroot daemon.info bluetoothd[171]: Starting SDP server
Jan  1 00:00:04 buildroot daemon.warn bluetoothd[171]: src/plugin.c:plugin_init() System does not support csip plugin
Jan  1 00:00:04 buildroot daemon.warn bluetoothd[171]: src/plugin.c:plugin_init() System does not support bass plugin
Jan  1 00:00:04 buildroot daemon.warn bluetoothd[171]: profiles/network/bnep.c:bnep_init() kernel lacks bnep-protocol support
Jan  1 00:00:04 buildroot daemon.warn bluetoothd[171]: src/plugin.c:plugin_init() System does not support network pluginJan  1 00:00:04 buildroot daemon.info bluetoothd[171]: Bluetooth management interface 1.22 initialized
Jan  1 00:00:04 buildroot kern.info kernel: [    4.832375] Bluetooth: MGMT ver 1.22
Jan  1 00:00:04 buildroot kern.info kernel: [    4.848638] NET: Registered PF_ALG protocol family
Jan  1 00:00:04 buildroot kern.info kernel: [    4.878216] cryptd: max_cpu_qlen set to 1000
Jan  1 00:00:05 buildroot kern.info kernel: [    5.261127] NET: Registered PF_INET6 protocol family
Jan  1 00:00:05 buildroot kern.info kernel: [    5.262687] Segment Routing with IPv6
Jan  1 00:00:05 buildroot kern.info kernel: [    5.262743] In-situ OAM (IOAM) with IPv6
Jan  1 00:00:05 buildroot kern.info kernel: [    5.262929] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan  1 00:00:05 buildroot authpriv.info dropbear[228]: Running in background
Jan  1 00:00:05 buildroot daemon.info dnsmasq[232]: started, version 2.89 cachesize 150
Jan  1 00:00:05 buildroot daemon.info dnsmasq[232]: compile time options: IPv6 GNU-getopt DBus no-UBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset no-nftset auth no-cryptohash no-DNSSEC loop-detect inotify dumpfile
Jan  1 00:00:05 buildroot daemon.info dnsmasq-dhcp[232]: DHCP, IP range 10.0.0.2 -- 10.0.0.20, lease time 12h
Jan  1 00:00:05 buildroot daemon.info dnsmasq[232]: read /etc/hosts - 2 names
Jan  1 00:00:05 buildroot daemon.info rngd: [jitter]: Initializing AES buffer
Jan  1 00:00:05 buildroot kern.info kernel: [    5.443662] file system registered
Jan  1 00:00:05 buildroot kern.info kernel: [    5.487288] read descriptors
Jan  1 00:00:05 buildroot kern.info kernel: [    5.487334] read strings
Jan  1 00:00:06 buildroot user.info usb_gadget: Enabled default usb gadget
Jan  1 00:00:06 buildroot daemon.info : starting pid 268, tty '/dev/tty1': '/sbin/getty -L  tty1 0 vt100 '
Jan  1 00:00:06 buildroot user.info aawgd[267]: AA Wireless Dongle
Jan  1 00:00:06 buildroot user.info aawgd[267]: Starting uevent monitoring
Jan  1 00:00:06 buildroot user.info aawgd[267]: Uevent monitoring started
Jan  1 00:00:06 buildroot user.info aawgd[267]: Initializing USB Manager
Jan  1 00:00:06 buildroot user.info aawgd[267]: USB Manager: Disabled all USB gadgets
Jan  1 00:00:06 buildroot user.info aawgd[267]: USB Manager: Start default gadget after restart
Jan  1 00:00:06 buildroot user.info aawgd[267]: USB Manager: Found UDC fe980000.usb
Jan  1 00:00:06 buildroot user.info aawgd[267]: Unique Name: :1.2
Jan  1 00:00:06 buildroot user.info aawgd[267]: Using bluetooth adapter at path: /org/bluez/hci0
Jan  1 00:00:06 buildroot user.info aawgd[267]: Bluetooth AA Wireless profile active
Jan  1 00:00:06 buildroot user.info aawgd[267]: HSP Handset profile active
Jan  1 00:00:06 buildroot user.info aawgd[267]: Starting tcp server
Jan  1 00:00:06 buildroot user.info aawgd[267]: Tcp server listening on 5288
Jan  1 00:00:06 buildroot kern.info kernel: [    6.733624] Bluetooth: RFCOMM TTY layer initialized
Jan  1 00:00:06 buildroot kern.info kernel: [    6.733679] Bluetooth: RFCOMM socket layer initialized
Jan  1 00:00:06 buildroot kern.info kernel: [    6.733698] Bluetooth: RFCOMM ver 1.11
Jan  1 00:00:06 buildroot user.info aawgd[267]: Bluetooth adapter was powered on
Jan  1 00:00:06 buildroot user.info aawgd[267]: Bluetooth adapter is now discoverable and pairable
Jan  1 00:00:06 buildroot user.info aawgd[267]: Found 1 bluetooth devices
Jan  1 00:00:06 buildroot user.info aawgd[267]: Trying to connect bluetooth device at path: /org/bluez/hci0/dev_E8_D5_2B_09_3C_96
Jan  1 00:00:07 buildroot user.info aawgd[267]: HSP HS NewConnection
Jan  1 00:00:07 buildroot user.info aawgd[267]: Path: /org/bluez/hci0/dev_E8_D5_2B_09_3C_96, fd: 10
Jan  1 00:00:07 buildroot user.info aawgd[267]: Bluetooth connected to the device
Jan  1 00:00:09 buildroot daemon.info rngd: [jitter]: Unable to obtain AES key, disabling JITTER source
Jan  1 00:00:09 buildroot daemon.err rngd: [jitter]: Initialization Failed
Jan  1 00:00:13 buildroot user.info aawgd[267]: AA Wireless NewConnection
Jan  1 00:00:13 buildroot user.info aawgd[267]: Path: /org/bluez/hci0/dev_E8_D5_2B_09_3C_96, fd: 11
Jan  1 00:00:13 buildroot user.info aawgd[267]: Sending WifiStartRequest (ip: 10.0.0.1, port: 5288)
Jan  1 00:00:13 buildroot user.info aawgd[267]: Sent WifiStartRequest, messageId: 1, wrote 17 bytes
Jan  1 00:00:13 buildroot user.info aawgd[267]: Read WifiInfoRequest. length: 0, messageId: 2
Jan  1 00:00:13 buildroot user.info aawgd[267]: Sending WifiInfoResponse (ssid: AAWirelessDongle, bssid: e4:5f:01:01:e0:a7)
Jan  1 00:00:13 buildroot user.info aawgd[267]: Sent WifiInfoResponse, messageId: 3, wrote 70 bytes
Jan  1 00:00:13 buildroot user.info aawgd[267]: Read WifiStartResponse. length: 2, messageId: 7
Jan  1 00:00:17 buildroot daemon.info hostapd: wlan0: STA 32:64:64:30:3d:e6 IEEE 802.11: associated
Jan  1 00:00:17 buildroot daemon.info hostapd: wlan0: STA 32:64:64:30:3d:e6 WPA: pairwise key handshake completed (RSN)
Jan  1 00:00:17 buildroot kern.err kernel: [   17.795987] ieee80211 phy0: brcmf_p2p_send_action_frame: Unknown Frame: category 0x8a, action 0x6
Jan  1 00:00:21 buildroot daemon.info dnsmasq-dhcp[232]: DHCPDISCOVER(wlan0) 32:64:64:30:3d:e6
Jan  1 00:00:21 buildroot daemon.info dnsmasq-dhcp[232]: DHCPOFFER(wlan0) 10.0.0.2 32:64:64:30:3d:e6
Jan  1 00:00:21 buildroot daemon.info dnsmasq-dhcp[232]: DHCPDISCOVER(wlan0) 32:64:64:30:3d:e6
Jan  1 00:00:21 buildroot daemon.info dnsmasq-dhcp[232]: DHCPOFFER(wlan0) 10.0.0.2 32:64:64:30:3d:e6
Jan  1 00:00:21 buildroot daemon.info dnsmasq-dhcp[232]: DHCPREQUEST(wlan0) 10.0.0.2 32:64:64:30:3d:e6
Jan  1 00:00:21 buildroot daemon.info dnsmasq-dhcp[232]: DHCPACK(wlan0) 10.0.0.2 32:64:64:30:3d:e6 Pixel-7
Jan  1 00:00:21 buildroot user.info aawgd[267]: Tcp server accepted connection
Jan  1 00:00:21 buildroot kern.info kernel: [   21.393297] dwc2 fe980000.usb: bound driver configfs-gadget.default
Jan  1 00:00:21 buildroot user.info aawgd[267]: USB Manager: Enabled default gadget
Jan  1 00:00:21 buildroot kern.info kernel: [   21.520029] dwc2 fe980000.usb: new device is high-speed
Jan  1 00:00:21 buildroot kern.info kernel: [   21.640432] android_work: sent uevent USB_STATE=CONNECTED
Jan  1 00:00:21 buildroot kern.info kernel: [   21.640612] dwc2 fe980000.usb: new address 4
Jan  1 00:00:21 buildroot kern.info kernel: [   21.665647] android_work: sent uevent USB_STATE=CONFIGURED
Jan  1 00:00:21 buildroot user.info aawgd[267]: Read WifiConnectStatus. length: 2, messageId: 6
Jan  1 00:00:21 buildroot user.info aawgd[267]: Bluetooth launch sequence completed
Jan  1 00:00:21 buildroot daemon.err bluetoothd[171]: src/adv_monitor.c:btd_adv_monitor_power_down() Unexpected NULL btd_adv_monitor_manager object upon power down
Jan  1 00:00:22 buildroot daemon.err bluetoothd[171]: src/profile.c:ext_io_disconnected() Unable to get io data for HSP HS: getpeername: Transport endpoint is not connected (107)
Jan  1 00:00:22 buildroot daemon.err bluetoothd[171]: src/profile.c:ext_io_disconnected() Unable to get io data for AA Wireless: getpeername: Transport endpoint is not connected (107)
Jan  1 00:00:22 buildroot user.info aawgd[267]: Bluetooth adapter was powered off
Jan  1 00:02:34 buildroot daemon.info hostapd: wlan0: STA 00:93:37:97:8b:8c IEEE 802.11: associated
Jan  1 00:02:34 buildroot daemon.info hostapd: wlan0: STA 00:93:37:97:8b:8c WPA: pairwise key handshake completed (RSN)
Jan  1 00:02:37 buildroot daemon.info dnsmasq-dhcp[232]: DHCPDISCOVER(wlan0) 00:93:37:97:8b:8c
Jan  1 00:02:37 buildroot daemon.info dnsmasq-dhcp[232]: DHCPOFFER(wlan0) 10.0.0.12 00:93:37:97:8b:8c
Jan  1 00:02:37 buildroot daemon.info dnsmasq-dhcp[232]: DHCPREQUEST(wlan0) 10.0.0.12 00:93:37:97:8b:8c
Jan  1 00:02:37 buildroot daemon.info dnsmasq-dhcp[232]: DHCPACK(wlan0) 10.0.0.12 00:93:37:97:8b:8c DESKTOP-1U6J8I0
Jan  1 00:07:05 buildroot authpriv.info dropbear[278]: Child connection from 10.0.0.12:63041
Jan  1 00:07:05 buildroot authpriv.info dropbear[278]: Generated hostkey /etc/dropbear/dropbear_ed25519_host_key, fingerprint is SHA256:ignJ1GjJqd9XMbEtRTkDP5iVPWyMFws/h8WhPCd4t1Q
Jan  1 00:07:10 buildroot authpriv.notice dropbear[278]: Password auth succeeded for 'root' from 10.0.0.12:63041
Jan  1 00:10:24 buildroot authpriv.info dropbear[278]: Exit (root) from <10.0.0.12:63041>: Disconnect received
Jan  1 00:10:35 buildroot authpriv.info dropbear[286]: Child connection from 10.0.0.12:51532
Jan  1 00:10:37 buildroot authpriv.warn dropbear[286]: Login attempt for nonexistent user
Jan  1 00:10:43 buildroot authpriv.info dropbear[286]: Exit before auth from <10.0.0.12:51532>: Exited normally
Jan  1 00:10:48 buildroot authpriv.info dropbear[287]: Child connection from 10.0.0.12:51440
Jan  1 00:10:50 buildroot authpriv.notice dropbear[287]: Password auth succeeded for 'root' from 10.0.0.12:51440

Tried both modes with the "select mode operation" pull request, neither works properly either. Basically every time I start the car I have to wait until Sync is booted and then power cycle the Pi.

So, I have a bit of an update.

When I first started using this project I too went to the latest artifact but when I did that I didn't initially realize it was containing code from a pull request. I realized that late last week and decided to run a build of just the main repo this weekend (since there hasn't been a release November but there have been changes) and it appears to working completely fine for me. My phone has connected from a cold boot without issue since Saturday.

The only thing I don't understand is that the artifact mentioned in this issue should be the same code as what I built. Are you sure you downloaded that artifact and not one containing the pull request?

cr08 commented

So, I have a bit of an update.

When I first started using this project I too went to the latest artifact but when I did that I didn't initially realize it was containing code from a pull request. I realized that late last week and decided to run a build of just the main repo this weekend (since there hasn't been a release November but there have been changes) and it appears to working completely fine for me. My phone has connected from a cold boot without issue since Saturday.

The only thing I don't understand is that the artifact mentioned in this issue should be the same code as what I built. Are you sure you downloaded that artifact and not one containing the pull request?

Positive. The link I posted above is exactly where I pulled from (which was the latest at the time of the post, I see some newer artifacts are up now). I will try later this afternoon with a local build and report back.

Sorry I haven't posted any newer updates from my end. My local Microcenter went out of stock of the Zero 2's and the only other free Pi I have is a 4 which @admiralspeedy has already been working with. Will continue to try the 0w I have now with the test this afternoon.

cr08 commented

Ok. Just a quick test sitting in my garage and building my own image seems to have helped here. I need to take a few drives to confirm, but it's looking good so far. Voice/mic usage also seems to have been fixed in my case. Same 0w and microSD card I was using previously.

So, I have a bit of an update.
When I first started using this project I too went to the latest artifact but when I did that I didn't initially realize it was containing code from a pull request. I realized that late last week and decided to run a build of just the main repo this weekend (since there hasn't been a release November but there have been changes) and it appears to working completely fine for me. My phone has connected from a cold boot without issue since Saturday.
The only thing I don't understand is that the artifact mentioned in this issue should be the same code as what I built. Are you sure you downloaded that artifact and not one containing the pull request?

Positive. The link I posted above is exactly where I pulled from (which was the latest at the time of the post, I see some newer artifacts are up now). I will try later this afternoon with a local build and report back.

Sorry I haven't posted any newer updates from my end. My local Microcenter went out of stock of the Zero 2's and the only other free Pi I have is a 4 which @admiralspeedy has already been working with. Will continue to try the 0w I have now with the test this afternoon.

The one you linked was not the latest at the time you made this issue. This one, created by the pull request existed before you made this post, as well as two others before the one you linked. I can only assume you are mistaken on which one you downloaded because if you had truly used the one you linked, it would have been the exact same code as what you and I both built because that was the last change to the main repo until the name change this morning.

I will say I did speak too soon though. So it does work perfectly for me now every time from a cold start however I did just find a situation where it doesn't work properly now. When I got home from work I parked my car on the street for about 4-5 minutes because I had to do something in my driveway. I got back in my car and pulled it in the driveway when I was done and it was just stuck on "Looking for Android Auto..." on my phone, despite working perfectly from cold starts three other times today.

I suspect my car did not completely shut down the Pi in the 5 or so minutes the car was parked and off. For whatever reason my Escape likes to seemingly randomly and arbitrarily keep power going to the USB ports for a long time after shutting the car off, and sometimes it doesn't. When I was testing last week, it kept the Pi powered on for almost 10 minutes after I got out of the car for some reason (I knew because the AA Wireless network was still showing up on my phone in my house) and my touch screen backlight stayed lit up. Today on my lunch break at work, I shut the car off when I got back to the office and everything turned off immediately, including the Pi.

Not sure why it does this but we definitely need some code to work around it because I suspect (haven't tested yet but I will) that this also means that if I walk out of range of the Pi with my phone and come back, it will not connect again without power cycling the Pi. I think this is what the pull request is actually trying to fix, however it seems that it breaks the initial connection as we have both experienced now.

cr08 commented

The one you linked was not the latest at the time you made this issue. This one, created by the pull request existed before you made this post, as well as two others before the one you linked. I can only assume you are mistaken on which one you downloaded because if you had truly used the one you linked, it would have been the exact same code as what you and I both built because that was the last change to the main repo until the name change this morning.

Ok. I had a chance to dig further into it and I see where the disconnect was. I was originally following the link @nisargjhaveri posted in #52 which only shows main branch commits and at the time of writing that was current even though there was newer stuff in other branches. Ultimately I think going forward I'm just going to do my own builds and save the confusion.

The Pi not fully powering down in those short stops I can definitely see with Sync. I don't know the exact behaviors, but I do know under normal operation it shouldn't be shutting down straight away likely to allow a warm boot to happen on short trips. The age/charge level of the 12v battery can also effect this and how long it stays powered. I know when I was experimenting a while back I had an old phone connected to the second USB port on the back of the APIM for power with Tasker configured to shut down on power loss and sometimes it stayed powered for 5-10 minutes after key-off while some others it shut down shortly after. But ultimately it means this definitely seems like a key area of focus for Ford vehicles.

Well, I can't explain why that build wouldn't work but do your own does then.

I could test it myself but it's probably not worth the effort lol. I'm trying to understand the code a bit more to figure out the power down thing.

Well, it's like 90% functional for me. Yesterday morning I had to disconnect and connect the Pi twice on my way to work before it would connect, and now it has worked again every time since then,

We really need persistent logs because I cannot simple turn around and come back within range of my house/PC to SSH into the Pi whenever it fails and doing it on a phone is tedious.

We really need persistent logs because I cannot simple turn around and come back within range of my house/PC to SSH into the Pi whenever it fails and doing it on a phone is tedious.

I completely agree. Though, frequently writing on the SD card can corrupt the SD card if the power suddenly goes away, which would be the case in most cars, we don't get a chance to shutdown properly. And once it is corrupt, you need to re-image the card to make it work again.

Maybe we can have a config for this, and when on, it'll to persist the logs. This should minimise the risk to only the people actively debugging.

cr08 commented

This is actually something I meant to ask (and a little off topic) is what kind of protections are in place against SD card corruption. I haven't trolled through the code much myself yet but it seems like some care has went into this at least based on the logs not being persistent. And it seems like the overall 'OS' build seems to be tightly controlled and not just a 'slapped on top of Raspbian' setup.

#72 should help with the issue where headunit starts much later than the power to the the dongle, if anyone wants to try out.

@admiralspeedy, @cr08 let's move the persistent log conversation to a new issue?

#72 should help with the issue where headunit starts much later than the power to the the dongle, if anyone wants to try out.

@admiralspeedy, @cr08 let's move the persistent log conversation to a new issue?

I will build this right now at work and try it when I leave. Do you think this mode will also resolve the issues related to the phone connecting and disconnecting while the dongle is still powered?

Do you think this mode will also resolve the issues related to the phone connecting and disconnecting while the dongle is still powered?

No the reconnection issue is different. It needs some more work the cleanly close tcp and usb sockets on error or timeout. Not part of the current change.

Do you think this mode will also resolve the issues related to the phone connecting and disconnecting while the dongle is still powered?

No the reconnection issue is different. It needs some more work the cleanly close tcp and usb sockets on error or timeout. Not part of the current change.

I spent most of the evening last night toying with some ideas on how to handle it, but the sockets do not throw an error or timeout when the phone is disconnected. Reading and writing from them is still successful. I was able to set up the Android Studio Desktop Head Unit Emulator to test this in my house instead of going back and forth from my PC and my car. It's handy because I can also see logs on the Android Auto side through the head unit emulator's terminal window.

The first thing I tried is creating another thread in proxyHandler that loops and pings the phone with a system call so I could listen for it to disconnect, but this is super hacky and slow. I started looking at the emulator logs and I can see that when the phone is disconnected AA reports a timeout so I suspect that if we intercept the messages in proxyHandler we can detect those timeout messages.

I could also be really dumb, and maybe there is a really easy way to determine when the phone has disconnected, but I haven't touched sockets for years.

cr08 commented

Had a chance today to go out for a few sequential trips with about 5-15 minutes in between. Knock on wood it connected reliably each time and the subsequent stops (likely the Pi was still booted/powered) it reconnected pretty quick with no input from me. Not 100% sure if it was long enough for things to fully power down at the time.

However the lack of working mic is back again and did not resolve itself on those subsequent drives. I'll check it again after it has sat and fully powered down and try again and get the logs.

Also I'll open the new issue regarding the persistent logs here soon.

Had a chance today to go out for a few sequential trips with about 5-15 minutes in between. Knock on wood it connected reliably each time and the subsequent stops (likely the Pi was still booted/powered) it reconnected pretty quick with no input from me. Not 100% sure if it was long enough for things to fully power down at the time.

However the lack of working mic is back again and did not resolve itself on those subsequent drives. I'll check it again after it has sat and fully powered down and try again and get the logs.

Also I'll open the new issue regarding the persistent logs here soon.

Have you had any resolution with the mic input not working? I've been having the same issue on a F150 with Sync 3.4 and using a pi0w. Sometimes the first input will be recognized (ex: asking it to text someone), but then nothing else after. Most of the time though the mic does not seem to be picked up at all.

Had a chance today to go out for a few sequential trips with about 5-15 minutes in between. Knock on wood it connected reliably each time and the subsequent stops (likely the Pi was still booted/powered) it reconnected pretty quick with no input from me. Not 100% sure if it was long enough for things to fully power down at the time.

However the lack of working mic is back again and did not resolve itself on those subsequent drives. I'll check it again after it has sat and fully powered down and try again and get the logs.

Also I'll open the new issue regarding the persistent logs here soon.

That's pure luck because the current build still does not handle disconnects properly lol. I worked on it all weekend though and have made some progress. We have been discussing it on #26 .

Had a chance today to go out for a few sequential trips with about 5-15 minutes in between. Knock on wood it connected reliably each time and the subsequent stops (likely the Pi was still booted/powered) it reconnected pretty quick with no input from me. Not 100% sure if it was long enough for things to fully power down at the time.
However the lack of working mic is back again and did not resolve itself on those subsequent drives. I'll check it again after it has sat and fully powered down and try again and get the logs.
Also I'll open the new issue regarding the persistent logs here soon.

Have you had any resolution with the mic input not working? I've been having the same issue on a F150 with Sync 3.4 and using a pi0w. Sometimes the first input will be recognized (ex: asking it to text someone), but then nothing else after. Most of the time though the mic does not seem to be picked up at all.

I've been talking about this issue in #26 but I found some stuff online suggesting that this issue is not exclusive to this project and happens with many of the commercially available adapters too.

Some people suggest that it is related to using 2.4 GHz over 5 GHz, but I disproved that by switching from my Pi Zero W to my Pi 4, which uses 5 GHz. I have also tried a few other code changes but had no luck.

One suggestion I did read is that someone said what fixed it on their AAWireless dongle was changing a setting in their app to keep the Bluetooth connection alive after a disconnection and enable "Use this device for calls" in the dongle's Bluetooth settings. I am going to make some changes today to keep the Bluetooth connection alive but I don't know how I'm going to do the call routing thing.

cr08 commented

Had a chance today to go out for a few sequential trips with about 5-15 minutes in between. Knock on wood it connected reliably each time and the subsequent stops (likely the Pi was still booted/powered) it reconnected pretty quick with no input from me. Not 100% sure if it was long enough for things to fully power down at the time.
However the lack of working mic is back again and did not resolve itself on those subsequent drives. I'll check it again after it has sat and fully powered down and try again and get the logs.
Also I'll open the new issue regarding the persistent logs here soon.

That's pure luck because the current build still does not handle disconnects properly lol. I worked on it all weekend though and have made some progress. We have been discussing it on #26 .

Yeah. That first day seemed to be perfect but subsequent days it went back to being hit or miss. But it did seem to be improved overall.

Also good catch on the microphone audio issue. I haven't really bothered to look much into the commercial products and how they behave. Mostly because I have a Pixel 4a with poor battery life that using wireless regularly isn't really useful. I jumped on this project to tinker and provide any help I can because the Pi was already on hand. Can't say no to free! ๐Ÿ˜…But I am hoping to get a new phone in this week so I can start using it more often.

Sorry I haven't kept up on this or provided the logs/started that persistent log issue. My day job's kept me super busy and haven't had the extra mental capacity to tinker. I have a few errands I need to run later today and I'll do some more checking and update accordingly.

Bunch of the changes for recovering the connection has went into v0.4.0 along with dongle mode, which should also helo with early start of dongle in some cases. I believe most of the issues should've been fixed with it.