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

Error reporting cleanup #6979

Merged
merged 9 commits into from
May 26, 2021
Merged

Conversation

andy31415
Copy link
Contributor

@andy31415 andy31415 commented May 19, 2021

Problem

OnReceiveError was reporting 'accept failure' and the 'received message from node...' was logged as an error

Summary of Changes

Expand the message for OnReceive error to make it clear it is on receiving and to note from where the error came from.
Switch the progress log to 'progress' instead of error.

Testing

Manually ran ble-wifi pairing on esp32 and watced logs with ./scripts/tools/esp32_log_cat.py

Saw:

2021-05-20 11:55:07 /dev/ttyUSB0 INFO    I (40123) chip[IN]: Secure transport received message destined to fabric 0, node 12344321. Key ID 0
2021-05-20 11:55:07 /dev/ttyUSB0 INFO    I (40133) chip[EM]: Received message of type 8 and protocolId 327680
2021-05-20 11:55:07 /dev/ttyUSB0 INFO    I (40173) chip[IN]: Sending msg from 0x0000000000bc5c01 to 0x000000000001b669 at utc time: 39494 msec
2021-05-20 11:55:07 /dev/ttyUSB0 INFO    I (40183) chip[IN]: Sending secure msg on generic transport
2021-05-20 11:55:07 /dev/ttyUSB0 INFO    I (40193) chip[IN]: Secure msg send status No Error
2021-05-20 11:55:07 /dev/ttyUSB0 ERROR   E (40203) chip[EM]: Error receiving message from BLE: CHIP Error 4000047 (0x003D092F): Invalid argument

@andy31415
Copy link
Contributor Author

The benefit of this now is: i see that the message counter mismatch occurs in BLE, which may be considered odd as BLE is point-to-point so nodes do not necesarely need to validate destination node id for every incoming message.

@andy31415
Copy link
Contributor Author

@@ -141,7 +141,11 @@ CHIP_ERROR ExchangeManager::UnregisterUnsolicitedMessageHandlerForType(Protocols

void ExchangeManager::OnReceiveError(CHIP_ERROR error, const Transport::PeerAddress & source, SecureSessionMgr * msgLayer)
{
ChipLogError(ExchangeManager, "Accept FAILED, err = %s", ErrorStr(error));
char srcAddressStr[Transport::PeerAddress::kMaxToStringSize];
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: might be worth guarding this code with #if CHIP_ERROR_LOGGING (not sure if it will be optimized out when logging is disabled).

ChipLogError(Inet, "Secure transport received message destined to node ID (0x" ChipLogFormatX64 ")",
ChipLogValueX64(packetHeader.GetDestinationNodeId().Value()));
ChipLogProgress(Inet, "Secure transport received message destined to fabric %d, node 0x" ChipLogFormatX64 ". Key ID %d",
static_cast<int>(state->GetAdminId()), packetHeader.GetDestinationNodeId().Value(),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You removed the ChipLogValueX64 macro (probably unintentionally).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, bad merge. Trying again. Thanks for noticing.

}
else
{
ChipLogError(Inet, "Secure transport received message without node ID with key ID (%d)", packetHeader.GetEncryptionKeyID());
ChipLogProgress(Inet, "Secure transport received message for fabrid %d without node ID. Key ID %d",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

typo: fabrid

@github-actions
Copy link

Size increase report for "esp32-example-build" from 81a4896

File Section File VM
chip-all-clusters-app.elf .flash.rodata 32 32
chip-all-clusters-app.elf .flash.text 24 24
Full report output
BLOAT REPORT

Files found only in the build output:
    report.csv

Comparing ./master_artifact/chip-pigweed-app.elf and ./pull_artifact/chip-pigweed-app.elf:

sections,vmsize,filesize

Comparing ./master_artifact/chip-all-clusters-app.elf and ./pull_artifact/chip-all-clusters-app.elf:

sections,vmsize,filesize
.debug_info,0,192
.debug_loc,0,78
.debug_line,0,76
.flash.rodata,32,32
.flash.text,24,24
.debug_abbrev,0,18
.debug_str,0,14
.xt.prop._ZTVN4chip11DeviceLayer37DeviceNetworkProvisioningDelegateImplE,0,-2
[Unmapped],0,-32


@github-actions
Copy link

Size increase report for "gn_qpg6100-example-build" from 81a4896

File Section File VM
chip-qpg6100-lighting-example.out .text 64 64
Full report output
BLOAT REPORT

Files found only in the build output:
    report.csv

Comparing ./master_artifact/chip-qpg6100-lighting-example.out.map and ./pull_artifact/chip-qpg6100-lighting-example.out.map:

BLOAT EXECUTION FAILED WITH CODE 1:
bloaty: unknown file type for file './pull_artifact/chip-qpg6100-lighting-example.out.map'

Comparing ./master_artifact/chip-qpg6100-lighting-example.out and ./pull_artifact/chip-qpg6100-lighting-example.out:

sections,vmsize,filesize
.debug_info,0,192
.debug_loc,0,129
.text,64,64
.debug_line,0,39
.debug_abbrev,0,18
.debug_str,0,14
.debug_frame,0,4
[Unmapped],0,-64


@github-actions
Copy link

Size increase report for "nrfconnect-example-build" from 81a4896

File Section File VM
chip-shell.elf rodata 32 36
chip-shell.elf text 36 36
chip-shell.elf device_handles -4 -4
chip-lock.elf text 48 48
chip-lock.elf rodata 40 40
Full report output
BLOAT REPORT

Files found only in the build output:
    report.csv

Comparing ./master_artifact/chip-shell.elf and ./pull_artifact/chip-shell.elf:

sections,vmsize,filesize
.debug_info,0,192
.debug_loc,0,98
.debug_line,0,42
rodata,36,32
text,36,36
.debug_abbrev,0,18
.symtab,0,16
.debug_str,0,14
.debug_frame,0,4
device_handles,-4,-4

Comparing ./master_artifact/chip-lock.elf and ./pull_artifact/chip-lock.elf:

sections,vmsize,filesize
.debug_info,0,187
.debug_loc,0,94
.debug_ranges,0,64
.debug_line,0,51
text,48,48
rodata,40,40
.debug_abbrev,0,18
.symtab,0,16
.debug_str,0,14
.debug_frame,0,4


@andy31415 andy31415 merged commit a152b44 into project-chip:master May 26, 2021
nikita-s-wrk pushed a commit to nikita-s-wrk/connectedhomeip that referenced this pull request Sep 23, 2021
* Code cleanup: better error report for on receive errors, destination node id logging is a progress not an error

* Include fabric ID in progress message for secure transport. We may want to eventually maye this "Detail" in case logging is too verbose

* Take into account that node ids in packet headers are optional

* Restyle fixes and swap back error to progress

* Review comments and merge fix

* revert unwanted changes

* Updated the chip error logging conditional
@andy31415 andy31415 deleted the debuggability_cleanup branch October 28, 2021 14:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants