search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.42k stars 1.99k forks source link

Python chip-device-ctl crashing - DnssdImpl.cpp:333: CHIP Error 0x00000003: Incorrect state #17937

Closed agners closed 1 year ago

agners commented 2 years ago

Problem

Followed the guide at docs/guides/python_chip_controller_building.md (using Debian 11 instead of Debian 10, since at least Python 3.8 seems to be required nowadays) to build the Python CHIP Controller.

I am building in a Container. I tried running the container with and without --privileged, same result. I also have similar issues on my native host (Arch Linux).

However, Python CHIP Controller seems to crash on startup:

root@250d4a1f1b45:/connectedhomeip# source ./out/python_env/bin/activate  
(python_env) root@250d4a1f1b45:/connectedhomeip# out/python_env/bin/chip-device-ctrl
[1651312624.601623][10:10] CHIP:CTL: Setting attestation nonce to random value
[1651312624.601677][10:10] CHIP:CTL: Setting CSR nonce to random value
[1651312624.603666][10:10] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-pzAnAX)
[1651312624.603746][10:10] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1651312624.603759][10:10] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1651312624.603860][10:10] CHIP:DL: Got Ethernet interface: eth0
[1651312624.603885][10:10] CHIP:DL: Found the primary Ethernet interface:eth0
[1651312624.603917][10:10] CHIP:DL: Failed to get WiFi interface
[1651312624.603920][10:10] CHIP:DL: Failed to reset WiFi statistic counts
[1651312624.603974][10:15] CHIP:DL: Platform main loop started.
2022-04-30 09:57:04 250d4a1f1b45 root[10] CRITICAL Loading configuration from /tmp/chip-device-ctrl-storage.json...
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetSdkKey: g/gcc = b'\xb8\x0b\x00\x00'
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetSdkKey: g/gdc = b'\xb8\x0b\x00\x00'
2022-04-30 09:57:04 250d4a1f1b45 chip.ZCL[10] INFO Using ZAP configuration...
2022-04-30 09:57:04 250d4a1f1b45 chip.DL[10] INFO Avahi connecting
2022-04-30 09:57:04 250d4a1f1b45 chip.IN[10] INFO CASE Server enabling CASE session setups
2022-04-30 09:57:04 250d4a1f1b45 chip.DIS[10] INFO Updating services using commissioning mode 0
2022-04-30 09:57:04 250d4a1f1b45 chip.DIS[10] ERROR Failed to initialize advertiser: ../../src/platform/Linux/DnssdImpl.cpp:333: CHIP Error 0x00000003: Incorrect state
2022-04-30 09:57:04 250d4a1f1b45 chip.DIS[10] INFO Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15
2022-04-30 09:57:04 250d4a1f1b45 chip.DIS[10] ERROR Failed to advertise commissioner: ../../src/lib/dnssd/Discovery_ImplPlatform.cpp:479: CHIP Error 0x00000003: Incorrect state
2022-04-30 09:57:04 250d4a1f1b45 chip.DIS[10] INFO Delaying proxy of operational discovery: missing delegate
New FabricAdmin: FabricId: 1(1)
2022-04-30 09:57:04 250d4a1f1b45 chip.CTL[10] INFO Couldn't get ExampleOpCredsCAKey from storage: ../../src/controller/python/ChipDeviceController-StorageDelegate.cpp:97: CHIP Error 0x000000A0: Value not found in the persisted storage
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetSdkKey: ExampleOpCredsCAKey1 = b"\x04M\xe9\xca\xf7\x0f\x9f\xa1\x81\xc2\xf9\xcd\xa9P\xbf}X\xf8\x06\xe8\x9b\xc9\xe5\x95\x91%\x04\x93~\xa4\x16\x97\x05\xd5fF\x88x\xba'\xbb;\xed)y\xc6[\x11\xc2b\x8fK|\xa1\xf2\xac\x087\xe75\xde\x98\xc9\x03\x7f\x8enI\xa9YQ!\xf0\x11\rd\x91\xd1\xf9\xc8\xdb\x85fI\xbb\xbf\xe1\xc5\x7f\x0e\xd8\x1fw\x1d\x9f@'"
2022-04-30 09:57:04 250d4a1f1b45 chip.CTL[10] INFO Couldn't get ExampleOpCredsICAKey from storage: ../../src/controller/python/ChipDeviceController-StorageDelegate.cpp:97: CHIP Error 0x000000A0: Value not found in the persisted storage
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetSdkKey: ExampleOpCredsICAKey1 = b'\x04Vfqe>\xe9:\x16\x9b\xe7\xb9\xe53m3\x83\xfdPQ\\~\xaai\xef\x10\xa2\xd6\xc4Ga\x8aCH\x1e\x0f\x94}\x8a\x8e\xf8\xeb\x84\xb6\x83;\xa6a\x98Dx\x8ad\xab\x91\x102\xa8\x9c\x9b\xdb]\xab\x18\x0c\x02t[\xcd\xbd\x8eF\xa8.\x08~\xbeE\xee\x8bV\x90;V\x1c\xba\xa5\xbe&K\x1a\xa5\xdd[\xe8\xdd}'
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetReplKey: fabricAdmins = {'1': {'fabricId': 1}}
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetReplKey: fabricAdmins = {'1': {'fabricId': 1}}
Allocating new controller with FabricId: 1(1), NodeId: 1
2022-04-30 09:57:04 250d4a1f1b45 chip.CTL[10] INFO Setting attestation nonce to random value
2022-04-30 09:57:04 250d4a1f1b45 chip.CTL[10] INFO Setting CSR nonce to random value
2022-04-30 09:57:04 250d4a1f1b45 chip.CTL[10] INFO Generating RCAC
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetSdkKey: ExampleCARootCert1 = b'0\x82\x01\x970\x82\x01<\xa0\x03\x02\x01\x02\x02\x01\x000\n\x06\x08*\x86H\xce=\x04\x03\x020"1 0\x1e\x06\n+\x06\x01\x04\x01\x82\xa2|\x01\x04\x0c\x1000000000000000000\x1e\x17\r210101000000Z\x17\r301230000000Z0"1 0\x1e\x06\n+\x06\x01\x04\x01\x82\xa2|\x01\x04\x0c\x1000000000000000000Y0\x13\x06\x07*\x86H\xce=\x02\x01\x06\x08*\x86H\xce=\x03\x01\x07\x03B\x00\x04M\xe9\xca\xf7\x0f\x9f\xa1\x81\xc2\xf9\xcd\xa9P\xbf}X\xf8\x06\xe8\x9b\xc9\xe5\x95\x91%\x04\x93~\xa4\x16\x97\x05\xd5fF\x88x\xba\'\xbb;\xed)y\xc6[\x11\xc2b\x8fK|\xa1\xf2\xac\x087\xe75\xde\x98\xc9\x03\x7f\xa3c0a0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\x0e\x06\x03U\x1d\x0f\x01\x01\xff\x04\x04\x03\x02\x01\x060\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14\xc0\xa2;\x949\x16\xce5\xae\xfa\xfa\xd3\x08\x88H\x93\xd5\xbb\xffs0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14\xc0\xa2;\x949\x16\xce5\xae\xfa\xfa\xd3\x08\x88H\x93\xd5\xbb\xffs0\n\x06\x08*\x86H\xce=\x04\x03\x02\x03I\x000F\x02!\x00\xccm\xb0\xd7Go\xa0\xf8\x1f\xd3\xf4QlR\x10\xeeb\x0e\x9a\xefK8\x1f~\x82\xb6\xf68\xc9\x01~\xf5\x02!\x00\xf7\x85\x8e;5\x86\x1a\xfa\xf6\xd0\xf4\x19\xf7RS\xfb\x17^&<\x13\x8f\x86s\xa0\xd2\xb3s\xb7u\t\x8c'
2022-04-30 09:57:04 250d4a1f1b45 chip.CTL[10] INFO Generating ICAC
2022-04-30 09:57:04 250d4a1f1b45 root[10] INFO SetSdkKey: ExampleCAIntermediateCert1 = b'0\x82\x01\x970\x82\x01<\xa0\x03\x02\x01\x02\x02\x01\x000\n\x06\x08*\x86H\xce=\x04\x03\x020"1 0\x1e\x06\n+\x06\x01\x04\x01\x82\xa2|\x01\x04\x0c\x1000000000000000000\x1e\x17\r210101000000Z\x17\r301230000000Z0"1 0\x1e\x06\n+\x06\x01\x04\x01\x82\xa2|\x01\x03\x0c\x1000000000000000010Y0\x13\x06\x07*\x86H\xce=\x02\x01\x06\x08*\x86H\xce=\x03\x01\x07\x03B\x00\x04Vfqe>\xe9:\x16\x9b\xe7\xb9\xe53m3\x83\xfdPQ\\~\xaai\xef\x10\xa2\xd6\xc4Ga\x8aCH\x1e\x0f\x94}\x8a\x8e\xf8\xeb\x84\xb6\x83;\xa6a\x98Dx\x8ad\xab\x91\x102\xa8\x9c\x9b\xdb]\xab\x18\x0c\xa3c0a0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\x0e\x06\x03U\x1d\x0f\x01\x01\xff\x04\x04\x03\x02\x01\x060\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14{\xb7/\xca\xbd\x08*y\xd4\x8c\xec-rg@\x96\xc9\x16\xaf\xae0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14\xc0\xa2;\x949\x16\xce5\xae\xfa\xfa\xd3\x08\x88H\x93\xd5\xbb\xffs0\n\x06\x08*\x86H\xce=\x04\x03\x02\x03I\x000F\x02!\x00\x86[\xd6#\xf5xO\xb7N\xea\xef\xbe\x9e\x8a\xb6\xab\xc9?\n%\x11{g\xdd\xe7\x81Vg\xdf\xb9D\xc0\x02!\x00\xe3\xb1H\x98\xe9\x14\x1c\x0c\x98c%\xc6IN\xad\x18\x95\xdd\x9e\xf7\xcb\xd8\xd9{\x03\xe4\x10(\x87\xb9\x15\x08'
2022-04-30 09:57:04 250d4a1f1b45 chip.CTL[10] INFO Generating NOC
CHIP Error 0x00000003: Incorrect state
Failed to bringup CHIPDeviceController CLI
Exception ignored in: <function ChipDeviceController.__del__ at 0x7fb6ca95e5e0>
Traceback (most recent call last):
  File "/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/ChipDeviceCtrl.py", line 188, in __del__
    self.Shutdown()
  File "/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/ChipDeviceCtrl.py", line 152, in Shutdown
    if (self.isActive):
AttributeError: 'ChipDeviceController' object has no attribute 'isActive'
Segmentation fault (core dumped)

It seems that the Discovery Platform/DNSSD/AVAHI initialization is the culprit: RROR Failed to initialize advertiser: ../../src/platform/Linux/DnssdImpl.cpp:333: CHIP Error 0x00000003: Incorrect state

It seems the system tries to initialize the advertizer twice, the first time from src/controller/CHIPDeviceControllerFactory.cpp:176:

    (this=0x7ffff40b0200 <chip::Dnssd::MdnsAvahi::sInstance>, initCallback=0x7ffff3e1aaf2 <chip::Dnssd::DiscoveryImplPlatform::HandleDnssdInit(void*, chip::ChipError)>, errorCallback=0x7ffff3e1ac80 <chip::Dnssd::DiscoveryImplPlatform::HandleDnssdError(void*, chip::ChipError)>, context=0x7ffff40aca00 <chip::Dnssd::DiscoveryImplPlatform::sManager>) at ../../src/platform/Linux/DnssdImpl.cpp:327
#1  0x00007ffff3f56a88 in chip::Dnssd::ChipDnssdInit(void (*)(void*, chip::ChipError), void (*)(void*, chip::ChipError), void*)
    (initCallback=0x7ffff3e1aaf2 <chip::Dnssd::DiscoveryImplPlatform::HandleDnssdInit(void*, chip::ChipError)>, errorCallback=0x7ffff3e1ac80 <chip::Dnssd::DiscoveryImplPlatform::HandleDnssdError(void*, chip::ChipError)>, context=0x7ffff40aca00 <chip::Dnssd::DiscoveryImplPlatform::sManager>) at ../../src/platform/Linux/DnssdImpl.cpp:822
#2  0x00007ffff3e1aa07 in chip::Dnssd::DiscoveryImplPlatform::InitImpl() (this=0x7ffff40aca00 <chip::Dnssd::DiscoveryImplPlatform::sManager>) at ../../src/lib/dnssd/Discovery_ImplPlatform.cpp:345
#3  0x00007ffff3e18e20 in chip::Dnssd::DiscoveryImplPlatform::Init(chip::Inet::EndPointManager<chip::Inet::UDPEndPoint>*) (this=0x7ffff40aca00 <chip::Dnssd::DiscoveryImplPlatform::sManager>) at ../../src/lib/dnssd/Discovery_ImplPlatform.h:40
#4  0x00007ffff3debda3 in chip::Controller::DeviceControllerFactory::InitSystemState(chip::Controller::FactoryInitParams) (this=0x7ffff40aaa00 <chip::Controller::DeviceControllerFactory::GetInstance()::instance>, params=...) at ../../src/controller/CHIPDeviceControllerFactory.cpp:176
#5  0x00007ffff3deb43d in chip::Controller::DeviceControllerFactory::Init(chip::Controller::FactoryInitParams) (this=0x7ffff40aaa00 <chip::Controller::DeviceControllerFactory::GetInstance()::instance>, params=...) at ../../src/controller/CHIPDeviceControllerFactory.cpp:65
#6  0x00007ffff3cd9fa7 in pychip_DeviceController_StackInit() () at ../../src/controller/python/ChipDeviceController-ScriptBinding.cpp:232

The second time via src/controller/CHIPDeviceControllerFactory.cpp:210.

(gdb) bt
#0  0x00007ffff3ca61e0 in chip::Dnssd::MdnsAvahi::Init(void (*)(void*, chip::ChipError), void (*)(void*, chip::ChipError), void*)@plt () at /home/sag/projects/project-chip/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/_ChipDeviceCtrl.so
#1  0x00007ffff3f56a88 in chip::Dnssd::ChipDnssdInit(void (*)(void*, chip::ChipError), void (*)(void*, chip::ChipError), void*)
    (initCallback=0x7ffff3e1aaf2 <chip::Dnssd::DiscoveryImplPlatform::HandleDnssdInit(void*, chip::ChipError)>, errorCallback=0x7ffff3e1ac80 <chip::Dnssd::DiscoveryImplPlatform::HandleDnssdError(void*, chip::ChipError)>, context=0x7ffff40aca00 <chip::Dnssd::DiscoveryImplPlatform::sManager>) at ../../src/platform/Linux/DnssdImpl.cpp:822
#2  0x00007ffff3e1aa07 in chip::Dnssd::DiscoveryImplPlatform::InitImpl() (this=0x7ffff40aca00 <chip::Dnssd::DiscoveryImplPlatform::sManager>) at ../../src/lib/dnssd/Discovery_ImplPlatform.cpp:345
#3  0x00007ffff3e18e20 in chip::Dnssd::DiscoveryImplPlatform::Init(chip::Inet::EndPointManager<chip::Inet::UDPEndPoint>*) (this=0x7ffff40aca00 <chip::Dnssd::DiscoveryImplPlatform::sManager>) at ../../src/lib/dnssd/Discovery_ImplPlatform.h:40
#4  0x00007ffff4010fff in chip::app::DnssdServer::StartServer(chip::Dnssd::CommissioningMode) (this=0x7ffff40ac980 <chip::app::DnssdServer::Instance()::instance>, mode=chip::Dnssd::CommissioningMode::kDisabled) at ../../src/app/server/Dnssd.cpp:443
#5  0x00007ffff4010f65 in chip::app::DnssdServer::StartServer() (this=0x7ffff40ac980 <chip::app::DnssdServer::Instance()::instance>) at ../../src/app/server/Dnssd.cpp:432
#6  0x00007ffff3debee1 in chip::Controller::DeviceControllerFactory::InitSystemState(chip::Controller::FactoryInitParams) (this=0x7ffff40aaa00 <chip::Controller::DeviceControllerFactory::GetInstance()::instance>, params=...) at ../../src/controller/CHIPDeviceControllerFactory.cpp:210
#7  0x00007ffff3deb43d in chip::Controller::DeviceControllerFactory::Init(chip::Controller::FactoryInitParams) (this=0x7ffff40aaa00 <chip::Controller::DeviceControllerFactory::GetInstance()::instance>, params=...) at ../../src/controller/CHIPDeviceControllerFactory.cpp:65
#8  0x00007ffff3cd9fa7 in pychip_DeviceController_StackInit() () at ../../src/controller/python/ChipDeviceController-ScriptBinding.cpp:232

Proposed Solution

agners commented 2 years ago

Crash using ArchLinux with Python 3.9

2022-04-30 10:44:54 allenwind chip.ZCL[256359] INFO Using ZAP configuration...
2022-04-30 10:44:54 allenwind chip.DL[256359] INFO Avahi re-register required
2022-04-30 10:44:54 allenwind chip.IN[256359] INFO CASE Server enabling CASE session setups
2022-04-30 10:44:54 allenwind chip.DIS[256359] INFO Updating services using commissioning mode 0
2022-04-30 10:44:54 allenwind chip.DIS[256359] ERROR Failed to initialize advertiser: ../../src/platform/Linux/DnssdImpl.cpp:333: CHIP Error 0x00000003: Incorrect state
2022-04-30 10:44:54 allenwind chip.DIS[256359] INFO Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15
2022-04-30 10:44:54 allenwind chip.DIS[256359] ERROR Failed to advertise commissioner: ../../src/lib/dnssd/Discovery_ImplPlatform.cpp:479: CHIP Error 0x00000003: Incorrect state
2022-04-30 10:44:54 allenwind chip.DIS[256359] INFO Delaying proxy of operational discovery: missing delegate
New FabricAdmin: FabricId: 1(1)
2022-04-30 10:44:54 allenwind root[256359] INFO SetReplKey: fabricAdmins = {'1': {'fabricId': 1}}
name 'path' is not defined
Failed to bringup CHIPDeviceController CLI
Exception ignored in: <function FabricAdmin.__del__ at 0x7ff94681cee0>
Traceback (most recent call last):
  File "/home/sag/projects/project-chip/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/FabricAdmin.py", line 209, in __del__
    self.Shutdown(False)
  File "/home/sag/projects/project-chip/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/FabricAdmin.py", line 188, in Shutdown
    if (self._isActive):
AttributeError: 'FabricAdmin' object has no attribute '_isActive'
[1]    256358 segmentation fault  sudo out/python_env/bin/chip-device-ctrl
agners commented 2 years ago

It seems that the minimal mDNS implementation works much better, e.g. using

scripts/build_python.sh -m minimal

instead of

scripts/build_python.sh -m platform

Is the platform mDNS implementation (Avahi in Linux' case) not supported anymore?

stale[bot] commented 1 year ago

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

stale[bot] commented 1 year ago

This stale issue has been automatically closed. Thank you for your contributions.

Firesuiry commented 1 year ago

same problem