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

BLE error due to invalid MTU size on esp32c6 #3

Open
oddlama opened this issue Jan 30, 2025 · 19 comments
Open

BLE error due to invalid MTU size on esp32c6 #3

oddlama opened this issue Jan 30, 2025 · 19 comments

Comments

@oddlama
Copy link

oddlama commented Jan 30, 2025

Hi there, thanks for this great project! I noticed that you set the BLE MTU size dynamically based on the crate configuration here

// Issue with esp32c6: we can't go lower than 255 on it
// Issue with esp32: we can't go lower than 251 on it
// TODO: Make the MTU size a feature in future
#[cfg(any(target_arch = "riscv32", target_arch = "xtensa"))]
const MAX_MTU_SIZE: usize = 255;
#[cfg(not(any(target_arch = "riscv32", target_arch = "xtensa")))]
const MAX_MTU_SIZE: usize = 131;

but for esp32c6 this still results in an MTU of 131 which causes the BLE initialization to fail. I'm not entirely sure why the first cfg doesn't trigger for the esp32c6, I did set the feature and target arch just like you described in the example readme. When I remove the conditional and hardcode 255 the example boots flawlessly until i run into an unrelated BLE panic later on at the end of commissioning, which I assume is still WIP.

@ivmarkov
Copy link
Owner

I just checked and I'm pretty sure the cfg is as it should.

If you are getting this right after starting the firmware:

====================== PANIC ======================
panicked at /home/ivan/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panicking.rs:218:5:
unsafe precondition(s) violated: ptr::copy_nonoverlapping requires that both pointer arguments are aligned and non-null and the specified memory ranges do not overlap

Backtrace:

0x420fc5a8
0x420fc5a8 - core::panicking::panic_nounwind_fmt
    at /home/ivan/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/intrinsics/mod.rs:3861
0x420fc5fa
0x420fc5fa - core::panicking::panic_nounwind
    at /home/ivan/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panicking.rs:218
0x4206f1de
0x4206f1de - core::intrinsics::copy_nonoverlapping::precondition_check
    at /home/ivan/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ub_checks.rs:68
0x420703e6
0x420703e6 - core::intrinsics::copy_nonoverlapping
    at /home/ivan/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ub_checks.rs:75
0x4201e1e2
0x4201e1e2 - esp_wifi::ble::controller::asynch::<impl bt_hci::transport::Transport for esp_wifi::ble::controller::BleConnector>::write::{{closure}}
    at /home/ivan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/esp-wifi-0.12.0/src/ble/controller/mod.rs:218
0x4204dcc6
0x4204dcc6 - <embassy_futures::select::Select3<A,B,C> as core::future::future::Future>::poll
    at /home/ivan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/embassy-futures-0.1.1/src/select.rs:114
0x4203c4d0
0x4203c4d0 - trouble_host::host::Runner<C>::run_with_handler::{{closure}}
    at /home/ivan/.cargo/git/checkouts/trouble-1b801b8f2d824f83/530434b/host/src/host.rs:574
0x42045ed4
0x42045ed4 - rs_matter_embassy::ble::TroubleBtpGattPeripheral<M,C>::run::{{closure}}
    at /home/ivan/dev/rs-matter-embassy/rs-matter-embassy/src/ble.rs:239
0x4202edce
0x4202edce - <embassy_futures::select::Select4<F1,F2,F3,F4> as rs_matter::utils::select::Coalesce<T>>::coalesce::{{closure}}
    at /home/ivan/.cargo/git/checkouts/rs-matter-63faec357d04c185/4d4b695/rs-matter/src/utils/select.rs:74
0x42049ff2
0x42049ff2 - <embassy_futures::select::Select<A,B> as core::future::future::Future>::poll
    at /home/ivan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/embassy-futures-0.1.1/src/select.rs:52

... this is not caused by the MTU size and seem to happen randomly. Just restarting the MCU fixes it for me. I think it is a bug in esp-wifi.

Can you paste here the error you are seeing at the end of the BT provisioning? This is actually not expected.

@oddlama
Copy link
Author

oddlama commented Jan 30, 2025

What I'm getting is this:

INFO - Wrapping over
INFO - Responder memory: Responder=480B, Runner=13624B
INFO - Responder: Creating 4 handlers
INFO - Responder: Handlers size: 10312B
INFO - Busy Responder: Creating 2 handlers
INFO - Busy Responder: Handlers size: 712B


====================== PANIC ======================
panicked at /home/myuser/projects/embedded/rs-matter-embassy/rs-matter-embassy/src/ble.rs:252:17:
[ble_task] error: BleHost(Hci(Invalid HCI Command Parameters))

Backtrace:

0x42039770
0x42039770 - <embassy_futures::join::Join<Fut1,Fut2> as core::future::future::Future>::poll
    at ??:??
0x42049a6a
0x42049a6a - rs_matter_embassy::ble::TroubleBtpGattPeripheral<M,C>::run::{{closure}}
    at /home/myuser/projects/embedded/rs-matter-embassy/rs-matter-embassy/src/ble.rs:239
0x420291f6
0x420291f6 - <embassy_futures::select::Select4<F1,F2,F3,F4> as rs_matter::utils::select::Coalesce<T>>::coalesce::{{closure}}
    at /home/myuser/.local/share/cargo/git/checkouts/rs-matter-63faec357d04c185/4d4b695/rs-matter/src/utils/select.rs:74
0x4204d738
0x4204d738 - <embassy_futures::select::Select<A,B> as core::future::future::Future>::poll
    at /home/myuser/.local/share/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/embassy-futures-0.1.1/src/select.rs:52
0x42021e82
0x42021e82 - <embassy_futures::select::Select<F1,F2> as rs_matter::utils::select::Coalesce<T>>::coalesce::{{closure}}
    at /home/myuser/.local/share/cargo/git/checkouts/rs-matter-63faec357d04c185/4d4b695/rs-matter/src/utils/select.rs:44
0x420512a0
0x420512a0 - <embassy_futures::select::Select3<A,B,C> as core::future::future::Future>::poll
    at /home/myuser/.local/share/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/embassy-futures-0.1.1/src/select.rs:108
0x42023932
0x42023932 - <embassy_futures::select::Select3<F1,F2,F3> as rs_matter::utils::select::Coalesce<T>>::coalesce::{{closure}}
    at /home/myuser/.local/share/cargo/git/checkouts/rs-matter-63faec357d04c185/4d4b695/rs-matter/src/utils/select.rs:58
