Skip to content

Instantly share code, notes, and snippets.

@Morozov-5F

Morozov-5F/application_log.txt

Last active May 2, 2019 01:40
Show Gist options
  • Save Morozov-5F/916d461921d0f6f9d3f3447de95adb66 to your computer and use it in GitHub Desktop.
Save Morozov-5F/916d461921d0f6f9d3f3447de95adb66 to your computer and use it in GitHub Desktop.
Download ZIP
Azure IoT Hub SDK fails to notify about device twin changes (MQTT)
Raw
application_log.txt
Aug 6 13:35:00 22 azure/azure.c:3543: s_azure_ctx_init: Azure: enabling logging to file /tmp/azure_sdk_log.txt
Aug 6 13:35:00 22 azure/azure.c:3550: s_azure_ctx_init: Azure: Logging setup
Sep 5 08:46:17 37 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:23 44 azure/azure.c:1312: s_azure_client_connection_status_cb: Azure connection status: ONLINE; reason: OK
Sep 5 08:46:23 44 advanced_diag.c:2113: s_set_azure_status: Setting azure_status to: 2
1> Sep 5 08:46:25 46 azure/azure.c:1669: s_azure_send_twin_properties: TWIN-REPORTED: uploading an update
2> Sep 5 08:46:28 49 azure/azure.c:1617: s_azure_send_reported_twin_props_cb: TWIN-REPORTED: upload successfull
Sep 5 08:46:28 49 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:29 50 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:30 51 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:31 52 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:32 53 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:33 54 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:34 55 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:35 56 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:36 57 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:37 58 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:38 59 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:39 60 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:40 61 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:41 62 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:42 63 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:43 64 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:44 65 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:45 66 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:46 67 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:47 68 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:48 69 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:49 70 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:50 71 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:46:51 72 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:46:52 73 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Sep 5 08:47:16 97 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:47:17 98 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
4> Sep 5 08:51:24 344 azure/azure.c:2752: s_azure_main_loop: TELEMETRY: sending a message to Azure
Sep 5 08:51:25 345 azure/azure.c:1161: s_azure_send_confirmation_cb: TELEMETRY: message is delievered
Raw
azure.c
/**
* Please note that the code is very simplified but no sgnificant Azure-related
* routines were removed.
*/
static int
s_azure_ctx_init()
{
/* ... Override logging functions. Same as ... */
platform_init();
/* ... Get private key and certificates ... */
iothub_client = IoTHubClient_LL_CreateFromConnectionString("HostName=IOTHUB_HOST;DeviceId=DEVICE_ID;x509=true",
MQTT_Protocol);
UNUSED(OPTION_PROXY_HOST);
UNUSED(OPTION_PROXY_USERNAME);
UNUSED(OPTION_PROXY_PASSWORD);
UNUSED(OPTION_SAS_TOKEN_LIFETIME);
UNUSED(OPTION_SAS_TOKEN_REFRESH_TIME);
UNUSED(OPTION_CBS_REQUEST_TIMEOUT);
UNUSED(OPTION_MIN_POLLING_TIME);
UNUSED(OPTION_BATCHING);
UNUSED(OPTION_PRODUCT_INFO);
UNUSED(OPTION_C2D_KEEP_ALIVE_FREQ_SECS);
UNUSED(OPTION_DIAGNOSTIC_SAMPLING_PERCENTAGE);
UNUSED(OPTION_CONNECTION_TIMEOUT);
UNUSED(OPTION_AUTO_URL_ENCODE_DECODE);
UNUSED(OPTION_SERVICE_SIDE_KEEP_ALIVE_FREQ_SECS);
UNUSED(OPTION_REMOTE_IDLE_TIMEOUT_RATIO);
UNUSED(OPTION_BLOB_UPLOAD_TIMEOUT_SECS);
/* Enable logging */
bool azure_log_trace = true;
iot_hub_ret = IoTHubClient_LL_SetOption(azure_ctx->azct_client,
OPTION_LOG_TRACE,
&azure_log_trace);
ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
/* Keep the connection alive */
int keep_alive_interval_sec = 30;
iot_hub_ret = IoTHubClient_LL_SetOption(azure_ctx->azct_client,
OPTION_KEEP_ALIVE,
&keep_alive_interval_sec);
ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
/* Set message timeout */
uint32_t azure_message_timeout_msec = 60 * 1000; /* 60 sec */
iot_hub_ret = IoTHubClient_LL_SetOption(azure_ctx->azct_client,
OPTION_MESSAGE_TIMEOUT,
&azure_message_timeout_msec);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
/* Assign certificates */
iot_hub_ret = IoTHubClient_LL_SetOption(azure_ctx->azct_client,
OPTION_X509_CERT,
certificates);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
/* Assign private key */
iot_hub_ret = IoTHubClient_LL_SetOption(azure_ctx->azct_client,
OPTION_X509_PRIVATE_KEY,
private_key);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
/* Set retry policy */
iot_hub_ret = IoTHubClient_LL_SetRetryPolicy(azure_ctx->azct_client,
IOTHUB_CLIENT_RETRY_INTERVAL,
0);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
/* Setup callbacks */
iot_hub_ret = IoTHubClient_LL_SetMessageCallback(azure_ctx->azct_client,
s_azure_receive_message_cb,
azure_ctx);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
iot_hub_ret = IoTHubClient_LL_SetConnectionStatusCallback(
azure_ctx->azct_client,
s_azure_client_connection_status_cb,
azure_ctx);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
iot_hub_ret = IoTHubClient_LL_SetDeviceMethodCallback(
azure_ctx->azct_client,
s_azure_device_method_cb,
azure_ctx);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
iot_hub_ret = IoTHubClient_LL_SetDeviceTwinCallback(azure_ctx->azct_client,
s_azure_device_twin_cb,
azure_ctx);
CAT_ASSERT(IOTHUB_CLIENT_OK == iot_hub_ret);
}
static void
s_azure_device_twin_cb(DEVICE_TWIN_UPDATE_STATE twin_update_state,
const unsigned char * payload,
size_t payload_size, void * ctx)
{
logger("TWIN-GENERAL: twin update received. Status: %d", twin_update_state);
/* ... Process reported and desired properties */
process_reported(payload, payload_size, ctx);
process_desired(payload, payload_size, ctx);
return;
}
Raw
azure_sdk_log.txt
[ 43.564652040] -> 08:46:22 CONNECT | VER: 4 | KEEPALIVE: 30 | FLAGS: 128 | USERNAME: IOTHUB_NAME/DEVICE_ID/api-version=2016-11-14&DeviceClientType=iothubclient%2f1.2.3%20(native%3b%20Linux%3b%20mips) | CLEAN: 0
[ 44.566573194] <- 08:46:23 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
1> [ 45.567527651] -> 08:46:24 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/DEVICE_ID/messages/devicebound/# | QOS: 1 | TOPIC_NAME: $iothub/twin/res/# | QOS: 0 | TOPIC_NAME: $iothub/twin/PATCH/properties/desired/# | QOS: 0 | TOPIC_NAME: $iothub/methods/POST/# | QOS: 0
[ 46.569427509] <- 08:46:25 SUBACK | PACKET_ID: 2 | RETURN_CODE: 1 | RETURN_CODE: 0 | RETURN_CODE: 0 | RETURN_CODE: 0
[ 48.572565816] -> 08:46:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=3 | PAYLOAD_LEN: 641
[ 48.573546609] -> 08:46:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 4 | PAYLOAD_LEN: 27
2> [ 49.575476930] <- 08:46:28 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=3&$version=4389 | PAYLOAD_LEN: 0
[ 49.576411645] <- 08:46:28 PUBACK | PACKET_ID: 4
[ 50.579360945] -> 08:46:29 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property2 | PACKET_ID: 5 | PAYLOAD_LEN: 15
[ 51.580685345] <- 08:46:30 PUBACK | PACKET_ID: 5
[ 52.583616945] -> 08:46:31 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 6 | PAYLOAD_LEN: 27
[ 53.585473456] <- 08:46:32 PUBACK | PACKET_ID: 6
[ 54.588386581] -> 08:46:33 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 7 | PAYLOAD_LEN: 27
[ 55.590272749] <- 08:46:34 PUBACK | PACKET_ID: 7
[ 56.594041728] -> 08:46:35 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 8 | PAYLOAD_LEN: 27
[ 57.593989903] <- 08:46:36 PUBACK | PACKET_ID: 8
[ 58.596927606] -> 08:46:37 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 9 | PAYLOAD_LEN: 27
[ 59.598760421] <- 08:46:38 PUBACK | PACKET_ID: 9
[ 60.601564292] -> 08:46:39 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 10 | PAYLOAD_LEN: 27
[ 61.603403135] <- 08:46:40 PUBACK | PACKET_ID: 10
[ 62.606331610] -> 08:46:41 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 11 | PAYLOAD_LEN: 27
[ 63.608188053] <- 08:46:42 PUBACK | PACKET_ID: 11
[ 64.611592600] -> 08:46:43 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 12 | PAYLOAD_LEN: 27
[ 65.612709957] <- 08:46:44 PUBACK | PACKET_ID: 12
[ 66.614562054] -> 08:46:45 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 13 | PAYLOAD_LEN: 27
[ 67.616425515] <- 08:46:46 PUBACK | PACKET_ID: 13
[ 68.619179754] -> 08:46:47 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property1 | PACKET_ID: 14 | PAYLOAD_LEN: 27
[ 69.620715625] <- 08:46:48 PUBACK | PACKET_ID: 14
[ 70.623633040] -> 08:46:49 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property3 | PACKET_ID: 15 | PAYLOAD_LEN: 12
[ 71.625524929] <- 08:46:50 PUBACK | PACKET_ID: 15
[ 72.628470044] -> 08:46:51 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property4 | PACKET_ID: 16 | PAYLOAD_LEN: 12
[ 73.630704558] <- 08:46:52 PUBACK | PACKET_ID: 16
[ 97.666315532] -> 08:47:16 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property5 | PACKET_ID: 17 | PAYLOAD_LEN: 31
[ 98.668167150] <- 08:47:17 PUBACK | PACKET_ID: 17
[ 127.698133064] -> 08:47:46 PINGREQ
[ 128.699889450] <- 08:47:47 PINGRESP
[ 157.729340317] -> 08:48:16 PINGREQ
[ 158.730658010] <- 08:48:17 PINGRESP
3> [ 181.754237367] <- 08:48:40 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/PATCH/properties/desired/?$version=82 | PAYLOAD_LEN: 60
[ 187.761150435] -> 08:48:46 PINGREQ
[ 188.762912149] <- 08:48:47 PINGRESP
[ 217.793573803] -> 08:49:16 PINGREQ
[ 218.795333660] <- 08:49:17 PINGRESP
[ 247.824732842] -> 08:49:47 PINGREQ
[ 248.826488295] <- 08:49:48 PINGRESP
[ 277.855858763] -> 08:50:17 PINGREQ
[ 278.857618024] <- 08:50:18 PINGRESP
[ 307.887220506] -> 08:50:47 PINGREQ
[ 308.888969291] <- 08:50:48 PINGRESP
[ 337.930616423] -> 08:51:17 PINGREQ
[ 338.932378470] <- 08:51:18 PINGRESP
4> [ 344.941159513] -> 08:51:24 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/DEVICE_ID/messages/events/name=property3 | PACKET_ID: 18 | PAYLOAD_LEN: 12
[ 345.943013553] <- 08:51:25 PUBACK | PACKET_ID: 18
[ 374.972279856] -> 08:51:54 PINGREQ
[ 375.974021688] <- 08:51:55 PINGRESP
[ 404.2389891] -> 08:52:23 PINGREQ
[ 405.4136534] <- 08:52:24 PINGRESP
[ 434.33375355] -> 08:52:53 PINGREQ
[ 435.35107823] <- 08:52:54 PINGRESP
[ 464.63233466] -> 08:53:23 PINGREQ
[ 465.64970930] <- 08:53:24 PINGRESP
5> [ 467.68099813] <- 08:53:26 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/PATCH/properties/desired/?$version=83 | PAYLOAD_LEN: 60
[ 494.96945326] -> 08:53:53 PINGREQ
[ 495.98697005] <- 08:53:54 PINGRESP
[ 524.129620044] -> 08:54:23 PINGREQ
[ 525.130673387] <- 08:54:24 PINGRESP
[ 554.162292094] -> 08:54:53 PINGREQ
[ 555.164045176] <- 08:54:54 PINGRESP
[ 584.194539176] -> 08:55:23 PINGREQ
[ 585.196293519] <- 08:55:24 PINGRESP
[ 614.225223626] -> 08:55:53 PINGREQ
[ 615.226975883] <- 08:55:54 PINGRESP
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment