ZHA - CRC error in frame b'1111556ea1ad87dc7e' (b'87dc' != b'fc23')

Tamas-Toth-ebola commented 4 years ago

The problem

Dear All!

I'm using a Bitronvideo - USB Zigbee gateway, and while I'm a little bit new in Zigbee basically after some failed try I got it working without any problem. After upgraded to HA Core 0.105 or 0.106 (sadly do not remember exactly) I started to get the following error in the logs. I don't know anything about the error but as the integration seemed working I patiently waited for the next and next version of HA Core. Meanwhile I tried to test my system with a hot fresh and steril HA just to check if I have any problematic integration or configuration but my HA Core throw this error also in case of totally empty /config dir with brand new configuration of HA. As the 'problem' still available this is why I drop my report here. Currently using the latest 0.107.1 version but with the last X major and minor versions gave me the same result as I wrote.

Sometime in the last some weeks I changed the Zigbee channel with bellows from the default 15 to 19, but did not do any other things with the Zigbee configuration.

Could anybody check it or verify it? Or could I write any other details to catch the problem?

Log Details (ERROR)

Logger: bellows.uart
Source: /usr/local/lib/python3.7/site-packages/bellows/uart.py:83
First occurred: 9:57:20 AM (1 occurrences)
Last logged: 9:57:20 AM

CRC error in frame b'1111556ea1ad87dc7e' (b'87dc' != b'fc23')

Thanks for your help in advance,

Environment

Home Assistant release with the issue: 0.107.1
Last working Home Assistant release (if known): ~ 0.104 - 0.105
Operating environment (Hass.io/Docker/Windows/etc.): Docker on Ubuntu ~~19.04~~ 19.10
Integration causing this issue: ZHA
Link to integration documentation on our website: https://www.home-assistant.io/integrations/zha/

Problem-relevant `configuration.yaml`

Traceback/Error logs

Log Details (ERROR)

Logger: bellows.uart
Source: /usr/local/lib/python3.7/site-packages/bellows/uart.py:83
First occurred: 9:57:20 AM (1 occurrences)
Last logged: 9:57:20 AM

CRC error in frame b'1111556ea1ad87dc7e' (b'87dc' != b'fc23')

Additional information

probot-home-assistant[bot] commented 4 years ago

Hey there @dmulcahey, @adminiuga, mind taking a look at this issue as its been labeled with a integration (zha) you are listed as a codeowner for? Thanks!

Adminiuga commented 4 years ago

per UART-EZSP protocol reference the CRC is calculated as per

A 16-bit CRC is computed on all bytes in a frame preceding the CRC, excluding bytes added by byte stuffing. The standard CRCCCITT (g(x) = x16 + x12 + x5 + 1) is initialized to 0xFFFF. The most significant byte precedes the least significant byte (big-endian mode)

per https://crccalc.com/ the CRC16 for 1111556ea1ad is 0xFC23 which is different from the frame supplied CRC of 0x87dc so it does look like bellows calculates the CRC correctly and application behaves as designed by rejecting the frames with wrong CRC.

I have no ideas why Bitron throws bad crc frames occasianally. but judging by the number of occurences, all other frames had the correct checksum, so while you get that error, it does not happen for every frame you ~~send~~ receive, does it?

Tamas-Toth-ebola commented 4 years ago

Hi @Adminiuga !

Thanks for your fast response, explanation. My setup just a test setup yet, with very slow development as I did not really trust in Z-wave and Zigbee in practice before I started some experiments with them. I just write this for you as there is no continuous usage of the system.

(HASS had just installed on our main NUC machine in our home until I could finish all the ironing of any possible problems and I just later will migrate one dedicated RPi.)

Please give me some more time in the coming weekend I will deep test the situation and I could answer for your 'frequency of problem' question.

Currently I just get the error altogether once per HASS start, but basically strictly after the container start without any discrete Zigbee activity made by me (seems as at some initialization process).

So please give me some time, tomorrow, or a day later I will write my test results about real usage with my Philips Hue lamp and it's Dimmer switch.

Thanks again for your efforts!

Tamas-Toth-ebola commented 4 years ago

Hello!

As I promised on the weekend I made some tests, butz sadly not with really accurate results:( Seems bellows drop the mentioned (or something like that) CRC error randomly or at least for me they were uncatchable.

What is sure that there is no continuous errors, just as you sai: occasionally.

I paired my Philips Hue lamp and it's own Hue Dimmer with the following results:

Hue Lamp

[0x0000](EZSP): started initialization
[0x0000:ZDO](EZSP): 'async_initialize' stage succeeded
[0x0000](EZSP): power source: Mains
[0x0000](EZSP): completed initialization
Device 0x2a39 (00:17:88:01:04:fb:bd:0e) joined the network
[0x2a39:zdo] ZDO request 0x0013: [0x2a39, 00:17:88:01:04:fb:bd:0e, 142]
[0x2a39] Requesting 'Node Descriptor'
[0x2a39] Extending timeout for 0x03 request
[0x2a39] Node Descriptor: <Optional byte1=1 byte2=64 mac_capability_flags=142 manufacturer_code=4107 maximum_buffer_size=71 maximum_incoming_transfer_size=45 server_mask=0 maximum_outgoing_transfer_size=45 descriptor_capability_field=0>
[0x2a39] Discovering endpoints
[0x2a39] Discovered endpoints: [11, 242]
[0x2a39:11] Discovering endpoint information
[0x2a39:11] Discovered endpoint information: <SimpleDescriptor endpoint=11 profile=49246 device_type=544 device_version=2 input_clusters=[0, 3, 4, 5, 6, 8, 768, 4096] output_clusters=[25]>
[0x2a39:11:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=9 command_id=Command.Read_Attributes_rsp>
[0x2a39:11] Manufacturer: Philips
[0x2a39:11] Model: LTC002
[0x2a39:242] Discovering endpoint information
[0x2a39:242] Discovered endpoint information: <SimpleDescriptor endpoint=242 profile=41440 device_type=97 device_version=0 input_clusters=[33] output_clusters=[33]>
Checking quirks for Philips LTC002 (00:17:88:01:04:fb:bd:0e)
Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
Fail because endpoint list mismatch: {1} {242, 11}
Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
Fail because endpoint list mismatch: {11, 13} {242, 11}
Considering <class 'zhaquirks.lutron.lzl4bwhl01remote.LutronLZL4BWHL01Remote2'>
Fail because endpoint list mismatch: {1} {242, 11}
Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
Fail because endpoint list mismatch: {1} {242, 11}
Considering <class 'zhaquirks.osram.a19twhite.A19TunableWhite'>
Fail because endpoint list mismatch: {3} {242, 11}
Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'>
Fail because endpoint list mismatch: {1} {242, 11}
Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
Fail because endpoint list mismatch: {1, 2} {242, 11}
Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'>
Fail because endpoint list mismatch: {1} {242, 11}
Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'>
Fail because endpoint list mismatch: {1} {242, 11}
Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'>
Fail because endpoint list mismatch: {232, 230} {242, 11}
Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'>
Fail because endpoint list mismatch: {232, 230} {242, 11}
Considering <class 'zhaquirks.xiaomi.mija.smoke.MijiaHoneywellSmokeDetectorSensor'>
Fail because endpoint list mismatch: {1} {242, 11}
device - 0x2a39:00:17:88:01:04:fb:bd:0e entering async_device_initialized - is_new_join: True
device - 0x2a39:00:17:88:01:04:fb:bd:0e has joined the ZHA zigbee network
[0x2a39](LTC002): started configuration
[0x2a39:ZDO](LTC002): 'async_configure' stage succeeded
[0x2a39:11:0x0006]: bound 'on_off' cluster: Status.SUCCESS
[0x2a39:11:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=15 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0300]: initializing channel: from_cache: False
[0x2a39:11:0x0008]: bound 'level' cluster: Status.TABLE_FULL
[0x2a39:11:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=19 command_id=Command.Configure_Reporting_rsp>
[0x2a39:11:0x0006]: reporting 'on_off' attr on 'on_off' cluster: 0/900/1: Result: '[[<ConfigureReportingResponseRecord status=Status.UNREPORTABLE_ATTRIBUTE direction=0 attrid=0>]]'
[0x2a39:11:0x0006]: finished channel configuration
[0x2a39:11:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=21 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=23 command_id=Command.Configure_Reporting_rsp>
[0x2a39:11:0x0008]: reporting 'current_level' attr on 'level' cluster: 1/900/1: Result: '[[<ConfigureReportingResponseRecord status=Status.UNREPORTABLE_ATTRIBUTE direction=0 attrid=0>]]'
[0x2a39:11:0x0008]: finished channel configuration
[0x2a39:11:0x1000]: bound 'lightlink' cluster: Status.TABLE_FULL
[0x2a39:11:0x1000]: finished channel configuration
[0x2a39:11:0x0300]: bound 'light_color' cluster: Status.TABLE_FULL
[0x2a39:11:0x0000]: bound 'basic' cluster: Status.TABLE_FULL
[0x2a39:11:0x0000]: finished channel configuration
[0x2a39:11:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=31 command_id=Command.Configure_Reporting_rsp>
[0x2a39:11:0x0300]: reporting 'current_x' attr on 'light_color' cluster: 30/900/1: Result: '[[<ConfigureReportingResponseRecord status=Status.UNREPORTABLE_ATTRIBUTE direction=0 attrid=3>]]'
[0x2a39:11:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=33 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0000]: initializing channel: from_cache: False
[0x2a39:11:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=35 command_id=Command.Configure_Reporting_rsp>
[0x2a39:11:0x0300]: reporting 'current_y' attr on 'light_color' cluster: 30/900/1: Result: '[[<ConfigureReportingResponseRecord status=Status.UNREPORTABLE_ATTRIBUTE direction=0 attrid=4>]]'
[0x2a39:11:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=37 command_id=Command.Configure_Reporting_rsp>
[0x2a39:11:0x0300]: reporting 'color_temperature' attr on 'light_color' cluster: 30/900/1: Result: '[[<ConfigureReportingResponseRecord status=Status.UNREPORTABLE_ATTRIBUTE direction=0 attrid=7>]]'
[0x2a39:11:0x0300]: finished channel configuration
[0x2a39:11:0x0006]: 'async_configure' stage succeeded
[0x2a39:11:0x0300]: 'async_configure' stage succeeded
[0x2a39:11:0x0008]: 'async_configure' stage succeeded
[0x2a39:11:0x1000]: 'async_configure' stage succeeded
[0x2a39:11:0x0000]: 'async_configure' stage succeeded
[0x2a39](LTC002): completed configuration
[0x2a39](LTC002): stored in registry: ZhaDeviceEntry(name='Philips LTC002', ieee='00:17:88:01:04:fb:bd:0e', last_seen=1584728827.0015786)
[0x2a39:11:0x0003] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=39 command_id=Command.Default_Response>
[0x2a39:11:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.SUCCESS: 0>]
[0x2a39](LTC002): started initialization
[0x2a39:ZDO](LTC002): 'async_initialize' stage succeeded
[0x2a39:11:0x0300]: initializing channel: from_cache: True
[0x2a39:11:0x0006]: attempting to update onoff state - from cache: False
[0x2a39:11:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=41 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0006]: initializing channel: from_cache: False
[0x2a39:11:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=43 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x1000]: initializing channel: from_cache: False
[0x2a39:11:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=45 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0008]: received attribute: 0 update with value: 254
[0x2a39:11:0x0008]: initializing channel: from_cache: False
[0x2a39:11:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=47 command_id=Command.Read_Attributes_rsp>
None: polling current state
[0x2a39:11:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=49 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=51 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0000]: initializing channel: from_cache: False
[0x2a39:11:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=53 command_id=Command.Read_Attributes_rsp>
[0x2a39:11:0x0008]: received attribute: 0 update with value: 254
[0x2a39:11:0x0006]: 'async_initialize' stage succeeded
[0x2a39:11:0x0300]: 'async_initialize' stage succeeded
[0x2a39:11:0x0008]: 'async_initialize' stage succeeded
[0x2a39:11:0x1000]: 'async_initialize' stage succeeded
[0x2a39:11:0x0000]: 'async_initialize' stage succeeded
[0x2a39](LTC002): power source: Mains
[0x2a39](LTC002): completed initialization

Hue Dimmer

Device 0xa2fc (00:17:88:01:06:b7:4a:0c) joined the network
[0xa2fc:zdo] ZDO request 0x0013: [0xa2fc, 00:17:88:01:06:b7:4a:0c, 128]
[0xa2fc] Requesting 'Node Descriptor'
[0xa2fc] Extending timeout for 0x39 request
[0xa2fc] Node Descriptor: <Optional byte1=2 byte2=64 mac_capability_flags=128 manufacturer_code=4107 maximum_buffer_size=71 maximum_incoming_transfer_size=45 server_mask=0 maximum_outgoing_transfer_size=45 descriptor_capability_field=0>
[0xa2fc] Discovering endpoints
[0xa2fc] Extending timeout for 0x3b request
[0xa2fc] Discovered endpoints: [1, 2]
[0xa2fc:1] Discovering endpoint information
[0xa2fc] Extending timeout for 0x3d request
[0xa2fc:1] Discovered endpoint information: <SimpleDescriptor endpoint=1 profile=49246 device_type=2096 device_version=2 input_clusters=[0] output_clusters=[0, 3, 4, 6, 8, 5]>
[0xa2fc] Extending timeout for 0x3f request
[0xa2fc:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=63 command_id=Command.Read_Attributes_rsp>
[0xa2fc:1] Manufacturer: Philips
[0xa2fc:1] Model: RWL021
[0xa2fc:2] Discovering endpoint information
[0xa2fc] Extending timeout for 0x41 request
[0xa2fc:2] Discovered endpoint information: <SimpleDescriptor endpoint=2 profile=260 device_type=12 device_version=0 input_clusters=[0, 1, 3, 15, 64512] output_clusters=[25]>
Checking quirks for Philips RWL021 (00:17:88:01:06:b7:4a:0c)
Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
Fail because endpoint list mismatch: {11, 13} {1, 2}
Considering <class 'zhaquirks.lutron.lzl4bwhl01remote.LutronLZL4BWHL01Remote2'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.osram.a19twhite.A19TunableWhite'>
Fail because endpoint list mismatch: {3} {1, 2}
Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
Found custom device replacement for 00:17:88:01:06:b7:4a:0c: <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
device - 0xa2fc:00:17:88:01:06:b7:4a:0c entering async_device_initialized - is_new_join: True
device - 0xa2fc:00:17:88:01:06:b7:4a:0c has joined the ZHA zigbee network
[0xa2fc](RWL021): started configuration
[0xa2fc:ZDO](RWL021): 'async_configure' stage succeeded
[0xa2fc] Extending timeout for 0x43 request
[0xa2fc] Extending timeout for 0x45 request
[0xa2fc] Extending timeout for 0x47 request
[0xa2fc:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
[0xa2fc:1:0x0000]: finished channel configuration
[0xa2fc] Extending timeout for 0x49 request
[0xa2fc:1:0x0008]: bound 'level' cluster: Status.SUCCESS
[0xa2fc:1:0x0008]: finished channel configuration
[0xa2fc] Extending timeout for 0x4b request
[0xa2fc:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=73 command_id=Command.Read_Attributes_rsp>
[0xa2fc:1:0x0000]: initializing channel: from_cache: False
[0xa2fc] Extending timeout for 0x4d request
[0xa2fc:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
[0xa2fc:1:0x0006]: finished channel configuration
[0xa2fc] Extending timeout for 0x4f request
[0xa2fc:2:0x0000]: bound 'basic' cluster: Status.SUCCESS
[0xa2fc:2:0x0000]: finished channel configuration
[0xa2fc] Extending timeout for 0x51 request
[0xa2fc:2:0x0001]: bound 'power' cluster: Status.SUCCESS
[0xa2fc] Extending timeout for 0x53 request
[0xa2fc:2:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=81 command_id=Command.Read_Attributes_rsp>
[0xa2fc:2:0x0000]: initializing channel: from_cache: False
[0xa2fc:1:0x0005]: bound 'scenes' cluster: Status.SUCCESS
[0xa2fc:1:0x0005]: finished channel configuration
[0xa2fc:1:0x0000]: 'async_configure' stage succeeded
[0xa2fc:1:0x0008]: 'async_configure' stage succeeded
[0xa2fc:1:0x0005]: 'async_configure' stage succeeded
[0xa2fc:1:0x0006]: 'async_configure' stage succeeded
Device 0xa2fc (00:17:88:01:06:b7:4a:0c) joined the network
Skip initialization for existing device 00:17:88:01:06:b7:4a:0c
[0xa2fc:zdo] ZDO request 0x0013: [0xa2fc, 00:17:88:01:06:b7:4a:0c, 128]
Device 0xa2fc (00:17:88:01:06:b7:4a:0c) left the network
[0xa2fc:2:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=83 command_id=Command.Configure_Reporting_rsp>
[0xa2fc:2:0x0001]: reporting 'battery_voltage' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.UNREPORTABLE_ATTRIBUTE direction=0 attrid=32>]]'
[0xa2fc] Extending timeout for 0x55 request
[0xa2fc:2:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=85 command_id=Command.Configure_Reporting_rsp>
[0xa2fc:2:0x0001]: reporting 'battery_percentage_remaining' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xa2fc:2:0x0001]: finished channel configuration
[0xa2fc:2:0x0000]: 'async_configure' stage succeeded
[0xa2fc:2:0x0001]: 'async_configure' stage succeeded
[0xa2fc](RWL021): completed configuration
[0xa2fc](RWL021): stored in registry: ZhaDeviceEntry(name='Philips RWL021', ieee='00:17:88:01:06:b7:4a:0c', last_seen=1584728982.4917521)
[0xa2fc] Extending timeout for 0x57 request
[0xa2fc:2:0x0003] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=87 command_id=Command.Default_Response>
[0xa2fc:2:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.UNSUP_CLUSTER_COMMAND: 129>]
[0xa2fc](RWL021): started initialization
[0xa2fc:ZDO](RWL021): 'async_initialize' stage succeeded
[0xa2fc] Extending timeout for 0x59 request
[0xa2fc:1:0x0008]: initializing channel: from_cache: False
[0xa2fc:1:0x0005]: initializing channel: from_cache: False
[0xa2fc:1:0x0006]: initializing channel: from_cache: False
[0xa2fc] Extending timeout for 0x5b request
[0xa2fc] Extending timeout for 0x5d request
[0xa2fc:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=89 command_id=Command.Read_Attributes_rsp>
[0xa2fc:1:0x0000]: initializing channel: from_cache: False
[0xa2fc:2:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=91 command_id=Command.Read_Attributes_rsp>
[0xa2fc:1:0x0000]: 'async_initialize' stage succeeded
[0xa2fc:1:0x0008]: 'async_initialize' stage succeeded
[0xa2fc:1:0x0005]: 'async_initialize' stage succeeded
[0xa2fc:1:0x0006]: 'async_initialize' stage succeeded
[0xa2fc:2:0x0000]: initializing channel: from_cache: False
[0xa2fc:2:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=93 command_id=Command.Read_Attributes_rsp>
[0xa2fc:2:0x0001]: initializing channel: from_cache: False
[0xa2fc] Extending timeout for 0x5f request
[0xa2fc:2:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=95 command_id=Command.Read_Attributes_rsp>
[0xa2fc:2:0x0000]: 'async_initialize' stage succeeded
[0xa2fc:2:0x0001]: 'async_initialize' stage succeeded
[0xa2fc](RWL021): power source: Battery or Unknown
[0xa2fc](RWL021): completed initialization

And got the following errors summarized while I setup them and use just for the test purposes approx. for a 30-60 minutes.

I think this one was at HA start as usually at initialization processes:

Logger: bellows.uart
Source: /usr/local/lib/python3.7/site-packages/bellows/uart.py:83
First occurred: 7:22:38 PM (1 occurrences)
Last logged: 7:22:38 PM

CRC error in frame b'1111556ea1ad87dc7e' (b'87dc' != b'fc23')

But these 2 were I simply do know know when. Sometime when I configure the corresponding automations and tried to switch the lamp on/off, and also dim, etc.:

Logger: bellows.uart
Source: /usr/local/lib/python3.7/site-packages/bellows/uart.py:83
First occurred: 8:22:30 PM (2 occurrences)
Last logged: 8:22:36 PM

CRC error in frame b'115469b1ed502a15b259944a25aa5592ad63e2db0912316c8f7fd65884fc1132a7ebcd53bd7e' (b'53bd' != b'1265')
CRC error in frame b'11706da1ad55877e' (b'5587' != b'6e40')

And if I'm right I got the following whe tried to change some parameter of one automation (maybe when changed the brightness_pct in light.turn_on action or something like that.):

Logger: asyncio
Source: util/yaml/loader.py:50
First occurred: 8:31:15 PM (1 occurrences)
Last logged: 8:31:15 PM

Task was destroyed but it is pending! task: <Task pending coro=<Gateway._send_task() running at /usr/local/lib/python3.7/site-packages/bellows/uart.py:237> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f549c7ef1d0>()]>>

Basically the system worked. I could paired the devices, use the dimmer, also the lamp. There were 1-2 times instability (Dimmer just simply - from the nowhere - not worked as before, while I tried to switch pell-mell) but without any config modification some seconds later it worked again.

What is interesting for me that if I'm right I simply not got these errors before HA 0.105 or 0.16 upgrade, but this is just what I remember sot not 100000% sure.

What is your opinion?

Adminiuga commented 4 years ago

Uninstall modem manager! There were no changes in bellows-homeassistant UART serial port processing. And ATM no one else is reporting the same issue.

Tamas-Toth-ebola commented 4 years ago

Hi!

Modem manager was my first step when I saw the suggestion in HA manuals before my first experiments with Z-Wave and/or Zigbee. You can check the current state of it:

  pc-ebola  ebola  ~  sudo apt list modem*
Listing... Done
modem-cmd/eoan,eoan 1.0.2-3 all
modem-manager-gui-help/eoan,eoan 0.0.19.1-2 all
modem-manager-gui/eoan 0.0.19.1-2 amd64
modem-manager-gui/eoan 0.0.19.1-2 i386
modemmanager-dev/eoan 1.10.4-0.1 amd64
modemmanager-dev/eoan 1.10.4-0.1 i386
modemmanager-doc/eoan,eoan 1.10.4-0.1 all
modemmanager-qt-dev/eoan 5.62.0-0ubuntu1 amd64
modemmanager-qt-dev/eoan 5.62.0-0ubuntu1 i386
modemmanager/eoan 1.10.4-0.1 amd64
modemmanager/eoan 1.10.4-0.1 i386
  pc-ebola  ebola  ~  sudo apt autopurge modem*
Reading package lists... Done
Building dependency tree       
Reading state information... Done
Note, selecting 'modemmanager-dev' for glob 'modem*'
Note, selecting 'modemmanager-doc' for glob 'modem*'
Note, selecting 'modem-cmd' for glob 'modem*'
Note, selecting 'modemmanager-qt-dev' for glob 'modem*'
Note, selecting 'modem-manager-gui-help' for glob 'modem*'
Note, selecting 'modem-manager-gui' for glob 'modem*'
Note, selecting 'modemmanager' for glob 'modem*'
Package 'modemmanager' is not installed, so not removed
Package 'modemmanager-dev' is not installed, so not removed
Package 'modemmanager-doc' is not installed, so not removed
Package 'modem-cmd' is not installed, so not removed
Package 'modem-manager-gui' is not installed, so not removed
Package 'modem-manager-gui-help' is not installed, so not removed
Package 'modemmanager-qt-dev' is not installed, so not removed
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.

Adminiuga commented 4 years ago

I'm running of ideas here. After HA Core start, what do you get for EZSP protocol version and stack version? Do you get anything about in /var/log/debug, /var/log/kern.log about USB around same time when you get those CRC errors? Overall frame looks like a frame and at least it has the frame delimiter at the end, just CRC is wrong.

Tamas-Toth-ebola commented 4 years ago

No problem and thanks again for your effort. I need some more time to make a test again, but in some days I will do it. Please leave this issue open until if not problem, after the next test if you have no more ideas of course could be closed.

(Anyway as I wrote I do not feel any problems at least problems what affected by this error log just wrote the report if anybody have any ideas about that as after all the error log is there:))

Tamas-Toth-ebola commented 4 years ago

Are there any possibility to switch on any type of timestamp into logs of bellows? Sorry I'm a little bit off to bellows itself yet.

Adminiuga commented 4 years ago

in configuration.yaml add

logger:
  default: info
  logs:
    asyncio: debug
    homeassistant.components.zha: debug
    zigpy: debug
    bellows.zigbee.application: debug
    bellows.ezsp: debug

Then check home-assistant.log in your configuration folder, its gonna have timestamps

Adminiuga commented 4 years ago

How did you configure zha integration? Integration UI or using configuration.yaml ? if using configuration.yaml what port speed did you use?

Tamas-Toth-ebola commented 4 years ago

Through the GUI without any configuration.yaml specialities.

Z-wave by configuration. yaml because the security key, but Zigbee by GUI as it works (I hope:))...

Adminiuga commented 4 years ago

I'm out of ideas here. Don't know, maybe a kernel update would fix it, but as long as you don't get too many, i think you can ignore them.

Closing this for now.

houseio commented 1 year ago

hi, same problems here:

Logger: bellows.uart Source: /usr/local/lib/python3.11/site-packages/bellows/uart.py:92 First occurred: 14:35:55 (1 occurrences) Last logged: 14:35:55 CRC error in frame b'8a5aab4d499cad9763cf7f9874f2ce9283fd7e1fea0932fe596b00e7db7a1c7e' (b'7a1c' != b'cb27

any ideas ?

Tamas-Toth-ebola commented 1 year ago

Hi! Meanwhile, I changed my Zigbee gateway from that Bitronvideo one to a SONOFF - ZBDongle-P, which does not have such 'warnings'.

So from my aspect, I sadly can not offer any more information about it.

Adminiuga commented 1 year ago

Depends what firmware is running on that button and whether it expects software flow control on or off, I've seen mismatch producing those CRC errors

85Kid commented 1 year ago

Had the same issue today

Logger: bellows.uart Source: /usr/local/lib/python3.11/site-packages/bellows/uart.py:92 First occurred: 14:18:56 (1 occurrences) Last logged: 14:18:56

CRC error in frame b'bd7e' (b'bd' != b'ffff')

Stefos13 commented 11 months ago

here the same.

Logger: bellows.uart Source: /usr/local/lib/python3.11/site-packages/bellows/uart.py:92 First occurred: 17:56:14 (1 occurrences) Last logged: 17:56:14

CRC error in frame b'8f9ad7dbbbf269e36623a8cd9237a6c26f8760984f2e32a3c67a1995f39e98e5ca658adebb4d9ee7aa7e' (b'e7aa' != b'922b')

urosch commented 11 months ago

same issue: Logger: bellows.uart Source: /usr/local/lib/python3.11/site-packages/bellows/uart.py:92 First occurred: 19:01:00 (1 occurrences) Last logged: 19:01:00

CRC error in frame b'a50a7e' (b'a50a' != b'ffff')

kgrzebien commented 11 months ago

I've had the same while using SONOFF ZBDongle-E. The problem was related with interference, I'm using USB extension cable (relatively short though) and everything worked fine when connected to laptop, however it didn't work out when connected to Raspberry Pi. Overall I followed this thread, removed anthena and retried configuration few times, which helped at the end of the day. I'm guessing longer extension cable should help here.

home-assistant / core