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.

Sign up for GitHub

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

Jump to bottom

Commissioning fails on Linux #16

Open
bewee-i opened this issue Sep 12, 2022 · 7 comments
Open

Commissioning fails on Linux #16

bewee-i opened this issue Sep 12, 2022 · 7 comments

Comments

@bewee-i
Copy link

bewee-i commented Sep 12, 2022

Hi all!
I really appreciate your work on this crate; The functionality that is already implemented looks quite promising to me!
Unfortunately, I was not yet able to commission the example as described in the README because the CHIP tool crashes. Here is an extract of the log:

[1662967379.124620][23231:23237] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:10578812 on exchange 33111i
[1662967379.124623][23231:23237] CHIP:EM: Found matching exchange: 33111i, Delegate: 0x7fed2800c860
[1662967379.124626][23231:23237] CHIP:EM: Rxd Ack; Removing MessageCounter:223883550 from Retrans Table on exchange 33111i
[1662967379.124628][23231:23237] CHIP:EM: Removed CHIP MessageCounter:223883550 from RetransTable on exchange 33111i
[1662967379.124634][23231:23237] CHIP:SC: Received error (protocol code 2) during PASE process: ../Projects/connectedhomeip/examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:756: CHIP Error 0x00000038: Invalid PASE parameter
[1662967379.124637][23231:23237] CHIP:IN: SecureSession[0x7fed2800a0e0]: Released - Type:1 LSID:28137
[1662967379.124641][23231:23237] CHIP:SC: Failed during PASE session setup: ../Projects/connectedhomeip/examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:756: CHIP Error 0x00000038: Invalid PASE parameter
[1662967379.124644][23231:23237] CHIP:TOO: Secure Pairing Failed
[1662967379.124654][23231:23237] CHIP:TOO: Pairing Failure: ../Projects/connectedhomeip/examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:756: CHIP Error 0x00000038: Invalid PASE parameter
[1662967379.124657][23231:23237] CHIP:EM: Sending Standalone Ack for MessageCounter:10578812 on exchange 33111i
[1662967379.124662][23231:23237] CHIP:IN: Prepared unauthenticated message 0x7fed3e255fd0 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 33111i with MessageCounter:223883551.
[1662967379.124668][23231:23237] CHIP:IN: Sending unauthenticated msg 0x7fed3e255fd0 with MessageCounter:223883551 to 0x0000000000000000 at monotonic time: 0000000000495F84 msec
[1662967379.124696][23231:23237] CHIP:EM: Flushed pending ack for MessageCounter:10578812 on exchange 33111i
[1662967379.124778][23231:23231] CHIP:CTL: Shutting down the commissioner
[1662967379.124794][23231:23231] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662967379.124830][23231:23231] CHIP:CTL: Shutting down the controller
[1662967379.124838][23231:23231] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1662967379.124845][23231:23231] CHIP:FP: Forgetting fabric 0x1
[1662967379.124856][23231:23231] CHIP:TS: Pending Last Known Good Time: 2022-09-06T15:14:17
[1662967379.124921][23231:23231] CHIP:TS: Previous Last Known Good Time: 2022-09-06T15:14:17
[1662967379.124928][23231:23231] CHIP:TS: Reverted Last Known Good Time to previous value
[1662967379.124945][23231:23231] CHIP:CTL: Shutting down the commissioner
[1662967379.124950][23231:23231] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662967379.124968][23231:23231] CHIP:CTL: Shutting down the controller
[1662967379.124973][23231:23231] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1662967379.125221][23231:23231] CHIP:DMG: IM WH moving to [Uninitialized]
[1662967379.125228][23231:23231] CHIP:DMG: IM WH moving to [Uninitialized]
[1662967379.125233][23231:23231] CHIP:DMG: IM WH moving to [Uninitialized]
[1662967379.125239][23231:23231] CHIP:DMG: IM WH moving to [Uninitialized]
[1662967379.125246][23231:23231] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1662967379.125263][23231:23231] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1662967379.125345][23231:23231] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-6rOj5p)
[1662967379.127292][23231:23231] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1662967379.127299][23231:23231] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1662967379.127302][23231:23231] CHIP:DL: Inet Layer shutdown
[1662967379.127304][23231:23231] CHIP:DL: BLE shutdown
[1662967379.127307][23231:23231] CHIP:DL: System Layer shutdown
[1662967379.127316][23231:23231] CHIP:TOO: Run command failure: ../Projects/connectedhomeip/examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:756: CHIP Error 0x00000038: Invalid PASE parameter

The Rust example itself logs two error messages:

[2022-09-12T07:22:53Z ERROR matter::sys::sys_linux] Linux is not yet supported for MDNS Service

[2022-09-12T07:22:59Z ERROR matter::secure_channel::core] PASE Not enabled

From briefly looking at the code, I assume that you are working on MacOS? I am on Ubuntu 22.04, so this may be part of the problem. For testing purpose, I added an MDNS implementation for sys_publish_service() to sys/sys_linux.rs. However, the second error remained, so I suppose this is the actual problem. Could you give me some hints?

Thanks four your help!
Regards :)
@kedars
Copy link
Owner

kedars commented Sep 12, 2022 •
edited
Loading

Ah, could you also share the full rust side logs from Linux?

@kedars
Copy link
Owner

kedars commented Sep 12, 2022

I think what is likely happening is that commissioning worked for you once (after you fixed the mDNS). But then once commissioning has happened matter-rs persistently stored a record of it, and hence the next time the commissioning is not enabled (hence PASE is disabled).

  • You could either try using the control commands from chip-tool, since both sides have persistently stored information about the successful commissioning
  • Try deleting the /tmp/plonk_psm directory on Linux, which is where the matter-rs persistently stores information, and then relaunch the matter server

@bewee-i
Copy link
Author

bewee-i commented Sep 12, 2022

Thank you for your quick reply! This actually did the trick. I have succesfully commissioned the device and toggled the onoff state.

However, there are still some quirks. First off, my sys_publish_service() implementation based on the mdns_sd crate did not do the job (I don't really know why, but it's not such a nice option anyways since it only supports IPv4). Instead, I ended up installing libavahi-compat-libdnssd-dev and basically copied the MacOS implementation. However, this always resulted in a RegistrationError::ServiceError(0), which I imagine should be an Ok state and which I thus treated so. Interestingly, this was already sufficient to make it work. Unfortunately, with this hack, we are not able to gain access to the RegisteredDnsService object. If my theory about the ServiceError(0) sounds reasonable to you, I can create an issue in the astro-dnssd crate.
One final side note: I have to wait a few seconds after cargo running before performing the commissioning, or I will end up with the following error. Is this different on MacOS?

[2022-09-12T13:45:16Z INFO  matter::transport::session] Received from src: [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:16Z INFO  matter::transport::plain_hdr] [decode] flags: SRC_ADDR_PRESENT, session type: None, sess_id: 0, ctr: 86287484
[2022-09-12T13:45:16Z INFO  matter::transport::session] Creating new session
[2022-09-12T13:45:16Z INFO  matter::transport::proto_hdr] [decode] ExId: 27974, Proto: 0, Opcode: 32, Flags: R|I|
[2022-09-12T13:45:16Z INFO  matter::transport::exchange] Creating new exchange
[2022-09-12T13:45:16Z DEBUG matter::transport::mgr] Exchange is Exchange { id: 27974, sess_idx: 0, role: Responder, state: Open, data: None, mrp: ReliableMessage { retrans: None, ack: Some(AckEntry { msg_ctr: 86287484, ack_timeout: Sys
temTime { tv_sec: 1662990316, tv_nsec: 597661544 } }) } }
[2022-09-12T13:45:16Z INFO  matter::secure_channel::core] In PBKDF Param Request Handler
[2022-09-12T13:45:16Z INFO  matter::transport::exchange] Sending with proto id: 0 opcode: 33
[2022-09-12T13:45:16Z INFO  matter::transport::proto_hdr] [encode] ExId: 27974, Proto: 0, Opcode: 33, Flags: R|A|
Message Sent to [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:16Z INFO  matter::transport::mgr] Exchange Mgr: {  Session Mgr: {[
    { peer: [::ffff:192.168.178.24]:56740
    , peer_nodeid: Some(16523851297399427681), local: 0, remote: 0, msg_ctr: 31518809, mode: PlainText, ts: SystemTime { tv_sec: 1662990316, tv_nsec: 397715582 }, },
    ], next_sess_id: 2},
      Exchanges: [
    { exch_id: 27974, sess_index: 0, role: Responder, data: None, mrp: ReliableMessage { retrans: Some(RetransEntry { msg_ctr: 31518808 }), ack: None }, state: Open, },
      ]
    }
