mqtt and file upload from same device

JustElectron commented 3 years ago

Hi

I am trying to add support for IoT Hub for an older device, but I have run into an issue that I hope you can help me with. The issue started when trying to send mqtt messages and file uploads from the same device.

I have the following setup: sdk version: 2018-03-16 openssl version: 1.0.2o The device is using sas tokens at the moment, but the plan is to change to self signed x509 before release. Due to the implementation being on an older device, I unfortunately am not able to update to a newer sdk or openssl. So I really hope that the issue is due to something I am doing wrong.

Here is a snip to get an idea of what I am doing.

int do_work(IOTHUB_CLIENT_LL_HANDLE *client_handle, char *taskname);
{
    size_t reportedStateSize;
    char *reportedState;
    IOTHUB_MESSAGE_HANDLE message_handle;

    reportedState = get_data();

    if (!strcmp(task_name, send_mqtt_message))
    {
        is_message = 1;
        message_handle = IoTHubMessage_CreateFromString(reportedState);

        // Set Message property
        IoTHubMessage_SetMessageId(message_handle, task_name);
        IoTHubMessage_SetCorrelationId(message_handle, "CORE_ID");
        IoTHubMessage_SetContentTypeSystemProperty(message_handle, "application%2Fjson");
        IoTHubMessage_SetContentEncodingSystemProperty(message_handle, "utf-8");

        IoTHubClient_LL_SendEventAsync(*client_handle, message_handle, send_confirm_callback, &rc);
     }
    else if(!strcmp(task_name, https_file_upload))
    {
        /////////////////////
       // Actual code reads some file into buffer and sets lSize
       /////////////////////
        if (IoTHubClient_LL_UploadToBlob(*client_handle, log_path, buffer, lSize) != IOTHUB_CLIENT_OK)
        {
            (void)printf("hello world failed to upload\n");
        }
        else
        {
            (void)printf("%s has been created\n", log_path);
        }
    else
    {
        reportedStateSize = strlen(reportedState);
        IoTHubClient_LL_SendReportedState(*client_handle, (const unsigned char*)reportedState, reportedStateSize, 
            reportedStateCallback, &rc);
    }

    while (g_continueRunning)
    {
        IoTHubClient_LL_DoWork(*client_handle);
        ThreadAPI_Sleep(10);
    };

    if (is_message)
    {
        IoTHubMessage_Destroy(message_handle);
    }

    free(reportedState);
    g_continueRunning = 1;
}

int main()
{
char *connectionString;
int use_mqtt = 1;

IOTHUB_CLIENT_LL_HANDLE mqttClientHandle;

// Generate connection string from configs.
_create_connection_string(&connectionString);

rc = platform_init();

if (rc != 0)
{
    (void)printf("Failed to initialize the platform.\r\n");
}

// Extract certificate from file
char *mqtt_certificate;
FILE *fp;
long lsize;

fp = fopen(IOT_ROOT_CERT_FILE, "r");
if( !fp ) perror("No IoT root certificate found."),exit(1);

fseek( fp , 0L , SEEK_END);
lsize = ftell( fp );
rewind( fp );

/* allocate memory for entire content */
mqtt_certificate = calloc( 1, lsize+1 );
if( !mqtt_certificate ) fclose(fp),fputs("memory alloc fails",stderr),exit(1);

/* copy the file into the buffer */
if(1 != fread( mqtt_certificate , lsize, 1 , fp))
{
    free(mqtt_certificate);
    fputs("entire read fails",stderr),exit(1);
}
fclose(fp);

int keepalive = 1*60*60;
bool traceOn = true;
//bool urlEncodeOn = true;

if (use_mqtt)
{
    mqttClientHandle = IoTHubClient_LL_CreateFromConnectionString(connectionString, MQTT_Protocol);

    if (mqttClientHandle == NULL)
    {
        printf("ERROR: mqttClientHandle is NULL!\r\n");
    }

    if (IoTHubClient_LL_SetOption(mqttClientHandle, OPTION_LOG_TRACE, &traceOn) != IOTHUB_CLIENT_OK)
    {
        printf("Failure to set option \"TraceOn\"\r\n");
    }

    if (IoTHubClient_LL_SetOption(mqttClientHandle, OPTION_TRUSTED_CERT, mqtt_certificate) != IOTHUB_CLIENT_OK)
    {
        printf("failure to set option \"TrustedCerts\"\r\n");
    }

    if (IoTHubClient_LL_SetOption(mqttClientHandle, OPTION_KEEP_ALIVE, &keepalive) != IOTHUB_CLIENT_OK)
    {
        printf("Failure to set option \"KeepAlive\"\r\n");
    }

    IoTHubClient_LL_SetDeviceTwinCallback(mqttClientHandle, deviceTwinCallback, mqttClientHandle);
}

while (1)
{
    loop_time = do_work(&mqttClientHandle);

    while (time < time + loop_time) // Loop untill next scheduled task
    {
        ////////////
       /// Errors occur in this loop
      ////////////

        IoTHubClient_LL_DoWork(mqttClientHandle);
        ThreadAPI_Sleep(50);
    }
}
}

The system runs well at first, but after approx. 30 minutes I start getting the following errors:

Error: Time:Mon Jan 11 13:47:11 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:log_ERR_get_error Line:425 Failed allocating OpenSSL context.
Error: Time:Mon Jan 11 13:47:11 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:log_ERR_get_error Line:432   [0] error:140A90F1:lib(20):func(169):reason(241)
Error: Time:Mon Jan 11 13:47:11 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:tlsio_openssl_open Line:1243 Failed creating the OpenSSL instance.
Error: Time:Mon Jan 11 13:47:11 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/umqtt/src/mqtt_client.c Func:mqtt_client_connect Line:980 Error: io_open failed
Error: Time:Mon Jan 11 13:47:11 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:1787 failure connecting to address iot-cap-dev-westeu-01.azure-devices.net.

I have tried using a seperate client handler for mqtt and http, but with the same issue. I have changed to only using the mqtt handler as this seems to be the correct way according to #276.

I think this issue is similar to #709 but the cause for the issue was never described.

Many thanks Andreas Rønning

ewertons commented 3 years ago

@JustElectron ,

note that the Azure IoT Hub does not support two endpoints connected with the same device ID. Attempting to do that causes both applications to keep disconnecting each other from the Azure IoT Hub. So you must have just one unique device ID per device client instance.

One important information is that upload to blob uses HTTP to connect to Azure Blob Storage. So even if you use MQTT to connect to the Azure IoT Hub, behind the scenes it will use HTTP for Blob Storage.

Now the issue you posted above could be related to a reconnection gone wrong. Could you please provide full logs from the beginning all the way to past when the error occurs? Also, try running the code:

without changing the MQTT keep alives (the period you are setting seems way too long. That will impact capacity of the client to detect lack of connection);
Run DoWork at every 100 milliseconds instead of ten milliseconds.

JustElectron commented 3 years ago

I can provide a bit of my use case if that helps to understand what I am trying to achive. The device is running on a satellite connection where you sometimes pay for the amount of data sent. Therefore we are trying to reduce the amount of data used. Often the time between two messages can be 1 hour. The product previously generated a diagnostic report which was sent by email at a set interval. We now want to split the diagnostic report into some groups which will be sent at different interval and for some of the groups when a change occurs. These data have different structures, which is why I want them to be sent to different endpoints. Some examples are: events - Sent as mqtt message. mostly static configurations. e.g. hostname, serial number, etc. - Sent as device twin updates. System logs - Sent as file upload.

the Azure IoT Hub does not support two endpoints connected with the same device ID.

With endpoint do you mean protocol or file upload, device twin, D2C messages, etc.? So would I need two device ID's like deviceIDmqtt and deviceIDhttp or deviceIDFileUpload, deviceIDDeviceTwin and deviceIDMessages?

Here is the log from start to first error. Unfortunately I don't have CURL_VERBOSE on when using only the mqtt client handle. I can reproduce the error using a separate http client handle with the same connection string if needed?

2021-01-11 14:22:59 Getting data: cfg.mqtt.post
2021-01-11 14:22:59 Creating post
2021-01-11 14:23:00 Compressed size is: 916
2021-01-11 14:23:00 -> 14:23:00 CONNECT | VER: 4 | KEEPALIVE: 3600 | FLAGS: 192 | USERNAME: iot-cap-dev-westeu-01.azure-devices.net/antenna-test/api-version=2016-11-14&DeviceClientType=iothubclient%2f1.2.1%20(native%3b%20Linux%3b%20armv5tejl) | PWD: XXXX | CLEAN: 0
2021-01-11 14:23:00 <- 14:23:00 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
2021-01-11 14:23:00 -> 14:23:00 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: $iothub/twin/res/# | QOS: 0 | TOPIC_NAME: $iothub/twin/PATCH/properties/desired/# | QOS: 0
2021-01-11 14:23:00 -> 14:23:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.post&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 3 | PAYLOAD_LEN: 9
2021-01-11 14:23:00 <- 14:23:00 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0 | RETURN_CODE: 0
2021-01-11 14:23:00 -> 14:23:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/GET/?$rid=4
2021-01-11 14:23:00 <- 14:23:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/200/?$rid=4 | PAYLOAD_LEN: 23926
2021-01-11 14:23:00 Device Twin update received (state=DEVICE_TWIN_UPDATE_COMPLETE, size=23926)
2021-01-11 14:23:00 <- 14:23:00 PUBACK | PACKET_ID: 3
2021-01-11 14:23:00 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-11 14:23:00 Getting data: cfg.mqtt.event
2021-01-11 14:23:00 Creating event
2021-01-11 14:23:01 Compressed size is: 1214
2021-01-11 14:23:01 -> 14:23:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.event&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 5 | PAYLOAD_LEN: 179
2021-01-11 14:23:01 <- 14:23:01 PUBACK | PACKET_ID: 5
2021-01-11 14:23:01 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-11 14:23:01 Getting data: cfg.mqtt.boards
2021-01-11 14:23:01 -> 14:23:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=6 | PAYLOAD_LEN: 980
2021-01-11 14:23:01 <- 14:23:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=6&$version=652 | PAYLOAD_LEN: 0
2021-01-11 14:23:01 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:01 Getting data: cfg.mqtt.syslog
2021-01-11 14:23:01 Written 7361 lines to file
2021-01-11 14:23:01 Original size 1104673
2021-01-11 14:23:05 Compressed size 82987, Sending 20746 bytes
2021-01-11 14:23:10 syslog/iot_syslog_1610374981.gz has been created
2021-01-11 14:23:10 -> 14:23:10 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.syslog&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 7 | PAYLOAD_LEN: 31
2021-01-11 14:23:10 <- 14:23:10 PUBACK | PACKET_ID: 7
2021-01-11 14:23:10 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-11 14:23:10 Getting data: cfg.mqtt.general
2021-01-11 14:23:10 -> 14:23:10 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=8 | PAYLOAD_LEN: 304
2021-01-11 14:23:10 <- 14:23:10 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=8&$version=653 | PAYLOAD_LEN: 0
2021-01-11 14:23:10 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:10 Getting data: cfg.mqtt.hardware
2021-01-11 14:23:10 -> 14:23:10 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=9 | PAYLOAD_LEN: 142
2021-01-11 14:23:10 <- 14:23:10 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=9&$version=654 | PAYLOAD_LEN: 0
2021-01-11 14:23:10 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:10 Getting data: cfg.mqtt.supp.identifiers
2021-01-11 14:23:11 -> 14:23:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=10 | PAYLOAD_LEN: 208
2021-01-11 14:23:11 <- 14:23:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=10&$version=655 | PAYLOAD_LEN: 0
2021-01-11 14:23:11 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:11 Getting data: cfg.mqtt.supp.buclnb
2021-01-11 14:23:11 -> 14:23:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=11 | PAYLOAD_LEN: 761
2021-01-11 14:23:11 <- 14:23:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=11&$version=656 | PAYLOAD_LEN: 0
2021-01-11 14:23:11 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:11 Getting data: cfg.mqtt.supp.setup
2021-01-11 14:23:11 -> 14:23:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=12 | PAYLOAD_LEN: 640
2021-01-11 14:23:11 <- 14:23:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=12&$version=657 | PAYLOAD_LEN: 0
2021-01-11 14:23:11 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:11 Getting data: cfg.mqtt.supp.calibration
2021-01-11 14:23:12 -> 14:23:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=13 | PAYLOAD_LEN: 210
2021-01-11 14:23:12 <- 14:23:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=13&$version=658 | PAYLOAD_LEN: 0
2021-01-11 14:23:12 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:12 Getting data: cfg.mqtt.supp.network
2021-01-11 14:23:12 -> 14:23:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=14 | PAYLOAD_LEN: 5308
2021-01-11 14:23:12 <- 14:23:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=14&$version=659 | PAYLOAD_LEN: 0
2021-01-11 14:23:12 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:12 Getting data: cfg.mqtt.supp.modems
2021-01-11 14:23:12 -> 14:23:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=15 | PAYLOAD_LEN: 3280
2021-01-11 14:23:12 <- 14:23:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=15&$version=660 | PAYLOAD_LEN: 0
2021-01-11 14:23:12 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:12 Getting data: cfg.mqtt.supp.satellites
2021-01-11 14:23:13 -> 14:23:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=16 | PAYLOAD_LEN: 6576
2021-01-11 14:23:13 <- 14:23:13 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=16&$version=661 | PAYLOAD_LEN: 0
2021-01-11 14:23:13 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:13 Getting data: cfg.mqtt.supp.operation
2021-01-11 14:23:13 -> 14:23:13 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=17 | PAYLOAD_LEN: 2771
2021-01-11 14:23:13 <- 14:23:13 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=17&$version=662 | PAYLOAD_LEN: 0
2021-01-11 14:23:13 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:13 Getting data: cfg.mqtt.vesselstats.slow
2021-01-11 14:23:16 Compressed size is: 12422
2021-01-11 14:23:16 -> 14:23:16 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.vesselstats.slow&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 18 | PAYLOAD_LEN: 152
2021-01-11 14:23:16 <- 14:23:16 PUBACK | PACKET_ID: 18
2021-01-11 14:23:16 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-11 14:23:16 Getting data: cfg.mqtt.blockingzones
2021-01-11 14:23:17 -> 14:23:16 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=19 | PAYLOAD_LEN: 2601
2021-01-11 14:23:17 <- 14:23:17 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=19&$version=663 | PAYLOAD_LEN: 0
2021-01-11 14:23:17 Device Twin reported properties update completed with result: 204
2021-01-11 14:23:17 Getting data: cfg.mqtt.accumstats
2021-01-11 14:23:17 Compressed size is: 426
2021-01-11 14:23:17 -> 14:23:17 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.accumstats&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 20 | PAYLOAD_LEN: 264
2021-01-11 14:23:17 <- 14:23:17 PUBACK | PACKET_ID: 20
2021-01-11 14:23:17 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-11 14:23:17 Getting data: cfg.mqtt.processlog
2021-01-11 14:23:17 Reported state Null
2021-01-11 14:23:17 Sleep for: 163
2021-01-11 14:26:00 Getting data: cfg.mqtt.event
2021-01-11 14:26:00 Reported state Null
2021-01-11 14:26:00 Sleep for: 240
2021-01-11 14:30:00 Getting data: cfg.mqtt.vesselstats.slow
2021-01-11 14:30:02 Reported state Null
2021-01-11 14:30:02 Sleep for: 60
2021-01-11 14:31:00 Getting data: cfg.mqtt.event
2021-01-11 14:31:00 Reported state Null
2021-01-11 14:31:00 Sleep for: 120
2021-01-11 14:33:00 Getting data: cfg.mqtt.syslog
2021-01-11 14:33:00 Written 2 lines to file
2021-01-11 14:33:00 Reported state Null
2021-01-11 14:33:00 Sleep for: 180
2021-01-11 14:36:00 Getting data: cfg.mqtt.event
2021-01-11 14:36:00 Reported state Null
2021-01-11 14:36:00 Sleep for: 300
2021-01-11 14:41:00 Getting data: cfg.mqtt.event
2021-01-11 14:41:00 Reported state Null
2021-01-11 14:41:00 Sleep for: 300
2021-01-11 14:46:00 Getting data: cfg.mqtt.event
2021-01-11 14:46:00 Reported state Null
2021-01-11 14:46:00 Sleep for: 300
2021-01-11 14:51:00 Getting data: cfg.mqtt.event
2021-01-11 14:51:00 Reported state Null
2021-01-11 14:51:00 Sleep for: 300
2021-01-11 14:53:09 Error: Time:Mon Jan 11 14:53:02 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:log_ERR_get_error Line:425 Failed allocating OpenSSL context.
2021-01-11 14:53:09 Error: Time:Mon Jan 11 14:53:02 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:log_ERR_get_error Line:432   [0] error:140A90F1:lib(20):func(169):reason(241)
2021-01-11 14:53:09 Error: Time:Mon Jan 11 14:53:02 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:tlsio_openssl_open Line:1243 Failed creating the OpenSSL instance.
2021-01-11 14:53:09 Error: Time:Mon Jan 11 14:53:02 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/umqtt/src/mqtt_client.c Func:mqtt_client_connect Line:980 Error: io_open failed
2021-01-11 14:53:09 Error: Time:Mon Jan 11 14:53:02 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:1787 failure connecting to address iot-cap-dev-westeu-01.azure-devices.net.

Please correct me if I have misunderstood this, but I thought that the keepalive was the requested time for the server to keep the connection open between sending messages, DT updates, etc. As it takes a fair amount of data to establish a connection I want to limit the certificate renegotiations as much as possible.

Also, try running the code:

I will try that and get back to you.

JustElectron commented 3 years ago

Here is an updated log without setting keepalive and with DoWork each 100 ms.

2021-01-13 08:26:47 Getting data: cfg.mqtt.post
2021-01-13 08:26:47 Creating post
2021-01-13 08:26:49 -> 08:26:48 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: iot-cap-dev-westeu-01.azure-devices.net/antenna-test/api-version=2016-11-14&DeviceClientType=iothubclient%2f1.2.1%20(native%3b%20Linux%3b%20armv5tejl) | PWD: XXXX | CLEAN: 0
2021-01-13 08:26:49 <- 08:26:48 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
2021-01-13 08:26:49 -> 08:26:48 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: $iothub/twin/res/# | QOS: 0 | TOPIC_NAME: $iothub/twin/PATCH/properties/desired/# | QOS: 0
2021-01-13 08:26:49 <- 08:26:49 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0 | RETURN_CODE: 0
2021-01-13 08:26:49 -> 08:26:49 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/GET/?$rid=3
2021-01-13 08:26:49 -> 08:26:49 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.post&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 4 | PAYLOAD_LEN: 5421
2021-01-13 08:26:49 <- 08:26:49 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/200/?$rid=3 | PAYLOAD_LEN: 23926
2021-01-13 08:26:49 Device Twin update received (state=DEVICE_TWIN_UPDATE_COMPLETE, size=23926)
2021-01-13 08:26:49 <- 08:26:49 PUBACK | PACKET_ID: 4
2021-01-13 08:26:49 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-13 08:26:49 Getting data: cfg.mqtt.event
2021-01-13 08:26:49 Creating event
2021-01-13 08:26:50 -> 08:26:50 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.event&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 5 | PAYLOAD_LEN: 5679
2021-01-13 08:26:50 <- 08:26:50 PUBACK | PACKET_ID: 5
2021-01-13 08:26:50 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-13 08:26:50 Getting data: cfg.mqtt.boards
2021-01-13 08:26:50 -> 08:26:50 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=6 | PAYLOAD_LEN: 980
2021-01-13 08:26:50 <- 08:26:50 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=6&$version=664 | PAYLOAD_LEN: 0
2021-01-13 08:26:50 Device Twin reported properties update completed with result: 204
2021-01-13 08:26:50 Getting data: cfg.mqtt.syslog
2021-01-13 08:26:51 Written 7466 lines to file
2021-01-13 08:26:51 Original size 1119972
2021-01-13 08:26:55 Compressed size 84482, Sending 21120 bytes
2021-01-13 08:27:00 syslog/iot_syslog_1610526411.gz has been created
2021-01-13 08:27:00 -> 08:26:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.syslog&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 7 | PAYLOAD_LEN: 31
2021-01-13 08:27:00 <- 08:26:59 PUBACK | PACKET_ID: 7
2021-01-13 08:27:00 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-13 08:27:00 Getting data: cfg.mqtt.general
2021-01-13 08:27:00 -> 08:27:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=8 | PAYLOAD_LEN: 304
2021-01-13 08:27:00 <- 08:27:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=8&$version=665 | PAYLOAD_LEN: 0
2021-01-13 08:27:00 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:00 Getting data: cfg.mqtt.hardware
2021-01-13 08:27:01 -> 08:27:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=9 | PAYLOAD_LEN: 142
2021-01-13 08:27:01 <- 08:27:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=9&$version=666 | PAYLOAD_LEN: 0
2021-01-13 08:27:01 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:01 Getting data: cfg.mqtt.supp.identifiers
2021-01-13 08:27:01 -> 08:27:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=10 | PAYLOAD_LEN: 208
2021-01-13 08:27:01 <- 08:27:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=10&$version=667 | PAYLOAD_LEN: 0
2021-01-13 08:27:01 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:01 Getting data: cfg.mqtt.supp.buclnb
2021-01-13 08:27:02 -> 08:27:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=11 | PAYLOAD_LEN: 761
2021-01-13 08:27:02 <- 08:27:02 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=11&$version=668 | PAYLOAD_LEN: 0
2021-01-13 08:27:02 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:02 Getting data: cfg.mqtt.supp.setup
2021-01-13 08:27:02 -> 08:27:02 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=12 | PAYLOAD_LEN: 640
2021-01-13 08:27:02 <- 08:27:02 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=12&$version=669 | PAYLOAD_LEN: 0
2021-01-13 08:27:02 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:02 Getting data: cfg.mqtt.supp.calibration
2021-01-13 08:27:03 -> 08:27:02 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=13 | PAYLOAD_LEN: 210
2021-01-13 08:27:03 <- 08:27:03 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=13&$version=670 | PAYLOAD_LEN: 0
2021-01-13 08:27:03 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:03 Getting data: cfg.mqtt.supp.network
2021-01-13 08:27:03 -> 08:27:03 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=14 | PAYLOAD_LEN: 5308
2021-01-13 08:27:03 <- 08:27:03 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=14&$version=671 | PAYLOAD_LEN: 0
2021-01-13 08:27:03 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:03 Getting data: cfg.mqtt.supp.modems
2021-01-13 08:27:04 -> 08:27:03 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=15 | PAYLOAD_LEN: 3280
2021-01-13 08:27:04 <- 08:27:04 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=15&$version=672 | PAYLOAD_LEN: 0
2021-01-13 08:27:04 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:04 Getting data: cfg.mqtt.supp.satellites
2021-01-13 08:27:04 -> 08:27:04 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=16 | PAYLOAD_LEN: 6576
2021-01-13 08:27:04 <- 08:27:04 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=16&$version=673 | PAYLOAD_LEN: 0
2021-01-13 08:27:04 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:04 Getting data: cfg.mqtt.supp.operation
2021-01-13 08:27:05 -> 08:27:04 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=17 | PAYLOAD_LEN: 2774
2021-01-13 08:27:05 <- 08:27:05 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=17&$version=674 | PAYLOAD_LEN: 0
2021-01-13 08:27:05 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:05 Getting data: cfg.mqtt.vesselstats.slow
2021-01-13 08:27:08 -> 08:27:07 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.vesselstats.slow&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 18 | PAYLOAD_LEN: 195996
2021-01-13 08:27:08 <- 08:27:08 PUBACK | PACKET_ID: 18
2021-01-13 08:27:08 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-13 08:27:08 Getting data: cfg.mqtt.blockingzones
2021-01-13 08:27:09 -> 08:27:08 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=19 | PAYLOAD_LEN: 2601
2021-01-13 08:27:09 <- 08:27:09 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/204/?$rid=19&$version=675 | PAYLOAD_LEN: 0
2021-01-13 08:27:09 Device Twin reported properties update completed with result: 204
2021-01-13 08:27:09 Getting data: cfg.mqtt.accumstats
2021-01-13 08:27:09 -> 08:27:09 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/antenna-test/messages/events/%24.cid=CORE_ID&%24.mid=cfg.mqtt.accumstats&%24.ct=application%2Fjson&%24.ce=utf-8 | PACKET_ID: 20 | PAYLOAD_LEN: 1611
2021-01-13 08:27:09 <- 08:27:09 PUBACK | PACKET_ID: 20
2021-01-13 08:27:09 Confirmation callback received with result IOTHUB_CLIENT_CONFIRMATION_OK
2021-01-13 08:27:09 Getting data: cfg.mqtt.processlog
2021-01-13 08:27:09 Reported state Null
2021-01-13 08:27:09 Sleep for: 171
2021-01-13 08:30:00 Getting data: cfg.mqtt.vesselstats.slow
2021-01-13 08:30:02 Reported state Null
2021-01-13 08:30:02 Sleep for: 60
2021-01-13 08:31:00 Getting data: cfg.mqtt.event
2021-01-13 08:31:00 Reported state Null
2021-01-13 08:31:00 Sleep for: 120
2021-01-13 08:33:00 -> 08:31:09 PINGREQ
2021-01-13 08:33:00 <- 08:31:09 PINGRESP
2021-01-13 08:33:00 Getting data: cfg.mqtt.syslog
2021-01-13 08:33:00 Written 0 lines to file
2021-01-13 08:33:00 Reported state Null
2021-01-13 08:33:00 Sleep for: 180
2021-01-13 08:36:00 -> 08:35:09 PINGREQ
2021-01-13 08:36:00 <- 08:35:09 PINGRESP
2021-01-13 08:36:00 Getting data: cfg.mqtt.event
2021-01-13 08:36:00 Reported state Null
2021-01-13 08:36:00 Sleep for: 300
2021-01-13 08:41:00 -> 08:39:09 PINGREQ
2021-01-13 08:41:00 <- 08:39:09 PINGRESP
2021-01-13 08:41:00 Getting data: cfg.mqtt.event
2021-01-13 08:41:00 Reported state Null
2021-01-13 08:41:00 Sleep for: 300
2021-01-13 08:46:00 -> 08:43:09 PINGREQ
2021-01-13 08:46:00 <- 08:43:09 PINGRESP
2021-01-13 08:46:00 Getting data: cfg.mqtt.event
2021-01-13 08:46:00 Reported state Null
2021-01-13 08:46:00 Sleep for: 300
2021-01-13 08:51:00 -> 08:47:09 PINGREQ
2021-01-13 08:51:00 <- 08:47:09 PINGRESP
2021-01-13 08:51:00 Getting data: cfg.mqtt.event
2021-01-13 08:51:00 Reported state Null
2021-01-13 08:51:00 Sleep for: 300
2021-01-13 08:56:00 -> 08:51:09 PINGREQ
2021-01-13 08:56:00 <- 08:51:09 PINGRESP
2021-01-13 08:56:00 -> 08:55:09 PINGREQ
2021-01-13 08:56:00 <- 08:55:09 PINGRESP
2021-01-13 08:56:00 Getting data: cfg.mqtt.event
2021-01-13 08:56:00 Reported state Null
2021-01-13 08:56:00 Sleep for: 300
2021-01-13 09:01:00 -> 08:59:09 PINGREQ
2021-01-13 09:01:00 <- 08:59:09 PINGRESP
2021-01-13 09:01:00 Getting data: cfg.mqtt.event
2021-01-13 09:01:00 Reported state Null
2021-01-13 09:01:00 Sleep for: 120
2021-01-13 09:03:00 Getting data: cfg.mqtt.syslog
2021-01-13 09:03:00 Written 2 lines to file
2021-01-13 09:03:00 Reported state Null
2021-01-13 09:03:00 Sleep for: 180
2021-01-13 09:06:00 -> 09:03:09 PINGREQ
2021-01-13 09:06:00 <- 09:03:09 PINGRESP
2021-01-13 09:06:00 Getting data: cfg.mqtt.event
2021-01-13 09:06:00 Reported state Null
2021-01-13 09:06:00 Sleep for: 300
2021-01-13 09:11:00 -> 09:07:09 PINGREQ
2021-01-13 09:11:00 <- 09:07:09 PINGRESP
2021-01-13 09:11:00 Getting data: cfg.mqtt.event
2021-01-13 09:11:00 Reported state Null
2021-01-13 09:11:00 Sleep for: 300
2021-01-13 09:14:56 -> 09:11:09 PINGREQ
2021-01-13 09:14:56 <- 09:11:09 PINGRESP
2021-01-13 09:14:56 -> 09:14:49 DISCONNECT
2021-01-13 09:14:56 Error: Time:Wed Jan 13 09:14:49 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:log_ERR_get_error Line:425 Failed allocating OpenSSL context.
2021-01-13 09:14:56 Error: Time:Wed Jan 13 09:14:49 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:log_ERR_get_error Line:432   [0] error:140A90F1:lib(20):func(169):reason(241)
2021-01-13 09:14:56 Error: Time:Wed Jan 13 09:14:49 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/c-utility/src/tlsio_openssl.c Func:tlsio_openssl_open Line:1243 Failed creating the OpenSSL instance.
2021-01-13 09:14:56 Error: Time:Wed Jan 13 09:14:49 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/umqtt/src/mqtt_client.c Func:mqtt_client_connect Line:980 Error: io_open failed
2021-01-13 09:14:56 Error: Time:Wed Jan 13 09:14:49 2021 File:/work/jenkins2/jenkins/workspace/tt7090_vsat_buildroot/output/build/azure-iot-sdk-c-2018-03-16/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:1787 failure connecting to address iot-cap-dev-westeu-01.azure-devices.net.

JustElectron commented 3 years ago

I have found a solution to my problem. It seemed like it was an issue on my device. I created a minimum implementation based on the file upload and mqtt message sample. It ran fine on my virtual machine, but when running on my device it was not able to reconnect. I think there was some issues when sharing tls resources in the same process. I have split the mqtt client and http client into separate processes and it now runs and can automatically reconnect.

I still have some issues with the duration of the mqtt sessions. It only runs approx. 1h 15m before not receiving a ping response. I suspect that it might be because the connection is not used enough.

Azure / azure-iot-sdk-c

mqtt and file upload from same device #1822