0x4204c796
0x4204c796 - <embassy_futures::select::Select<A,B> as core::future::future::Future>::poll
    at /home/myuser/.local/share/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/embassy-futures-0.1.1/src/select.rs:52
0x4202deb2
0x4202deb2 - <embassy_futures::select::Select<F1,F2> as rs_matter::utils::select::Coalesce<T>>::coalesce::{{closure}}
    at /home/myuser/.local/share/cargo/git/checkouts/rs-matter-63faec357d04c185/4d4b695/rs-matter/src/utils/select.rs:44
0x4205125c
0x4205125c - <embassy_futures::select::Select3<A,B,C> as core::future::future::Future>::poll
    at /home/myuser/.local/share/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/embassy-futures-0.1.1/src/select.rs:108

But you are right, I was too quick in drawing a conclusion. When I restart the device one or two times it works randomly. I just had "luck" when removing the cfg that it worked next time. So I guess the cfg is working properly and 255 is used in both cases, the error is just not deterministic.

@ivmarkov
Copy link
Owner

Yours is even different than mine, but I still think this is a bug in esp-wifi, yeah.

@ivmarkov
Copy link
Owner

But the question is: what is the error you are getting at the end of the provisioning? I would not expect an error there?

@oddlama
Copy link
Author

oddlama commented Jan 30, 2025

Currently trying to reproduce that so I can copy the logs, but I'm hitting different errors each time. I'll write that up shortly

@ivmarkov
Copy link
Owner

BTW, the c3 works in a much more stable fashion. Also the s3 and even the stock esp32. c6 seems to be the most unstable of all (and is the newest one anyway).

@oddlama
Copy link
Author

oddlama commented Jan 30, 2025

Good point. I might have some S3s laying around somewhere, I'll test those later

@oddlama
Copy link
Author

oddlama commented Jan 30, 2025

I've done some runs now on the C6, here are the results. Unfortunately I didn't encounter the original error again, which was some kind of radio panic. Apparently a very rare one :( - if it happens again, I'll post it here.

Ignoring the runs that panic due to BLE HCI parameters in the beginning, which is about one failure in three tries, there are several different cases I encounter when I start commissioning via my Pixel 9 to Home Assistant.

After thinking about it for a bit, I presume that the main issue is that my networks are separated, which may just be unsupported by matter? I usually have a home network which can use the home assistant web ui, a devices and an iot network which both reach home assistant on a separate VLANs, one with and one without internet access respectively. I usually put my android device into that IoT network before commissioning so that the correct wifi network is passed to the device.

I do encounter some weird issues when I try to use the iot network that is fully isolated from the internet. In that case the device doesn't even try to connect to it, and the process is aborted early (see 1. and 2. below). When I chose the devices network, everything seems to complete properly and the matter server finds it via mDNS, but the device is never actually registered (see 3.). Probably some last communication step to Home Assistant is required which cannot complete because my android cannot reach it in that moment. I tried switching back to the home WiFi on my phone just after the ESP tries to connect to the devices wifi, but the same timeout error occurs.

I hoped the matter commissioning would allow me to pick a wifi network which the device should use, but alas it seems to me like I am doing something which is unsupported. There's probably nothing you can do either, I'm just leaving it here for future reference.

  1. (5x) Phone says "Failed to generate device credentials", using a WiFi network that does not route internet traffic

    ESP log output
    INFO - BLE driver started
    INFO - Running Matter in concurrent commissioning mode (BLE and Wireless)
    INFO - Starting advertising and GATT service
    INFO - GATT address = Address { kind: AddrKind(1), addr: BdAddr([3, 231, 173, 172, 195, 202]) }
    INFO - Running commissioning network only
    INFO - Running Matter transport
    INFO - Waiting for orphaned RX packets
    INFO - Wrapping over
    INFO - Responder memory: Responder=480B, Runner=13624B
    INFO - Responder: Creating 4 handlers
    INFO - Responder: Handlers size: 10312B
    INFO - Busy Responder: Creating 2 handlers
    INFO - Busy Responder: Handlers size: 712B
    INFO - GATT: Advertising
    INFO - Light toggled
    INFO - GATT: Connection established
    INFO - Light toggled
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [H|M|B|E,OP:6c]
    HANDSHAKE REQ HandshakeReq { versions: 4, mtu: 251, window_size: 5 }
    Selected version: 4, MTU: 244, window size: 5
    INFO - Subscribe request from 63:A8:DF:5E:8D:4A
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [H|M|B|E,OP:6c]
    HANDSHAKE RESP HandshakeResp { version: 4, mtu: 244, window_size: 5 }
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:0,CTR:0,LEN:62]
    READ 98B
    INFO - New exchange: 0::0 [SID:0,RSID:0,EID:d5af] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [S,SID:0,CTR:626a8d4,SRC:bb2130aa4cf0927f][I,EID:d5af,PROTO:0,OP:20]
    SC::PBKDFParamRequest
    => Processing (new exchange)
    INFO - Exchange 0::0 [SID:0,RSID:0,EID:d5af]: Accepted
    INFO - Responder: Handler 0 / exchange 0::0: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [U,SID:0,CTR:1317742,DST:bb2130aa4cf0927f][EID:d5af,PROTO:0,OP:21]
    SC::PBKDFParamResponse
    => Sending
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:0,CTR:1,LEN:8b]
    WRITE 139B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:1,CTR:1,LEN:5c]
    READ 92B
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [S,SID:0,CTR:626a8d5,SRC:bb2130aa4cf0927f][I,EID:d5af,PROTO:0,OP:22]
    SC::PASEPake1
    => Processing
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [U,SID:0,CTR:1317743,DST:bb2130aa4cf0927f][EID:d5af,PROTO:0,OP:23]
    SC::PASEPake2
    => Sending
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:1,CTR:2,LEN:7f]
    WRITE 127B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:2,CTR:2,LEN:3b]
    READ 59B
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [S,SID:0,CTR:626a8d6,SRC:bb2130aa4cf0927f][I,EID:d5af,PROTO:0,OP:24]
    SC::PASEPake3
    => Processing
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [U,SID:0,CTR:1317744,DST:bb2130aa4cf0927f][EID:d5af,PROTO:0,OP:40]
    SC::StatusReport
    => Sending
    INFO - Responder: Handler 0 / exchange 0::0: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:2,CTR:3,LEN:1e]
    WRITE 30B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:3,CTR:3,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:7eb9,EID:d5b0] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eab][I,EID:d5b0,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7eb9,EID:d5b0]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767841][EID:d5b0,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:3,CTR:4,LEN:53]
    WRITE 83B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:4,CTR:4,LEN:34]
    READ 52B
    INFO - New exchange: 1::1 [SID:1,RSID:7eb9,EID:d5b1] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eac][I,EID:d5b1,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::1 [SID:1,RSID:7eb9,EID:d5b1]: Accepted
    INFO - Responder: Handler 0 / exchange 1::1: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767842][EID:d5b1,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::1: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:4,CTR:5,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:5,CTR:5,LEN:33]
    READ 51B
    INFO - New exchange: 1::2 [SID:1,RSID:7eb9,EID:d5b2] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947ead][I,EID:d5b2,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::2 [SID:1,RSID:7eb9,EID:d5b2]: Accepted
    INFO - Responder: Handler 0 / exchange 1::2: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767843][EID:d5b2,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::2: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:5,CTR:6,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:6,CTR:6,LEN:33]
    READ 51B
    INFO - New exchange: 1::3 [SID:1,RSID:7eb9,EID:d5b3] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eae][I,EID:d5b3,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::3 [SID:1,RSID:7eb9,EID:d5b3]: Accepted
    INFO - Responder: Handler 0 / exchange 1::3: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767844][EID:d5b3,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::3: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:6,CTR:7,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:7,CTR:7,LEN:33]
    READ 51B
    INFO - New exchange: 1::4 [SID:1,RSID:7eb9,EID:d5b4] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eaf][I,EID:d5b4,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::4 [SID:1,RSID:7eb9,EID:d5b4]: Accepted
    INFO - Responder: Handler 0 / exchange 1::4: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767845][EID:d5b4,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::4: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:7,CTR:8,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:8,CTR:8,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:7eb9,EID:d5b5] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eb0][I,EID:d5b5,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7eb9,EID:d5b5]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767846][EID:d5b5,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:8,CTR:9,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:9,CTR:9,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:7eb9,EID:d5b6] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eb1][I,EID:d5b6,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7eb9,EID:d5b6]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767847][EID:d5b6,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:9,CTR:a,LEN:3f]
    WRITE 63B
    INFO - Light toggled
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A,ACTR:a,CTR:a]
    READ 0B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [B|E,CTR:b,LEN:3e]
    READ 62B
    INFO - New exchange: 1::0 [SID:1,RSID:7eb9,EID:d5b7] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eb2][I,EID:d5b7,PROTO:1,OP:8]
    IM::InvokeRequest
    => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7eb9,EID:d5b7]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - Handling command CertChainRequest
    INFO - Received data: 1: {
    	0: U8(1)
    }
    INFO - Received Cert Type:1
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767848][EID:d5b7,PROTO:1,OP:9]
    IM::InvokeResponse
    => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B,ACTR:b,CTR:b,LEN:229]
    WRITE 239B
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [C,CTR:c]
    WRITE 242B
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [C|E,CTR:d]
    WRITE 72B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:d,CTR:c,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:7eb9,EID:d5b8] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eb3][I,EID:d5b8,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7eb9,EID:d5b8]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:7767849][EID:d5b8,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:c,CTR:e,LEN:53]
    WRITE 83B
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:e,CTR:d,LEN:34]
    READ 52B
    INFO - New exchange: 1::0 [SID:1,RSID:7eb9,EID:d5b9] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 63:A8:DF:5E:8D:4A [SID:1,CTR:1947eb4][I,EID:d5b9,PROTO:1,OP:2]
    IM::ReadRequest
    => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7eb9,EID:d5b9]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 63:A8:DF:5E:8D:4A [SID:7eb9,CTR:776784a][EID:d5b9,PROTO:1,OP:5]
    IM::ReportData
    => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 63:A8:DF:5E:8D:4A [A|B|E,ACTR:d,CTR:f,LEN:40]
    WRITE 64B
    INFO - Light toggled
    INFO - 
    >>>>> (BTP IO) 63:A8:DF:5E:8D:4A [A,ACTR:f,CTR:e]
    READ 0B
    INFO - GATT: Disconnect Err(Remote User Terminated Connection)
    INFO - Unsubscribe request from 63:A8:DF:5E:8D:4A
    INFO - Session 63:A8:DF:5E:8D:4A removed
    INFO - GATT: Task finished
    INFO - GATT: Advertising
    
  2. (2x) Phone says "Something went wrong; Make sure that you are connected to your network and try again", again using a WiFi network that does not route internet traffic. Not sure why it sometimes does this and sometimes does the other thing in (1).

    ESP log output
    INFO - BLE driver started
    INFO - Running Matter in concurrent commissioning mode (BLE and Wireless)
    INFO - Starting advertising and GATT service
    INFO - GATT address = Address { kind: AddrKind(1), addr: BdAddr([108, 75, 99, 251, 141, 108]) }
    INFO - Running commissioning network only
    INFO - Running Matter transport
    INFO - Waiting for orphaned RX packets
    INFO - Wrapping over
    INFO - Responder memory: Responder=480B, Runner=13624B
    INFO - Responder: Creating 4 handlers
    INFO - Responder: Handlers size: 10312B
    INFO - Busy Responder: Creating 2 handlers
    INFO - Busy Responder: Handlers size: 712B
    INFO - GATT: Advertising
    INFO - Light toggled
    INFO - GATT: Connection established
    INFO - Light toggled
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [H|M|B|E,OP:6c]
    HANDSHAKE REQ HandshakeReq { versions: 4, mtu: 251, window_size: 5 }
    Selected version: 4, MTU: 244, window size: 5
    INFO - Subscribe request from 0E:99:18:7F:0B:78
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [H|M|B|E,OP:6c]
    HANDSHAKE RESP HandshakeResp { version: 4, mtu: 244, window_size: 5 }
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:0,CTR:0,LEN:62]
    READ 98B
    INFO - New exchange: 0::0 [SID:0,RSID:0,EID:d5c5] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [S,SID:0,CTR:626a8da,SRC:6743ba9b31cd0cc8][I,EID:d5c5,PROTO:0,OP:20]
    SC::PBKDFParamRequest
     => Processing (new exchange)
    INFO - Exchange 0::0 [SID:0,RSID:0,EID:d5c5]: Accepted
    INFO - Responder: Handler 0 / exchange 0::0: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [U,SID:0,CTR:7b737cd,DST:6743ba9b31cd0cc8][EID:d5c5,PROTO:0,OP:21]
    SC::PBKDFParamResponse
     => Sending
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:0,CTR:1,LEN:8b]
    WRITE 139B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:1,CTR:1,LEN:5c]
    READ 92B
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [S,SID:0,CTR:626a8db,SRC:6743ba9b31cd0cc8][I,EID:d5c5,PROTO:0,OP:22]
    SC::PASEPake1
     => Processing
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [U,SID:0,CTR:7b737ce,DST:6743ba9b31cd0cc8][EID:d5c5,PROTO:0,OP:23]
    SC::PASEPake2
     => Sending
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:1,CTR:2,LEN:7f]
    WRITE 127B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:2,CTR:2,LEN:3b]
    READ 59B
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [S,SID:0,CTR:626a8dc,SRC:6743ba9b31cd0cc8][I,EID:d5c5,PROTO:0,OP:24]
    SC::PASEPake3
     => Processing
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [U,SID:0,CTR:7b737cf,DST:6743ba9b31cd0cc8][EID:d5c5,PROTO:0,OP:40]
    SC::StatusReport
     => Sending
    INFO - Responder: Handler 0 / exchange 0::0: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:2,CTR:3,LEN:1e]
    WRITE 30B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:3,CTR:3,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:7ebb,EID:d5c6] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [SID:1,CTR:2881e03][I,EID:d5c6,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7ebb,EID:d5c6]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [SID:7ebb,CTR:36b519f][EID:d5c6,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:3,CTR:4,LEN:53]
    WRITE 83B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:4,CTR:4,LEN:34]
    READ 52B
    INFO - New exchange: 1::1 [SID:1,RSID:7ebb,EID:d5c7] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [SID:1,CTR:2881e04][I,EID:d5c7,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::1 [SID:1,RSID:7ebb,EID:d5c7]: Accepted
    INFO - Responder: Handler 0 / exchange 1::1: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [SID:7ebb,CTR:36b51a0][EID:d5c7,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::1: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:4,CTR:5,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:5,CTR:5,LEN:33]
    READ 51B
    INFO - New exchange: 1::2 [SID:1,RSID:7ebb,EID:d5c8] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [SID:1,CTR:2881e05][I,EID:d5c8,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::2 [SID:1,RSID:7ebb,EID:d5c8]: Accepted
    INFO - Responder: Handler 0 / exchange 1::2: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [SID:7ebb,CTR:36b51a1][EID:d5c8,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::2: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:5,CTR:6,LEN:40]
    WRITE 64B
    INFO - Light toggled
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:6,CTR:6,LEN:33]
    READ 51B
    INFO - New exchange: 1::3 [SID:1,RSID:7ebb,EID:d5c9] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [SID:1,CTR:2881e06][I,EID:d5c9,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::3 [SID:1,RSID:7ebb,EID:d5c9]: Accepted
    INFO - Responder: Handler 0 / exchange 1::3: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [SID:7ebb,CTR:36b51a2][EID:d5c9,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::3: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:6,CTR:7,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:7,CTR:7,LEN:33]
    READ 51B
    INFO - New exchange: 1::4 [SID:1,RSID:7ebb,EID:d5ca] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [SID:1,CTR:2881e07][I,EID:d5ca,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::4 [SID:1,RSID:7ebb,EID:d5ca]: Accepted
    INFO - Responder: Handler 0 / exchange 1::4: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [SID:7ebb,CTR:36b51a3][EID:d5ca,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::4: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:7,CTR:8,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:8,CTR:8,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:7ebb,EID:d5cb] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [SID:1,CTR:2881e08][I,EID:d5cb,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7ebb,EID:d5cb]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [SID:7ebb,CTR:36b51a4][EID:d5cb,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:8,CTR:9,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:9,CTR:9,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:7ebb,EID:d5cc] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 0E:99:18:7F:0B:78 [SID:1,CTR:2881e09][I,EID:d5cc,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:7ebb,EID:d5cc]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 0E:99:18:7F:0B:78 [SID:7ebb,CTR:36b51a5][EID:d5cc,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 0E:99:18:7F:0B:78 [A|B|E,ACTR:9,CTR:a,LEN:3f]
    WRITE 63B
    INFO - GATT: Disconnect Err(Connection Timeout)
    INFO - Unsubscribe request from 0E:99:18:7F:0B:78
    INFO - Session 0E:99:18:7F:0B:78 removed
    INFO - GATT: Task finished
    INFO - GATT: Advertising
    
  3. (1x) When I use a WiFi network which can reach the internet (everything else is the same!), the phone waits on "Checking network connectivity to MyDevicesNetwork", then says "Can't reach device" after some minutes.

    This looks promising though, the device connects to the wifi network and the matter server finds it. But the Android device probably cannot continue to set it up maybe because Home Assistant's web interface is not reachable from that network. If I try to switch into the correct home network after the ESP has connected to the devices network, the process stays stuck.

    ESP log output
    INFO - BLE driver started
    INFO - Running Matter in concurrent commissioning mode (BLE and Wireless)
    INFO - Starting advertising and GATT service
    INFO - GATT address = Address { kind: AddrKind(1), addr: BdAddr([124, 46, 73, 234, 15, 231]) }
    INFO - Running commissioning network only
    INFO - Running Matter transport
    INFO - Waiting for orphaned RX packets
    INFO - Wrapping over
    INFO - Responder memory: Responder=480B, Runner=13624B
    INFO - Responder: Creating 4 handlers
    INFO - Responder: Handlers size: 10312B
    INFO - Busy Responder: Creating 2 handlers
    INFO - Busy Responder: Handlers size: 712B
    INFO - GATT: Advertising
    INFO - Light toggled
    INFO - Light toggled
    INFO - GATT: Connection established
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [H|M|B|E,OP:6c]
    HANDSHAKE REQ HandshakeReq { versions: 4, mtu: 251, window_size: 5 }
    Selected version: 4, MTU: 244, window size: 5
    INFO - Subscribe request from 35:16:10:83:19:6E
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [H|M|B|E,OP:6c]
    HANDSHAKE RESP HandshakeResp { version: 4, mtu: 244, window_size: 5 }
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:0,CTR:0,LEN:62]
    READ 98B
    INFO - New exchange: 0::0 [SID:0,RSID:0,EID:dd97] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [S,SID:0,CTR:93c8149,SRC:f3a8ab91770fdd5d][I,EID:dd97,PROTO:0,OP:20]
    SC::PBKDFParamRequest
     => Processing (new exchange)
    INFO - Exchange 0::0 [SID:0,RSID:0,EID:dd97]: Accepted
    INFO - Responder: Handler 0 / exchange 0::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [U,SID:0,CTR:1b9876,DST:f3a8ab91770fdd5d][EID:dd97,PROTO:0,OP:21]
    SC::PBKDFParamResponse
     => Sending
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:0,CTR:1,LEN:8b]
    WRITE 139B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:1,CTR:1,LEN:5c]
    READ 92B
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [S,SID:0,CTR:93c814a,SRC:f3a8ab91770fdd5d][I,EID:dd97,PROTO:0,OP:22]
    SC::PASEPake1
     => Processing
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [U,SID:0,CTR:1b9877,DST:f3a8ab91770fdd5d][EID:dd97,PROTO:0,OP:23]
    SC::PASEPake2
     => Sending
    INFO - Light toggled
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:1,CTR:2,LEN:7f]
    WRITE 127B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:2,CTR:2,LEN:3b]
    READ 59B
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [S,SID:0,CTR:93c814b,SRC:f3a8ab91770fdd5d][I,EID:dd97,PROTO:0,OP:24]
    SC::PASEPake3
     => Processing
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [U,SID:0,CTR:1b9878,DST:f3a8ab91770fdd5d][EID:dd97,PROTO:0,OP:40]
    SC::StatusReport
     => Sending
    INFO - Responder: Handler 0 / exchange 0::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:2,CTR:3,LEN:1e]
    WRITE 30B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:3,CTR:3,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dd98] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1e7][I,EID:dd98,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dd98]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a68f][EID:dd98,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:3,CTR:4,LEN:53]
    WRITE 83B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:4,CTR:4,LEN:34]
    READ 52B
    INFO - New exchange: 1::1 [SID:1,RSID:80a5,EID:dd99] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1e8][I,EID:dd99,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::1 [SID:1,RSID:80a5,EID:dd99]: Accepted
    INFO - Responder: Handler 0 / exchange 1::1: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a690][EID:dd99,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::1: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:4,CTR:5,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:5,CTR:5,LEN:33]
    READ 51B
    INFO - New exchange: 1::2 [SID:1,RSID:80a5,EID:dd9a] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1e9][I,EID:dd9a,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::2 [SID:1,RSID:80a5,EID:dd9a]: Accepted
    INFO - Responder: Handler 0 / exchange 1::2: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a691][EID:dd9a,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::2: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:5,CTR:6,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:6,CTR:6,LEN:33]
    READ 51B
    INFO - New exchange: 1::3 [SID:1,RSID:80a5,EID:dd9b] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1ea][I,EID:dd9b,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::3 [SID:1,RSID:80a5,EID:dd9b]: Accepted
    INFO - Responder: Handler 0 / exchange 1::3: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a692][EID:dd9b,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::3: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:6,CTR:7,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:7,CTR:7,LEN:33]
    READ 51B
    INFO - New exchange: 1::4 [SID:1,RSID:80a5,EID:dd9c] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1eb][I,EID:dd9c,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::4 [SID:1,RSID:80a5,EID:dd9c]: Accepted
    INFO - Responder: Handler 0 / exchange 1::4: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a693][EID:dd9c,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::4: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:7,CTR:8,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:8,CTR:8,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dd9d] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1ec][I,EID:dd9d,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dd9d]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a694][EID:dd9d,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:8,CTR:9,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:9,CTR:9,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dd9e] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1ed][I,EID:dd9e,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dd9e]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a695][EID:dd9e,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:9,CTR:a,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:a,CTR:a,LEN:3e]
    READ 62B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dd9f] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1ee][I,EID:dd9f,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dd9f]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - Handling command CertChainRequest
    INFO - Received data: 1: {
        0: U8(1)
    }
    INFO - Received Cert Type:1
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a696][EID:dd9f,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B,ACTR:a,CTR:b,LEN:229]
    WRITE 239B
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [C,CTR:c]
    WRITE 242B
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [C|E,CTR:d]
    WRITE 72B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:d,CTR:b,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda0] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1ef][I,EID:dda0,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda0]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a697][EID:dda0,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:b,CTR:e,LEN:53]
    WRITE 83B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:e,CTR:c,LEN:34]
    READ 52B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda1] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f0][I,EID:dda1,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda1]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a698][EID:dda1,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:c,CTR:f,LEN:40]
    WRITE 64B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:f,CTR:d,LEN:27]
    READ 39B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda2] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f1][I,EID:dda2,PROTO:1,OP:a]
    IM::TimedRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda2]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a699][EID:dda2,PROTO:1,OP:1]
    IM::StatusResponse
     => Sending
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:d,CTR:10,LEN:23]
    WRITE 35B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:10,CTR:e,LEN:41]
    READ 65B
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f2][I,EID:dda2,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing
    INFO - Handling command ARM Fail Safe
    INFO - Received fail safe params: FailSafeParams { expiry_len: 120, bread_crumb: 1 }
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a69a][EID:dda2,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:e,CTR:11,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:11,CTR:f,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda3] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f3][I,EID:dda3,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda3]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a69b][EID:dda3,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:f,CTR:12,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:12,CTR:10,LEN:27]
    READ 39B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda4] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f4][I,EID:dda4,PROTO:1,OP:a]
    IM::TimedRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda4]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a69c][EID:dda4,PROTO:1,OP:1]
    IM::StatusResponse
     => Sending
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:10,CTR:13,LEN:23]
    WRITE 35B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:13,CTR:11,LEN:46]
    READ 70B
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f5][I,EID:dda4,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing
    INFO - Handling command Set Regulatory Config
    INFO - Received reg cfg: RegulatoryConfig { country_code: "DE" }
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a69d][EID:dda4,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:11,CTR:14,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:14,CTR:12,LEN:3e]
    READ 62B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda5] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f6][I,EID:dda5,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda5]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - Handling command CertChainRequest
    INFO - Received data: 1: {
        0: U8(2)
    }
    INFO - Received Cert Type:2
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a69e][EID:dda5,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B,ACTR:12,CTR:15,LEN:20c]
    WRITE 239B
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [C,CTR:16]
    WRITE 242B
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [C|E,CTR:17]
    WRITE 43B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:17,CTR:13,LEN:5e]
    READ 94B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda6] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f7][I,EID:dda6,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda6]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - Handling command AttestationRequest
    INFO - Received Attestation Nonce:Octets([172, 34, 10, 159, 131, 98, 230, 5, 0, 0, 1, 148, 184, 144, 29, 182, 1, 248, 1
    70, 61, 35, 247, 169, 224, 255, 244, 222, 250, 30, 15, 251, 108])
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a69f][EID:dda6,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B,ACTR:13,CTR:18,LEN:2c9]
    WRITE 239B
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [C,CTR:19]
    WRITE 242B
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [C|E,CTR:1a]
    WRITE 232B
    INFO - Light toggled
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:1a,CTR:14,LEN:60]
    READ 96B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda7] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f8][I,EID:dda7,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda7]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - Handling command CSRRequest
    INFO - Received CSR: CsrReq { nonce: Octets([240, 23, 123, 200, 147, 105, 217, 41, 0, 0, 1, 148, 184, 144, 29, 182, 1, 
    248, 170, 61, 35, 183, 168, 249, 185, 146, 77, 140, 238, 182, 37, 208]), for_update_noc: Some(false) }
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a6a0][EID:dda7,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B,ACTR:14,CTR:1b,LEN:175]
    WRITE 239B
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [C|E,CTR:1c]
    WRITE 134B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B,ACTR:1c,CTR:15,LEN:133]
    READ 239B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [C|E,CTR:16]
    READ 68B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda8] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1f9][I,EID:dda8,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda8]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - Handling command AddTrustedRootCert
    INFO - Received Trusted Cert: Octets([15, 30, 1, 1, 1, 24, 2, 1, 37, 3, 27, 14, 6, b4, 5c, 37, 62, 71, 43, 9c, 18, 26, 
    4, 0, 43, 24, 2f, 26, 5, 0, 49, bc, 54, 37, 6, 27, 14, 6, b4, 5c, 37, 62, 71, 43, 9c, 18, 24, 7, 1, 24, 8, 1, 30, 9, 41
    , 4, fa, 66, c4, df, 85, ad, 6f, 4c, 11, 3e, 84, 37, 8e, ed, 8a, 31, 4a, 59, 15, b4, d, 49, 89, 94, a2, ab, b5, 75, c0,
     10, a6, 3a, c8, f2, 5e, 9c, ed, 5c, 65, 6f, d5, 7d, 41, 9a, dd, f5, 56, e9, 99, 2c, 1d, b9, 4d, 47, 32, e6, 35, 4c, a9
    , d0, da, 6f, 5e, 6f, 37, a, 35, 1, 29, 1, 18, 24, 2, 60, 30, 4, 14, 83, 8f, f0, 4f, b5, e9, 51, 1a, 51, 13, 2b, 1a, d9
    , f7, 8e, 59, 91, 1c, a8, d5, 30, 5, 14, 83, 8f, f0, 4f, b5, e9, 51, 1a, 51, 13, 2b, 1a, d9, f7, 8e, 59, 91, 1c, a8, d5
    , 18, 30, b, 40, fd, de, 67, 3c, 6a, ae, 49, 67, 2f, 9, 34, a8, 6a, f7, c8, 28, 7f, 26, 66, 5b, cd, 37, 62, 10, 18, 72,
     9a, 7b, b1, 65, fd, 1a, 38, 36, 88, a, 12, 4a, d9, ce, 9c, 78, b1, 2d, 5c, 29, d3, 3, 48, bb, cc, 4c, f7, 8d, 8b, e, 5
    d, ee, 82, a3, 82, 3c, ec, 1c, 18])
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a6a1][EID:dda8,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:16,CTR:1d,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B,ACTR:1d,CTR:17,LEN:18b]
    READ 239B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [C|E,CTR:18]
    READ 156B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:dda9] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1fa][I,EID:dda9,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:dda9]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - Handling command AddNOC
    INFO - Received NOC as:  Version: [0]
          [2]
     Serial Num: [0, 99, b8, 9, ee, ac, 88, fc, 37]
     Signature Algorithm:
         ECDSA with SHA256
     Issuer:
                 Chip Root CA Id:
                  "9C437162375CB406"
     Validity:
         Not Before: 2025-01-23 0:00:00.0 +00:00:00
         Not After: 2045-01-18 0:00:00.0 +00:00:00
     Subject:
                 Chip Fabric Id:
                  "BF85A46AE11E7CB0"
                 Chip Node Id:
                  "D07ACC410C7F4F5A"
                 Chip NOC CAT Id:
                  "00010001"
                 Common Name:
                  "Android Local Fabric"
         Public Key Algorithm
             ECPubKey
             Prime256v1
         Public-Key: [4, 32, 6, e3, 5a, 9a, 7e, 16, c7, b4, ce, ff, 55, d6, 15, ca, 8, b4, 47, 61, 73, c0, 9e, b3, 1a, 17, 
    e8, 59, fc, dd, c6, ca, b1, d4, a6, 8d, 18, 45, 10, 72, c6, 19, 91, 5a, 3a, 29, f6, 46, 44, 23, e8, 7c, 9b, 48, e0, 15,
     93, 21, 88, a8, b2, ee, cc, 83, c3]
     X509v3 extensions: [3]
             X509v3 Basic Constraints
                 critical: true
                 value:
             X509v3 Key Usage
                 critical: true
                 value:
                     digitalSignature  [80, 0]
             X509v3 Extended Key Usage
                 critical: true
                 value:
                         ClientAuth
                         ServerAuth
             Subject Key ID
                 value:
                      [75, de, 7c, 92, 4c, ca, 9e, d1, 30, 5f, 3, ce, b, 16, 8e, a7, a6, 1c, f2, e4]
             Auth Key ID
                 value:
                         [0][83, 8f, f0, 4f, b5, e9, 51, 1a, 51, 13, 2b, 1a, d9, f7, 8e, 59, 91, 1c, a8, d5]
    Signature: [f0, 92, 7f, 66, e1, e6, a2, b0, fc, 2d, 41, 22, c5, 3f, a9, 4a, 63, b, 81, 3b, ce, 67, 4f, 4f, f5, 0, ea, 3
    5, 98, 75, 19, 24, fc, 8, 53, 87, 9e, 6e, 84, 45, f4, 1d, f4, a4, 81, 2d, 54, 28, e, 7b, b3, 9, 9a, 38, 39, 36, db, c8,
     e6, 9d, 7a, 32, 17, 98]
    
    INFO - mDNS Service name: 45DE821C269E7741-D07ACC410C7F4F5A
    INFO - mDNS service published: 45DE821C269E7741-D07ACC410C7F4F5A::Commissioned
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a6a2][EID:dda9,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:18,CTR:1e,LEN:42]
    WRITE 66B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:1e,CTR:19,LEN:80]
    READ 128B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:ddaa] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1fb][I,EID:ddaa,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:ddaa]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - AddOrUpdateWifiNetwork
    INFO - Added network with ID SSID::Ok("MyDevicesNetwork")
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a6a3][EID:ddaa,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:19,CTR:1f,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:1f,CTR:1a,LEN:33]
    READ 51B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:ddab] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1fc][I,EID:ddab,PROTO:1,OP:2]
    IM::ReadRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:ddab]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a6a4][EID:ddab,PROTO:1,OP:5]
    IM::ReportData
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:1a,CTR:20,LEN:3f]
    WRITE 63B
    INFO - 
    >>>>> (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:20,CTR:1b,LEN:4d]
    READ 77B
    INFO - New exchange: 1::0 [SID:1,RSID:80a5,EID:ddac] :: Responder(AcceptPending)
    INFO - 
    >>>>> BTP 35:16:10:83:19:6E [SID:1,CTR:96bd1fd][I,EID:ddac,PROTO:1,OP:8]
    IM::InvokeRequest
     => Processing (new exchange)
    INFO - Exchange 1::0 [SID:1,RSID:80a5,EID:ddac]: Accepted
    INFO - Responder: Handler 0 / exchange 1::0: Starting
    INFO - ConnectNetwork
    INFO - Request to connect to network with ID MyDevicesNetwork received
    INFO - Wifi connect request for SSID MyDevicesNetwork
    INFO - Wifi configuration updated
    INFO - Wifi started
    INFO - Light toggled
    INFO - Wifi connected
    INFO - Wifi connect complete
    INFO - 
    <<<<< BTP 35:16:10:83:19:6E [SID:80a5,CTR:fb5a6a5][EID:ddac,PROTO:1,OP:9]
    IM::InvokeResponse
     => Sending
    INFO - Responder: Handler 0 / exchange 1::0: Completed
    INFO - 
    <<<<< (BTP IO) 35:16:10:83:19:6E [A|B|E,ACTR:1b,CTR:21,LEN:3f]
    WRITE 63B
    WARN - Giving BLE/BTP extra 4 seconds for any outstanding messages before switching to the operational network
    INFO - Light toggled
    INFO - Trying with requested network first - ID: SSID::Ok("MyDevicesNetwork")
    INFO - Connecting to network with ID SSID::Ok("MyDevicesNetwork")
    INFO - Wifi connect request for SSID MyDevicesNetwork
    INFO - Wifi stopped
    INFO - Wifi configuration updated
    INFO - Wifi started
    INFO - GATT: Disconnect Err(Remote User Terminated Connection)
    INFO - Unsubscribe request from 35:16:10:83:19:6E
    INFO - Session 35:16:10:83:19:6E removed
    INFO - GATT: Task finished
    INFO - GATT: Advertising
    INFO - Wifi connected
    INFO - Wifi connect complete
    INFO - Connected to network with ID SSID::Ok("MyDevicesNetwork")
    INFO - Light toggled
    INFO - IP network change detected
    INFO - Netif up: IPv4: 192.168.20.29, IPv6: fe80::424c:caff:fe50:912c, Interface: 0, MAC: 40:4C:CA:50:91:2C
    INFO - Running operational and extra networks
    INFO - Running Matter transport
    INFO - Waiting for orphaned RX packets
    INFO - Running Matter built-in mDNS service
    INFO - Broadcasting mDNS entry to 224.0.0.251:5353
    INFO - Broadcasting mDNS entry to [ff02::fb]:5353
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Broadcasting mDNS entry to 224.0.0.251:5353
    INFO - Broadcasting mDNS entry to [ff02::fb]:5353
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Broadcasting mDNS entry to 224.0.0.251:5353
    INFO - Broadcasting mDNS entry to [ff02::fb]:5353
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Light toggled
    INFO - Broadcasting mDNS entry to 224.0.0.251:5353
    INFO - Broadcasting mDNS entry to [ff02::fb]:5353
    

    The python-matter-server finds the device, but no attempt is made to connect to it. Only one log line is printed in debug mode:

    Jan 30 20:00:36 myhost matter-server[307247]: 2025-01-30 20:00:36.708 (MainThread) DEBUG [matter_server.server.device_controller.mdns] Discovered commissionable Matter node: AsyncServiceInfo(type='_matterc._udp.local.', name='481778A2894EA8E8._matterc._udp.local.', addresses=[b'\xc0\xa8\x14\x1d'], port=5540, weight=0, priority=0, server='404CCA50912C.local.', properties={}, interface_index=None)
    

@ivmarkov
Copy link
Owner

Thank you for your feedback. I think we should push it until it works for you.

Digression:

First of all, your LAN setup w.r.t. Home Assistant is not unique. I have the exact same setup for my own HA installation:

  • A VLAN which does not have internet at all (actually limited to just one external IP) (my home Paradox alarm sits here, as this thing has the nasty habbit of pinging its home server to work, but I disallow all other IPs)
  • A VLAN which does have outgoing internet (my Wifi switches sit there; they need internet to update its firmware; also security cams are here though not strictly necessary for them)
  • A "main" VLAN for the TVs, computers and other non-IOT stuff.

HA is multi-homed and is present in all 3 VLANs.
With that said, I do not really have HA as a "Matter server", as I don't have (yet) Matter-compatible devices. What might be interesting is to have a HA-to-Matter bridge, which allows you to control all non-Matter devices registered in HA with a Matter Controller, like Google Home etc. There is a JS plugin for that for HA, but I'm developing my own Rust-based one which - if things go well - might even have the chance to get certified and so on.

===

Onto your issues:

(5x) Phone says "Failed to generate device credentials", using a WiFi network that does not route internet traffic
(2x) Phone says "Something went wrong; Make sure that you are connected to your network and try again", again using a WiFi network that does not route internet traffic. Not sure why it sometimes does this and sometimes does the other thing in (1).

(
Matter per-se does not need internet traffic at all. In fact, the ESP Matter device cannot even contact the Internet, as - over IPv6 - it only listens on a link-local IPv6 IP (I still allow it to get an IPv4 address as well, but this is only so that it can broadcast mDNS over IPv4 as well, and if the Matter controller contacts it over Ipv4 - Google Home sometimes does that if it can't really ping it via ipv6, it can answer over ipv4. But support for Matter-over-ipv4 is completely optional. It should all work with ipv6 only over link-local ipv6.
)

With that said, it could be that your phone during commissioning needs Internet (for whatever reasons?). What app do you use on your phone for commissioning to HA?

(1x) When I use a WiFi network which can reach the internet (everything else is the same!), the phone waits on "Checking network connectivity to MyDevicesNetwork", then says "Can't reach device" after some minutes.

This must work, but I just tested with esp32c6 and rs-matter-embassy specifically, and I must say it does not work for me either!
(It does work with esp32c6 + esp-idf-svc-master + esp-idf-matter).

I think this is a problem with the Wifi BLOB + esp32c6 on baremetal (it works for me with all other esps!).
I think the problem is multicast traffic simply does not reach the device. In the log we are completely missing the "mDNS reply to ..." messages, which means mDNS traffic does not reach the device.

I'll try to figure out what is going on with mDNS and esp32c6.

@ivmarkov
Copy link
Owner

UPDATE:

I'm pretty sure now the problem is not simply with multicast traffic on the esp32c6 but with ALL IP traffic on the esp32c6 when BLE is also active. I left the device running after the provisioning failed for me (it got 192.168.10.100 from DHCP) and observe:

ivan@ivan-laptop:~$ ping 192.168.10.100
PING 192.168.10.100 (192.168.10.100) 56(84) bytes of data.
From 192.168.10.84 icmp_seq=1 Destination Host Unreachable
From 192.168.10.84 icmp_seq=2 Destination Host Unreachable
From 192.168.10.84 icmp_seq=5 Destination Host Unreachable
From 192.168.10.84 icmp_seq=8 Destination Host Unreachable
From 192.168.10.84 icmp_seq=9 Destination Host Unreachable
From 192.168.10.84 icmp_seq=11 Destination Host Unreachable
From 192.168.10.84 icmp_seq=12 Destination Host Unreachable
From 192.168.10.84 icmp_seq=13 Destination Host Unreachable
ping: sendmsg: No route to host
From 192.168.10.84 icmp_seq=14 Destination Host Unreachable
From 192.168.10.84 icmp_seq=15 Destination Host Unreachable
From 192.168.10.84 icmp_seq=17 Destination Host Unreachable
64 bytes from 192.168.10.100: icmp_seq=110 ttl=64 time=164 ms
64 bytes from 192.168.10.100: icmp_seq=118 ttl=64 time=3776 ms
64 bytes from 192.168.10.100: icmp_seq=119 ttl=64 time=2753 ms
64 bytes from 192.168.10.100: icmp_seq=120 ttl=64 time=1733 ms
64 bytes from 192.168.10.100: icmp_seq=121 ttl=64 time=717 ms
64 bytes from 192.168.10.100: icmp_seq=127 ttl=64 time=3688 ms
From 192.168.10.84 icmp_seq=575 Destination Host Unreachable
From 192.168.10.84 icmp_seq=576 Destination Host Unreachable
From 192.168.10.84 icmp_seq=577 Destination Host Unreachable
From 192.168.10.84 icmp_seq=578 Destination Host Unreachable
From 192.168.10.84 icmp_seq=579 Destination Host Unreachable
ping: sendmsg: No route to host
From 192.168.10.84 icmp_seq=580 Destination Host Unreachable
From 192.168.10.84 icmp_seq=581 Destination Host Unreachable
From 192.168.10.84 icmp_seq=583 Destination Host Unreachable
From 192.168.10.84 icmp_seq=584 Destination Host Unreachable
From 192.168.10.84 icmp_seq=585 Destination Host Unreachable
From 192.168.10.84 icmp_seq=586 Destination Host Unreachable

It is simply not reachable most of the time, on an IP level.

@bjoernQ: Once I have a smaller repro case, I'll open a bug at esp-wifi.

@bjoernQ
Copy link

bjoernQ commented Jan 31, 2025

@bjoernQ: Once I have a smaller repro case, I'll open a bug at esp-wifi.

@ivmarkov Probably you don't need to create a reproducer - seems like the wifi_coex example in the esp-hal repo is enough. Interestingly it works quite well on ESP32-C3 and ESP32-S3 - maybe it's C6 specific or happening for the Nimble based drivers. (To check that I need to resolder the USB connector on my C2 dev-board - I broke that by plugging in a cable a bit too enthusiastically)

@ivmarkov
Copy link
Owner

You mean, you already reproduced it on the c6 with coex enabled, and now want to test on the c2 as well?

@bjoernQ
Copy link

bjoernQ commented Jan 31, 2025

Yes it's easily reproducible on C6 - I would like to know if it's a general issue with newer chips (which use a Nimble based BLE driver - currently we have C2 and C6 here). But anyways you can just create an issue for esp-hal (or I can do it - whatever is more convenient to you)

@bjoernQ
Copy link

bjoernQ commented Jan 31, 2025

Ok - I was able to run the example on C2 while pressing down and holding the USB-connector in a special way ... works fine so C6 is the only affected chip. I will create an issue for this and link it here

@bjoernQ
Copy link

bjoernQ commented Jan 31, 2025

Here is the issue in esp-hal: esp-rs/esp-hal#3079

@ivmarkov
Copy link
Owner

@oddlama I just pushed a power-boosting fix to rs-matter-embassy.
Whenever you have time, perhaps you could do cargo update and then a rebuild?
I'm relatively sure, that the provisioning process would then complete for you on the c6.

@oddlama
Copy link
Author

oddlama commented Jan 31, 2025

@ivmarkov Indeed, thank you very much! It works great when I am in my devices network, in the end I just have to switch back to my home wifi on my phone and wait a bit for the home assistant app to recognize that the connectivity has been restored, then I can add the matter device and complete the setup!

When I try with the non-internet connected IoT network, it still fails when generating the device credentials, but I presume this is linked to the esp-wifi issue above?

@ivmarkov
Copy link
Owner

When I try with the non-internet connected IoT network, it still fails when generating the device credentials, but I presume this is linked to the esp-wifi issue above?

No, the esp-wifi issue fixed it so that you can have successful provisioning now (on the internet-enabled network). As I said before, you probably need an internet-enabled network because:

With that said, it could be that your phone during commissioning needs Internet (for whatever reasons?). What app do you use on your phone for commissioning to HA?

@oddlama
Copy link
Author

oddlama commented Jan 31, 2025

With that said, it could be that your phone during commissioning needs Internet (for whatever reasons?). What app do you use on your phone for commissioning to HA?

Oh sorry, I missed that. I'm using the default app on my device which is the google play services app, it let's me choose whether I want to commission against google home (which I don't have) or another app where I can select HA. But who knows what google is doing there exactly, I'll definitely try another app for commissioning.

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