[2022-09-12T13:45:16Z INFO  matter::transport::session] Received from src: [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:16Z INFO  matter::transport::plain_hdr] [decode] flags: SRC_ADDR_PRESENT, session type: None, sess_id: 0, ctr: 86287484
[2022-09-12T13:45:16Z INFO  matter::transport::proto_hdr] [decode] ExId: 27974, Proto: 0, Opcode: 32, Flags: R|I|
[2022-09-12T13:45:16Z DEBUG matter::transport::mgr] Exchange is Exchange { id: 27974, sess_idx: 0, role: Responder, state: Open, data: None, mrp: ReliableMessage { retrans: Some(RetransEntry { msg_ctr: 31518808 }), ack: Some(AckEntry {
 msg_ctr: 86287484, ack_timeout: SystemTime { tv_sec: 1662990316, tv_nsec: 597839429 } }) } }
[2022-09-12T13:45:16Z INFO  matter::secure_channel::core] In PBKDF Param Request Handler
[2022-09-12T13:45:16Z INFO  matter::secure_channel::pake] Previous session in-progress, denying new request
[2022-09-12T13:45:16Z INFO  matter::transport::exchange] Sending with proto id: 0 opcode: 64
[2022-09-12T13:45:16Z ERROR matter::transport::mrp] Previous retrans entry for this exchange already exists
[2022-09-12T13:45:16Z ERROR matter::transport::mgr] Error in sending msg Invalid
[2022-09-12T13:45:16Z ERROR matter::transport::mgr] Error in handle_rxtx
[2022-09-12T13:45:16Z INFO  matter::transport::session] Received from src: [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:16Z INFO  matter::transport::plain_hdr] [decode] flags: SRC_ADDR_PRESENT, session type: None, sess_id: 0, ctr: 86287485
[2022-09-12T13:45:16Z INFO  matter::transport::proto_hdr] [decode] ExId: 27974, Proto: 0, Opcode: 34, Flags: R|A|I|
[2022-09-12T13:45:16Z DEBUG matter::transport::mgr] Exchange is Exchange { id: 27974, sess_idx: 0, role: Responder, state: Open, data: None, mrp: ReliableMessage { retrans: None, ack: Some(AckEntry { msg_ctr: 86287485, ack_timeout: Sys
temTime { tv_sec: 1662990316, tv_nsec: 602460524 } }) } }
[2022-09-12T13:45:16Z INFO  matter::secure_channel::core] In PASE Pake1 Handler
[2022-09-12T13:45:16Z ERROR matter::transport::mgr] Error in proto_demux InvalidSignature
[2022-09-12T13:45:16Z ERROR matter::transport::mgr] Error in handle_rxtx
[2022-09-12T13:45:16Z INFO  matter::transport::session] Received from src: [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:16Z INFO  matter::transport::plain_hdr] [decode] flags: SRC_ADDR_PRESENT, session type: None, sess_id: 0, ctr: 86287485
[2022-09-12T13:45:16Z INFO  matter::transport::proto_hdr] [decode] ExId: 27974, Proto: 0, Opcode: 34, Flags: R|A|I|
[2022-09-12T13:45:16Z ERROR matter::transport::mrp] Previous ACK entry for this exchange already exists
[2022-09-12T13:45:16Z ERROR matter::transport::mgr] Error in recv: Invalid
[2022-09-12T13:45:16Z ERROR matter::transport::mgr] Error in handle_rxtx
[2022-09-12T13:45:17Z INFO  matter::transport::session] Received from src: [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:17Z INFO  matter::transport::plain_hdr] [decode] flags: SRC_ADDR_PRESENT, session type: None, sess_id: 0, ctr: 86287485
[2022-09-12T13:45:17Z INFO  matter::transport::proto_hdr] [decode] ExId: 27974, Proto: 0, Opcode: 34, Flags: R|A|I|
[2022-09-12T13:45:17Z ERROR matter::transport::mrp] Previous ACK entry for this exchange already exists
[2022-09-12T13:45:17Z ERROR matter::transport::mgr] Error in recv: Invalid
[2022-09-12T13:45:17Z ERROR matter::transport::mgr] Error in handle_rxtx
[2022-09-12T13:45:17Z INFO  matter::transport::session] Received from src: [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:17Z INFO  matter::transport::plain_hdr] [decode] flags: SRC_ADDR_PRESENT, session type: None, sess_id: 0, ctr: 86287485
[2022-09-12T13:45:17Z INFO  matter::transport::proto_hdr] [decode] ExId: 27974, Proto: 0, Opcode: 34, Flags: R|A|I|
[2022-09-12T13:45:17Z ERROR matter::transport::mrp] Previous ACK entry for this exchange already exists
[2022-09-12T13:45:17Z ERROR matter::transport::mgr] Error in recv: Invalid
[2022-09-12T13:45:17Z ERROR matter::transport::mgr] Error in handle_rxtx
[2022-09-12T13:45:18Z INFO  matter::transport::session] Received from src: [::ffff:192.168.178.24]:56740

