Azure-iot-sdk-c: C SDK device client logs CBS error when destroy() is called

Created on 15 Feb 2018  路  9Comments  路  Source: Azure/azure-iot-sdk-c

  • OS and version used:
    Windows 10

  • SDK version used:
    IoT Hub SDK for C, master branch - HEAD

Description of the issue:

I am running the sample iothub_II_telemetry_sample with AMQP and it send the events correctly to the IoT Hub. I can see the events with the node package "iothub-explorer monitor-events" arriving at the IoT Hub. I receive the following error at the end of the five test-message transmissions:
Error: Time:Thu Feb 15 16:24:03 2018 File:C:\IoT\azure-iot-sdk-c\iothub_client\src\iothubtransport_amqp_connection.c Func:_on_cbs_error Line:160 CBS Error occured

Console log of the issue:

Creating IoTHub handle
Sending message 1 to IoTHub
Sending message 2 to IoTHub
Sending message 3 to IoTHub
Sending message 4 to IoTHub
Sending message 5 to IoTHub
-> Header (AMQP 0.1.0.0)
<- Header (AMQP 0.1.0.0)
-> [OPEN]* {fd5a99f2-1ceb-4ef9-abc0-45b2e6d7e806,LiSEC-IOT-POC.azure-devices.net,4294967295,65535,240000}
<- [OPEN]* {DeviceGateway_0d5748a0b468434c81073cea8e0a1cc8,10.0.4.50,65536,8191,240000,NULL,NULL,NULL,NULL,NULL}
-> [BEGIN]* {NULL,0,4294967295,100,4294967295}
<- [BEGIN]* {0,1,5000,4294967295,262143,NULL,NULL,NULL}
-> [ATTACH]* {$cbs-sender,0,false,0,0,* {$cbs},* {$cbs},NULL,NULL,0,0}
-> [ATTACH]* {$cbs-receiver,1,true,0,0,* {$cbs},* {$cbs},NULL,NULL,NULL,0}
<- [ATTACH]* {$cbs-sender,0,true,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,NULL}
<- [FLOW]* {0,5000,1,4294967295,0,0,100,0,NULL,false,NULL}
-> [TRANSFER]* {0,0,<01 00 00 00>,0,false,false}
<- [ATTACH]* {$cbs-receiver,1,false,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,1048576,NULL,NULL,NULL}
-> [FLOW]* {1,4294967295,1,99,1,0,10000}
<- [DISPOSITION]* {true,0,NULL,true,* {},NULL}
<- [TRANSFER]* {1,0,<01 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}
-> [DISPOSITION]* {true,0,0,true,* {}}
-> [ATTACH]* {link-snd-POC-TEST-1-8b2b14a9-2381-4abc-935e-4c49864cbcea,2,false,0,0,* {link-snd-POC-TEST-1-8b2b14a9-2381-4abc-935e-4c49864cbcea-source},* {amqps://LiSEC-IOT-POC.azure-devices.net/devices/POC-TEST-1/messages/events},NULL,NULL,0,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.31 (native; WindowsProduct:0x00000004 6.2; x32)]}}
-> [ATTACH]* {link-snd-POC-TEST-1-451bf8aa-a1d7-42bd-8d09-fb6ea64423b5,3,false,0,0,* {link-snd-POC-TEST-1-451bf8aa-a1d7-42bd-8d09-fb6ea64423b5-source},* {amqps://LiSEC-IOT-POC.azure-devices.net/devices/POC-TEST-1/twin},NULL,NULL,0,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.31 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:2c846b07-1d1f-4290-97ef-6a5bf9d7a50a],[com.microsoft:api-version:2016-11-14]}}
<- [ATTACH]* {link-snd-POC-TEST-1-8b2b14a9-2381-4abc-935e-4c49864cbcea,2,true,0,NULL,* {link-snd-POC-TEST-1-8b2b14a9-2381-4abc-935e-4c49864cbcea-source,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://LiSEC-IOT-POC.azure-devices.net/devices/POC-TEST-1/messages/events,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.31 (native; WindowsProduct:0x00000004 6.2; x32)]}}
<- [FLOW]* {1,5000,2,4294967295,2,0,1000,0,NULL,false,NULL}
<- [ATTACH]* {link-snd-POC-TEST-1-451bf8aa-a1d7-42bd-8d09-fb6ea64423b5,3,true,1,0,* {link-snd-POC-TEST-1-451bf8aa-a1d7-42bd-8d09-fb6ea64423b5-source,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://LiSEC-IOT-POC.azure-devices.net/devices/POC-TEST-1/twin,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.31 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:2c846b07-1d1f-4290-97ef-6a5bf9d7a50a],[com.microsoft:api-version:2016-11-14]}}
<- [FLOW]* {1,5000,2,4294967295,3,0,1000,0,NULL,false,NULL}
-> [ATTACH]* {link-rcv-POC-TEST-1-a3823cf5-bbdb-4ea1-b108-4c36af2ac141,4,true,0,0,* {amqps://LiSEC-IOT-POC.azure-devices.net/devices/POC-TEST-1/twin},* {link-rcv-POC-TEST-1-a3823cf5-bbdb-4ea1-b108-4c36af2ac141-target},NULL,NULL,NULL,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.31 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:2c846b07-1d1f-4290-97ef-6a5bf9d7a50a],[com.microsoft:api-version:2016-11-14]}}
<- [ATTACH]* {link-rcv-POC-TEST-1-a3823cf5-bbdb-4ea1-b108-4c36af2ac141,4,false,1,0,* {amqps://LiSEC-IOT-POC.azure-devices.net/devices/POC-TEST-1/twin,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {link-rcv-POC-TEST-1-a3823cf5-bbdb-4ea1-b108-4c36af2ac141-target,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.31 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:2c846b07-1d1f-4290-97ef-6a5bf9d7a50a],[com.microsoft:api-version:2016-11-14]}}
-> [FLOW]* {2,4294967294,1,99,4,0,10000}
-> [TRANSFER]* {2,1,<01 00 00 00>,2147563264,false,false}
<- [DISPOSITION]* {true,1,NULL,true,* {},NULL}
Confirmation callback received for message 1 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 2 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 3 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 4 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 5 with result IOTHUB_CLIENT_CONFIRMATION_OK
-> [DETACH]* {2,true}
-> [DETACH]* {3,true}
-> [DETACH]* {4,true}
Error: Time:Thu Feb 15 16:24:03 2018 File:C:\IoT\azure-iot-sdk-c\iothub_client\src\iothubtransport_amqp_connection.c Func:_on_cbs_error Line:160 CBS Error occured
-> [DETACH]* {0,true}
-> [DETACH]* {1,true}
-> [END]* {}
-> [CLOSE]* {}
bug
Source
picture woigl

All 9 comments

That's a non-critical known issue.
It will be printed in the logs when you destroy the IoThubClient when using AMQP protocol.
Despite the non-critical aspect the behavior is incorrect and it is in our list of errors to be fixed.

ewertons picture ewertons on 15 Feb 2018

Just to make sure, you should consider the results provided in the callback to evaluate if the messages were sent correctly (IOTHUB_CLIENT_CONFIRMATION_OK indicates messages were sent successfully, as you correctly verified using iothub-explorer monitor-events)

ewertons picture ewertons on 15 Feb 2018
👍1

Thanks for your feedback. At least I know it is nothing serious, but it still appears in my console.

Can this issue be resolved through that ticket, or do I need to create a ticket to another project?

woigl picture woigl on 16 Feb 2018

I would rename this ticket to "C SDK device client logs CBS error when destroy() is called".

ewertons picture ewertons on 16 Feb 2018

@ewertons, please go ahead with the rename.

woigl picture woigl on 16 Feb 2018
👍1

For (our internal) future reference, this is the callstack of the issue:

iothub_ll_telemetry_sample.exe!on_cbs_error(void * context) Line 160 C
iothub_ll_telemetry_sample.exe!on_underlying_amqp_management_error(void * context) Line 180 C
iothub_ll_telemetry_sample.exe!on_message_sender_state_changed(void * context, MESSAGE_SENDER_STATE_TAG new_state, MESSAGE_SENDER_STATE_TAG previous_state) Line 435 C
iothub_ll_telemetry_sample.exe!set_message_sender_state(MESSAGE_SENDER_INSTANCE_TAG * message_sender, MESSAGE_SENDER_STATE_TAG new_state) Line 640 C
iothub_ll_telemetry_sample.exe!messagesender_close(MESSAGE_SENDER_INSTANCE_TAG * message_sender) Line 802 C
iothub_ll_telemetry_sample.exe!amqp_management_close(AMQP_MANAGEMENT_INSTANCE_TAG * amqp_management) Line 1004 C
iothub_ll_telemetry_sample.exe!cbs_destroy(CBS_INSTANCE_TAG * cbs) Line 348 C
iothub_ll_telemetry_sample.exe!amqp_connection_destroy(AMQP_CONNECTION_INSTANCE * conn_handle) Line 301 C
iothub_ll_telemetry_sample.exe!internal_destroy_instance(AMQP_TRANSPORT_INSTANCE_TAG * instance) Line 1339 C
iothub_ll_telemetry_sample.exe!IoTHubTransport_AMQP_Common_Destroy(void * handle) Line 2342 C
iothub_ll_telemetry_sample.exe!IoTHubTransportAMQP_Destroy(void * handle) Line 138 C
iothub_ll_telemetry_sample.exe!IoTHubClient_LL_Destroy(IOTHUB_CLIENT_LL_HANDLE_DATA_TAG * iotHubClientHandle) Line 969 C
iothub_ll_telemetry_sample.exe!main() Line 127 C
[External Code]

ewertons picture ewertons on 15 Mar 2018

This issue was fixed.
The change needed was in uamqp repo.

https://github.com/Azure/azure-uamqp-c/pull/225

ewertons picture ewertons on 16 Mar 2018

Output from iothub_II_telemetry_sample now:

Creating IoTHub handle
Sending message 1 to IoTHub
Sending message 2 to IoTHub
Sending message 3 to IoTHub
Sending message 4 to IoTHub
Sending message 5 to IoTHub
-> Header (AMQP 0.1.0.0)
<- Header (AMQP 0.1.0.0)
-> [OPEN]* {f5afd910-e29e-4f0d-8582-01ac22192ea8,myiothub.azure-devices.net,4294967295,65535,240000}
<- [OPEN]* {DeviceGateway_dcb3c7031ba749b8acf2e3b6ebe1f41d,10.20.30.40,65536,8191,240000,NULL,NULL,NULL,NULL,NULL}
-> [BEGIN]* {NULL,0,4294967295,100,4294967295}
<- [BEGIN]* {0,1,5000,4294967295,262143,NULL,NULL,NULL}
-> [ATTACH]* {$cbs-sender,0,false,0,0,* {$cbs},* {$cbs},NULL,NULL,0,0}
-> [ATTACH]* {$cbs-receiver,1,true,0,0,* {$cbs},* {$cbs},NULL,NULL,NULL,0}
<- [ATTACH]* {$cbs-sender,0,true,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,NULL}
<- [FLOW]* {0,5000,1,4294967295,0,0,100,0,NULL,false,NULL}
-> [TRANSFER]* {0,0,<01 00 00 00>,0,false,false}
<- [ATTACH]* {$cbs-receiver,1,false,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,1048576,NULL,NULL,NULL}
-> [FLOW]* {1,4294967295,1,99,1,0,10000}
<- [DISPOSITION]* {true,0,NULL,true,* {},NULL}
<- [TRANSFER]* {1,0,<01 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}
-> [DISPOSITION]* {true,0,0,true,* {}}
-> [ATTACH]* {link-snd-mydeviceid-4f9e9332-d50e-4442-8f4f-f538208134b5,2,false,0,0,* {link-snd-mydeviceid-4f9e9332-d50e-4442-8f4f-f538208134b5-source},* {amqps://myiothub.azure-devices.net/devices/mydeviceid/messages/events},NULL,NULL,0,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.2.0 (native; WindowsProduct:0x00000004 6.2; x32)]}}
-> [ATTACH]* {link-snd-mydeviceid-4bbdb2e6-66de-49a8-85cd-dabadae46dd6,3,false,0,0,* {link-snd-mydeviceid-4bbdb2e6-66de-49a8-85cd-dabadae46dd6-source},* {amqps://myiothub.azure-devices.net/devices/mydeviceid/twin},NULL,NULL,0,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.2.0 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:90849ae1-eb8d-49ef-a87f-09efde727b9d],[com.microsoft:api-version:2016-11-14]}}
<- [ATTACH]* {link-snd-mydeviceid-4f9e9332-d50e-4442-8f4f-f538208134b5,2,true,0,NULL,* {link-snd-mydeviceid-4f9e9332-d50e-4442-8f4f-f538208134b5-source,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://myiothub.azure-devices.net/devices/mydeviceid/messages/events,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.2.0 (native; WindowsProduct:0x00000004 6.2; x32)]}}
<- [FLOW]* {1,5000,2,4294967295,2,0,1000,0,NULL,false,NULL}
<- [ATTACH]* {link-snd-mydeviceid-4bbdb2e6-66de-49a8-85cd-dabadae46dd6,3,true,1,0,* {link-snd-mydeviceid-4bbdb2e6-66de-49a8-85cd-dabadae46dd6-source,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://myiothub.azure-devices.net/devices/mydeviceid/twin,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.2.0 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:90849ae1-eb8d-49ef-a87f-09efde727b9d],[com.microsoft:api-version:2016-11-14]}}
<- [FLOW]* {1,5000,2,4294967295,3,0,1000,0,NULL,false,NULL}
-> [ATTACH]* {link-rcv-mydeviceid-21bc0b63-c5f7-44b5-bff9-0b4265dae3ed,4,true,0,0,* {amqps://myiothub.azure-devices.net/devices/mydeviceid/twin},* {link-rcv-mydeviceid-21bc0b63-c5f7-44b5-bff9-0b4265dae3ed-target},NULL,NULL,NULL,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.2.0 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:90849ae1-eb8d-49ef-a87f-09efde727b9d],[com.microsoft:api-version:2016-11-14]}}
<- [ATTACH]* {link-rcv-mydeviceid-21bc0b63-c5f7-44b5-bff9-0b4265dae3ed,4,false,1,0,* {amqps://myiothub.azure-devices.net/devices/mydeviceid/twin,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {link-rcv-mydeviceid-21bc0b63-c5f7-44b5-bff9-0b4265dae3ed-target,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.2.0 (native; WindowsProduct:0x00000004 6.2; x32)],[com.microsoft:channel-correlation-id:twin:90849ae1-eb8d-49ef-a87f-09efde727b9d],[com.microsoft:api-version:2016-11-14]}}
-> [FLOW]* {2,4294967294,1,99,4,0,10000}
-> [TRANSFER]* {2,1,<01 00 00 00>,2147563264,false,false}
<- [DISPOSITION]* {true,1,NULL,true,* {},NULL}
Confirmation callback received for message 1 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 2 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 3 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 4 with result IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation callback received for message 5 with result IOTHUB_CLIENT_CONFIRMATION_OK
-> [DETACH]* {2,true}
-> [DETACH]* {3,true}
-> [DETACH]* {4,true}
-> [DETACH]* {0,true}
-> [DETACH]* {1,true}
-> [END]* {}
-> [CLOSE]* {}
Press any key to continue

ewertons picture ewertons on 16 Mar 2018

@woigl thank you for your contribution to our open-sourced project!聽 Please help us improve by filling out this 2-minute customer satisfaction survey.

tameraw picture tameraw on 24 Apr 2018
Was this page helpful?
0 / 5 - 0 ratings

Related issues

hizzawaseem picture hizzawaseem  路  3Comments
wlisac picture wlisac  路  4Comments
kiranpradeep picture kiranpradeep  路  7Comments
alexeystrakh picture alexeystrakh  路  5Comments
kenyelima picture kenyelima  路  3Comments