[2022-09-12T13:45:18Z INFO  matter::transport::plain_hdr] [decode] flags: SRC_ADDR_PRESENT, session type: None, sess_id: 0, ctr: 86287485
[2022-09-12T13:45:18Z INFO  matter::transport::proto_hdr] [decode] ExId: 27974, Proto: 0, Opcode: 34, Flags: R|A|I|
[2022-09-12T13:45:18Z ERROR matter::transport::mrp] Previous ACK entry for this exchange already exists
[2022-09-12T13:45:18Z ERROR matter::transport::mgr] Error in recv: Invalid
[2022-09-12T13:45:18Z ERROR matter::transport::mgr] Error in handle_rxtx

[1662990308.284262][99161:99161] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1662990308.285457][99161:99161] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1662990308.285486][99161:99161] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1662990308.285497][99161:99161] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1662990308.285548][99161:99161] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-rmX3km)
[1662990308.285664][99161:99161] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1662990308.285669][99161:99161] CHIP:DL: NVS set: chip-counters/reboot-count = 84 (0x54)
[1662990308.285939][99161:99161] CHIP:DL: Got Ethernet interface: enp11s0
[1662990308.286084][99161:99161] CHIP:DL: Found the primary Ethernet interface:enp11s0
[1662990308.286243][99161:99161] CHIP:DL: Got WiFi interface: wlp9s0
[1662990308.286702][99161:99161] CHIP:DL: Found the primary WiFi interface:wlp9s0
[1662990308.286718][99161:99161] CHIP:IN: UDP::Init bind&listen port=0
[1662990308.286732][99161:99161] CHIP:IN: UDP::Init bound to port=51726
[1662990308.286734][99161:99161] CHIP:IN: UDP::Init bind&listen port=0
[1662990308.286740][99161:99161] CHIP:IN: UDP::Init bound to port=56740
[1662990308.286742][99161:99161] CHIP:IN: BLEBase::Init - setting/overriding transport
[1662990308.286743][99161:99161] CHIP:IN: TransportMgr initialized
[1662990308.286749][99161:99161] CHIP:FP: Initializing FabricTable from persistent storage
[1662990308.286772][99161:99161] CHIP:TS: Last Known Good Time: 2022-09-12T11:06:50
[1662990308.287045][99161:99161] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xCF158BD9346FE8FF, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1662990308.287252][99161:99161] CHIP:ZCL: Using ZAP configuration...
[1662990308.287418][99161:99161] CHIP:DL: MDNS failed to join multicast group on enp11s0 for address type IPv4: ../../third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:758: Inet Error 0x00000110: Address not found
[1662990308.287784][99161:99161] CHIP:DL: MDNS failed to join multicast group on enx00e04c68ed22 for address type IPv4: ../../third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:758: Inet Error 0x00000110: Address not found
[1662990308.287805][99161:99161] CHIP:CTL: System State Initialized...
[1662990308.287814][99161:99161] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662990308.287824][99161:99161] CHIP:CTL: Setting attestation nonce to random value
[1662990308.287830][99161:99161] CHIP:CTL: Setting CSR nonce to random value
[1662990308.287838][99161:99161] CHIP:IN: UDP::Init bind&listen port=5550
[1662990308.287845][99161:99161] CHIP:IN: UDP::Init bound to port=5550
[1662990308.287848][99161:99161] CHIP:IN: UDP::Init bind&listen port=5550
[1662990308.287853][99161:99161] CHIP:IN: UDP::Init bound to port=5550
[1662990308.287854][99161:99161] CHIP:IN: TransportMgr initialized
[1662990308.287890][99161:99166] CHIP:DL: CHIP task running
[1662990308.287934][99161:99166] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662990308.287940][99161:99166] CHIP:CTL: Setting attestation nonce to random value
[1662990308.287960][99161:99166] CHIP:CTL: Setting CSR nonce to random value
[1662990308.288136][99161:99166] CHIP:CTL: Generating NOC
[1662990308.288303][99161:99166] CHIP:FP: Validating NOC chain
[1662990308.288593][99161:99166] CHIP:FP: NOC chain validation successful
[1662990308.288618][99161:99166] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1662990308.288622][99161:99166] CHIP:TS: Last Known Good Time: 2022-09-12T11:06:50
[1662990308.288623][99161:99166] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1662990308.288624][99161:99166] CHIP:TS: Retaining current Last Known Good Time
[1662990308.289089][99161:99166] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1662990308.289248][99161:99166] CHIP:TS: Committing Last Known Good Time to storage: 2022-09-12T11:06:50
[1662990308.289396][99161:99166] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1662990308.289401][99161:99166] CHIP:IN: UDP::Init bind&listen port=5550
[1662990308.289411][99161:99166] CHIP:IN: UDP::Init bound to port=5550
[1662990308.289413][99161:99166] CHIP:IN: UDP::Init bind&listen port=5550
[1662990308.289420][99161:99166] CHIP:IN: UDP::Init bound to port=5550
[1662990308.289422][99161:99166] CHIP:IN: TransportMgr initialized
[1662990308.290627][99161:99166] CHIP:IN: SecureSession[0x7f52c000a460]: Allocated Type:1 LSID:53180
[1662990308.290632][99161:99166] CHIP:SC: Assigned local session key ID 53180
[1662990308.290642][99161:99166] CHIP:SC: Including MRP parameters in PBKDF param request
[1662990308.290652][99161:99166] CHIP:IN: Prepared unauthenticated message 0x55a297a0c5a8 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 27974i with MessageCounter:86287484.
[1662990308.290657][99161:99166] CHIP:IN: Sending unauthenticated msg 0x55a297a0c5a8 with MessageCounter:86287484 to 0x0000000000000000 at monotonic time: 0000000001A73E92 msec
[1662990308.290711][99161:99166] CHIP:SC: Sent PBKDF param request
[1662990308.290715][99161:99166] CHIP:CTL: Setting attestation nonce to random value
[1662990308.290718][99161:99166] CHIP:CTL: Setting CSR nonce to random value
[1662990308.290722][99161:99166] CHIP:CTL: Commission called for node ID 0x0000000000BC5C01
[1662990313.197467][99161:99166] CHIP:EM: Retransmitting MessageCounter:86287484 on exchange 27974i Send Cnt 1
[1662990313.197546][99161:99166] CHIP:IN: Sending unauthenticated msg 0x55a297a0c5a8 with MessageCounter:86287484 to 0x0000000000000000 at monotonic time: 0000000001A751BD msec
[1662990316.397920][99161:99166] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:31518808 on exchange 27974i
[1662990316.397950][99161:99166] CHIP:EM: Found matching exchange: 27974i, Delegate: 0x7f52c000ccc0
[1662990316.397966][99161:99166] CHIP:EM: Rxd Ack; Removing MessageCounter:86287484 from Retrans Table on exchange 27974i
[1662990316.397971][99161:99166] CHIP:EM: Removed CHIP MessageCounter:86287484 from RetransTable on exchange 27974i
[1662990316.397983][99161:99166] CHIP:SC: Received PBKDF param response
[1662990316.397997][99161:99166] CHIP:SC: Peer assigned session ID 1
[1662990316.402280][99161:99166] CHIP:EM: Piggybacking Ack for MessageCounter:31518808 on exchange: 27974i
[1662990316.402299][99161:99166] CHIP:IN: Prepared unauthenticated message 0x7f52c0009e28 to 0x0000000000000000 (0)  of type 0x22 and protocolId (0, 0) on exchange 27974i with MessageCounter:86287485.
[1662990316.402312][99161:99166] CHIP:IN: Sending unauthenticated msg 0x7f52c0009e28 with MessageCounter:86287485 to 0x0000000000000000 at monotonic time: 0000000001A75E42 msec
[1662990316.402407][99161:99166] CHIP:SC: Sent spake2p msg1
[1662990316.735927][99161:99166] CHIP:EM: Retransmitting MessageCounter:86287485 on exchange 27974i Send Cnt 1
[1662990316.735995][99161:99166] CHIP:IN: Sending unauthenticated msg 0x7f52c0009e28 with MessageCounter:86287485 to 0x0000000000000000 at monotonic time: 0000000001A75F8F msec
[1662990317.138635][99161:99166] CHIP:EM: Retransmitting MessageCounter:86287485 on exchange 27974i Send Cnt 2
[1662990317.138700][99161:99166] CHIP:IN: Sending unauthenticated msg 0x7f52c0009e28 with MessageCounter:86287485 to 0x0000000000000000 at monotonic time: 0000000001A76122 msec
[1662990317.772590][99161:99166] CHIP:EM: Retransmitting MessageCounter:86287485 on exchange 27974i Send Cnt 3
[1662990317.772660][99161:99166] CHIP:IN: Sending unauthenticated msg 0x7f52c0009e28 with MessageCounter:86287485 to 0x0000000000000000 at monotonic time: 0000000001A7639C msec
[1662990318.827299][99161:99166] CHIP:EM: Retransmitting MessageCounter:86287485 on exchange 27974i Send Cnt 4
[1662990318.827368][99161:99166] CHIP:IN: Sending unauthenticated msg 0x7f52c0009e28 with MessageCounter:86287485 to 0x0000000000000000 at monotonic time: 0000000001A767BB msec
[1662990320.437207][99161:99166] CHIP:EM: Failed to Send CHIP MessageCounter:86287485 on exchange 27974i sendCount: 4 max retries: 4
[1662990366.408509][99161:99166] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 35
[1662990366.408574][99161:99166] CHIP:IN: SecureSession[0x7f52c000a460]: Released - Type:1 LSID:53180
[1662990366.408587][99161:99166] CHIP:TOO: Secure Pairing Failed
[1662990366.408637][99161:99166] CHIP:TOO: Pairing Failure: ../../third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout
[1662990366.408855][99161:99161] CHIP:CTL: Shutting down the commissioner
[1662990366.408883][99161:99161] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662990366.408947][99161:99161] CHIP:CTL: Shutting down the controller
[1662990366.408957][99161:99161] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1662990366.408967][99161:99161] CHIP:FP: Forgetting fabric 0x1
[1662990366.408983][99161:99161] CHIP:TS: Pending Last Known Good Time: 2022-09-12T11:06:50
[1662990366.409060][99161:99161] CHIP:TS: Previous Last Known Good Time: 2022-09-12T11:06:50
[1662990366.409066][99161:99161] CHIP:TS: Reverted Last Known Good Time to previous value
[1662990366.409091][99161:99161] CHIP:CTL: Shutting down the commissioner
[1662990366.409095][99161:99161] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662990366.409115][99161:99161] CHIP:CTL: Shutting down the controller
[1662990366.409120][99161:99161] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1662990366.409504][99161:99161] CHIP:DMG: IM WH moving to [Uninitialized]
[1662990366.409516][99161:99161] CHIP:DMG: IM WH moving to [Uninitialized]
[1662990366.409528][99161:99161] CHIP:DMG: IM WH moving to [Uninitialized]
[1662990366.409534][99161:99161] CHIP:DMG: IM WH moving to [Uninitialized]
[1662990366.409543][99161:99161] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1662990366.409577][99161:99161] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1662990366.409800][99161:99161] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jjTc3U)
[1662990366.410086][99161:99161] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1662990366.410108][99161:99161] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1662990366.410115][99161:99161] CHIP:DL: Inet Layer shutdown
[1662990366.410120][99161:99161] CHIP:DL: BLE shutdown
[1662990366.410125][99161:99161] CHIP:DL: System Layer shutdown
[1662990366.410152][99161:99161] CHIP:TOO: Run command failure: ../../third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout

@kedars
Copy link
Owner

kedars commented Sep 13, 2022

I have to wait a few seconds after cargo running before performing the commissioning

I haven't noticed this problem on the Mac, I usually switch the terminal and run the commissioning command, but let me keep trying.

From the logs, what it looks like is that the PBKDFResponse from Plonk takes longer to reach the chip-tool and hence it triggers a retransmission (chip-tool timestamps: 1662990308.290657 and 1662990313.197467). This retransmission probably is causing the state machine to end up in a weird state. I will create a separate issue to track this.

@kedars kedars mentioned this issue Sep 13, 2022
Open
@kedars
Copy link
Owner

kedars commented Sep 13, 2022

Unfortunately, with this hack, we are not able to gain access to the RegisteredDnsService object. If my theory about the ServiceError(0) sounds reasonable to you, I can create an issue in the astro-dnssd crate.

I am not too familiar with astro_dnssd, but is it likely that this condition gets hit during the execution on Linux?
https://github.com/AstroHQ/astro-dnssd/blob/develop/src/os/apple/register.rs#L211

@bewee-i
Copy link
Author

bewee-i commented Sep 13, 2022

Unfortunately, with this hack, we are not able to gain access to the RegisteredDnsService object. If my theory about the ServiceError(0) sounds reasonable to you, I can create an issue in the astro-dnssd crate.

I am not too familiar with astro_dnssd, but is it likely that this condition gets hit during the execution on Linux? https://github.com/AstroHQ/astro-dnssd/blob/develop/src/os/apple/register.rs#L211

Sounds reasonable to me.

Anyway, I don't really feel like this avahi apple compatibility layer is really the way to go, with this warning being presented on every run:

*** WARNING *** The program 'onoff_light' uses the Apple Bonjour compatibility layer of Avahi.
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>

I therefore experimented with the libmdns crate instead. This works quite well for commissioning, but fails to perform correctly when toggling the onoff state. I am rather clueless here, but will quickly open a PR and also put the respective error messages in there.

@bewee-i bewee-i mentioned this issue Sep 13, 2022
Open
@angelybo
Copy link

angelybo commented Jan 20, 2023 •
edited
Loading

Unfortunately, with this hack, we are not able to gain access to the RegisteredDnsService object. If my theory about the ServiceError(0) sounds reasonable to you, I can create an issue in the astro-dnssd crate.

I am not too familiar with astro_dnssd, but is it likely that this condition gets hit during the execution on Linux? https://github.com/AstroHQ/astro-dnssd/blob/develop/src/os/apple/register.rs#L211

Sounds reasonable to me.

Anyway, I don't really feel like this avahi apple compatibility layer is really the way to go, with this warning being presented on every run:

*** WARNING *** The program 'onoff_light' uses the Apple Bonjour compatibility layer of Avahi.
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>

I therefore experimented with the libmdns crate instead. This works quite well for commissioning, but fails to perform correctly when toggling the onoff state. I am rather clueless here, but will quickly open a PR and also put the respective error messages in there.

Hi, I've been experimenting with your implementation of #18

Edit: libmdns seems to have an issue - when received a query for All, it doesn't actually return all records and the client is confused. Not sure if this is a thing in the spec or something else.
Might want a different mdns implementation.

Also, would you mind opening this PR on this repo: https://github.com/project-chip/matter-rs ?
Seems that one is under active development now.

kedars added a commit that referenced this issue Feb 8, 2023
@kedars
Merge pull request #16 from angelybo/comapre-attr
89d9737 
Derive PartialOrd for AttrValue so we can compare them directly
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@kedars @bewee-i @angelybo