Asynchronous notification callback with resource payload was not receiving to web application if resource payload size greater than 512 bytes

Hi Team,

We are working on DISCO-L475VG-IOT01A board with WiFi module Inventek ISM43362-M3G-L44 (802.11 b/g/n compliant) for ARM mbed pelion cloud.

issue : Asynchronous notification callback with resource payload was not receiving to web application if resource payload size greater than 512 bytes

We are posting a payload of greater than 512 bytes to resource object using mbed client to cloud connect, but we are not receiving the notification call back to our web app instead we just reeving callback aync-responses with message id with a mage-age: 60 only.

could you please let me know what may be issue.

Thanks &Regards
Praveen.Thota

Hi Praveen,
Is your client having COAP BLOCKWISE feature enabled?
Is it working for smaller payload? If possible you can post your client log trace for the issue so that we can confirm if client is sending the data correctly and then we can continue checking if its a cloud side issue.

Regards,
Yogesh

Hi Yogesh,

Thanks for your response.

i am not enabled COAP BLOCKWISE feature and i am using the configuration of sample example with only changes of wifi user name and password…
yes it was working for payload of size less than 512 bytes.

one more observation after posting more than 512 bytes some times application was loosing network connection and not reconnecting.

[SMCC] Error occurred : MbedCloudClient::ConnectSecureConnectionFailed
[SMCC] Error code : 11
[SMCC] Error details : Client in reconnection mode SecureConnectionFailed

[SMCC] Error occurred : MbedCloudClient::ConnectSecureConnectionFailed
[SMCC] Error code : 11
[SMCC] Error details : Client in reconnection mode SecureConnectionFailed

below was the log for greater than 512 bytes posted to a resource . i can clearly see the payload len as zero.

//sample code snippet where i set the hard coded value by calling setvalue.
payload_res->set_value((const char *)“9020c702400c53544d2d444953434f2d3031598e0240100e003a61797ae0931528ae5f3e22e0e240100e003a61797ae093153570105c93cd7140100e003a61797ae093154224a43c1afc8040100e003a61797ae093154324a43c1afc8140100e003a61797ae093154570105cdb17f140100e003a61797ae093154624a43c1afcc040100e003a61797ae093154624a43c1afcc140100e003a61797ae0931549b4e9b033e63140100e003a61797ae093155188dc9657070440100e003a61797ae093155324a43c1b010140100e003a61797ae093155424a43c1b010040100e003a61797ae093155424a43c1afc0140100e003a61797ae0931555384b76030b0f40100e003a61797ae093155732cda7b0288640100e003a61797ae093155932cda7b20e0b4226401e736c616d43616c63756c61746f722e43616c63756c617465456e61626c65410474727565”);

[DBG ][mClt]: M2MReportHandler::set_notification_trigger(): 0
[DBG ][mClt]: M2MReportHandler::schedule_report()
[DBG ][mClt]: M2MReportHandler::report() - current 0.000000, last 1.000000, notify 1, queued 0
[DBG ][mClt]: M2MReportHandler::report()- send with VALUE change
[DBG ][mClt]: M2MNsdlInterface::observation_to_be_sent() uri 3336/0/5514
[INFO][mClt]: M2MNsdlInterface::send_resource_observation - uri 3336/0/5514
[INFO][mClt]: ======== Outgoing CoAP package ========
[INFO][mClt]: Status: COAP_STATUS_OK
[INFO][mClt]: Code: COAP_MSG_CODE_RESPONSE_CONTENT
[INFO][mClt]: Type: COAP_MSG_TYPE_CONFIRMABLE
[INFO][mClt]: Id: 48953
[INFO][mClt]: Token: 66:80:68:e2
[INFO][mClt]: Content-type: 0
[INFO][mClt]: Payload len: 0
[INFO][mClt]: Max-age: 0
[INFO][mClt]: Observe: 2
[INFO][mClt]: ======== End of CoAP package ========
[DBG ][mClt]: M2MNsdlInterface::send_to_server_callback(data size 12)
[DBG ][mClt]: M2MInterfaceImpl::coap_message_ready
[DBG ][mClt]: M2MInterfaceImpl::internal_event : new state 13
[DBG ][mClt]: M2MInterfaceImpl::state_engine

below was the call where i can see the payloan as 264

[INFO][mClt]: ======== Outgoing CoAP package ========
[INFO][mClt]: Status: COAP_STATUS_OK
[INFO][mClt]: Code: COAP_MSG_CODE_RESPONSE_CONTENT
[INFO][mClt]: Type: COAP_MSG_TYPE_CONFIRMABLE
[INFO][mClt]: Id: 62729
[INFO][mClt]: Token: 41:75:50:47
[INFO][mClt]: Content-type: 0
[INFO][mClt]: Payload len: 264
[INFO][mClt]: Max-age: 0
[INFO][mClt]: Observe: 2
[INFO][mClt]: ======== End of CoAP package ========

A part from above logs some times i am able to observe the below errors in my trace logs

-------------------±-------------------------------------±----------------------
++++++++++++++++++++ Step 8. Update Data on Mbed Cloud ++++++++++++++++++++++++
-------------------±-------------------------------------±----------------------
Update cloud data With Payload : 9020b601400c53544d2d444953434f2d3031597e40100e00c0d801fe6794152fd0040000000040100e00c0d801fe6794154600000000000040100e00c0d801fe67941555fa8fca73bad240100e00c0d801fe679415592cdd96e16e3940100e00c0d801fe67941559ec080b0a020440100e00c0d801fe6794155e0c02050e0f0c40100e00c0d801fe679415609cd643d78af44226401e736c616d43616c63756c61746f722e43616c63756c617465456e61626c65410474727565
[DBG ][mClt]: M2MResourceBase::set_value()
[DBG ][mClt]: M2MReportHandler::set_notification_trigger(): 0
[DBG ][mClt]: M2MReportHandler::schedule_report()
[DBG ][mClt]: M2MReportHandler::report() - current 0.000000, last 1.000000, notify 1, queued 0
[DBG ][mClt]: M2MReportHandler::report()- send with VALUE change
[DBG ][mClt]: M2MNsdlInterface::observation_to_be_sent() uri 3336/0/5514
[INFO][mClt]: M2MNsdlInterface::send_resource_observation - uri 3336/0/5514
[ERR ][coap]: sn_coap_protocol_linked_list_send_msg_store - failed to allocate message!
[DBG ][mClt]: M2MReportHandler::handle_timers()
[DBG ][mClt]: M2MResourceBase::report() - level 1
[DBG ][mClt]: M2MResourceBase::report() - combined level 1
[DBG ][mClt]: M2MResourceBase::report() - resource level

------------------------------ 2--------------------------------------------------------------------------
[INFO][esfs]: esfs_read - enter
[DBG ][PAAL]: arm_uc_paal_update.c:266: ARM_UCP_GetActiveFirmwareDetails
[DBG ][fcc ]: storage.c:441:storage_file_read_with_ctx:<===
[ERR ][PAAL]: arm_uc_pal_flashiap_implementation.c:696: unrecognized firmware header version
[INFO][fcc ]: key_config_manager.c:311:kcm_item_get_data:<=== kcm data size = 1
[ERR ][HUB ]: update_client_hub_state_machine.c:240: Firmware manager GetActiveFirmwareDetails failed error code ERR_NOT_READY
[DBG ][fcc ]: storage.c:360:storage_file_close:===>
[DBG ][HUB ]: update_client_hub_state_machine.c:322: ARM_UC_MONITOR_STATE_IDLE

-----------------------------------------3 -----------------------------------------------------------------------

[INFO][esfs]: esfs_file_size - enter
[DBG ][fcc ]: storage.c:410:storage_file_size_get_with_ctx:<===
[ERR ][fcc ]: storage.c:434:storage_file_read_with_ctx:<=== Buffer too small
[ERR ][fcc ]: key_config_manager.c:309:kcm_item_get_data:Failed reading file from storage (3)
[DBG ][fcc ]: storage.c:360:storage_file_close:===>

DBG ][fcc ]: storage.c:258:storage_file_create:===> file_name_length=24
[INFO][esfs]: esfs_file_size - enter
[INFO][esfs]: esfs_create - enter
[DBG ][fcc ]: storage.c:410:storage_file_size_get_with_ctx:<===
[ERR ][esfs]: esfs_create() - pal_fsFopen() for working dir file failed
[INFO][esfs]: esfs_read - enter
[ERR ][fcc ]: storage.c:283:storage_file_create:File already exist in ESFS (esfs_status 5)
[DBG ][fcc ]: storage.c:441:storage_file_read_with_ctx:<===
[DBG ][fcc ]: storage.c:291:storage_file_create:<===
[INFO][fcc ]: key_config_manager.c:311:kcm_item_get_data:<=== kcm data size = 16
[ERR ][fcc ]: storage.c:131:storage_file_write:<=== Failed to create new file
[DBG ][fcc ]: storage.c:360:storage_file_close:===>
[ERR ][fcc ]: key_config_manager.c:206:kcm_item_store:Failed writing file to storage
[INFO][esfs]: esfs_close - enter
[INFO][fcc ]: key_config_manager.c:210:kcm_item_store:<===
[DBG ][fcc ]: storage.c:369:storage_file_close:<===
[INFO][uccc]: ARM_UC_AddCertificate failed

---------------------4 --------------------------------------------------

[INFO][esfs]: esfs_create - enter
[ERR ][esfs]: esfs_create() - pal_fsFopen() for working dir file failed
[ERR ][fcc ]: storage.c:283:storage_file_create:File already exist in ESFS (esfs_status 5)
[DBG ][fcc ]: storage.c:291:storage_file_create:<===
[ERR ][fcc ]: storage.c:131:storage_file_write:<=== Failed to create new file
[ERR ][fcc ]: key_config_manager.c:206:kcm_item_store:Failed writing file to storage
[INFO][fcc ]: key_config_manager.c:210:kcm_item_store:<===
[ERR ][fcc ]: fcc_dev_flow.c:96:fcc_developer_flow:<=== Store status: 8, Failed to store mbed.UseBootstrap
[SMCC] Developer credentials already exist

Regards
Praveen.Thota

Hi Yogesh,

Thanks for your response.

i am not enabled COAP BLOCKWISE feature and i am using the configuration of sample example with only changes of wifi user name and password…
yes it was working for payload of size less than 512 bytes.

one more observation after posting more than 512 bytes some times application was loosing network connection and not reconnecting.

[SMCC] Error occurred : MbedCloudClient::ConnectSecureConnectionFailed
[SMCC] Error code : 11
[SMCC] Error details : Client in reconnection mode SecureConnectionFailed

[SMCC] Error occurred : MbedCloudClient::ConnectSecureConnectionFailed
[SMCC] Error code : 11
[SMCC] Error details : Client in reconnection mode SecureConnectionFailed

below was the log for greater than 512 bytes posted to a resource . i can clearly see the payload len as zero.

//sample code snippet where i set the hard coded value by calling setvalue.
payload_res->set_value((const char *)“9020c702400c53544d2d444953434f2d3031598e0240100e003a61797ae0931528ae5f3e22e0e240100e003a61797ae093153570105c93cd7140100e003a61797ae093154224a43c1afc8040100e003a61797ae093154324a43c1afc8140100e003a61797ae093154570105cdb17f140100e003a61797ae093154624a43c1afcc040100e003a61797ae093154624a43c1afcc140100e003a61797ae0931549b4e9b033e63140100e003a61797ae093155188dc9657070440100e003a61797ae093155324a43c1b010140100e003a61797ae093155424a43c1b010040100e003a61797ae093155424a43c1afc0140100e003a61797ae0931555384b76030b0f40100e003a61797ae093155732cda7b0288640100e003a61797ae093155932cda7b20e0b4226401e736c616d43616c63756c61746f722e43616c63756c617465456e61626c65410474727565”);

[DBG ][mClt]: M2MReportHandler::set_notification_trigger(): 0
[DBG ][mClt]: M2MReportHandler::schedule_report()
[DBG ][mClt]: M2MReportHandler::report() - current 0.000000, last 1.000000, notify 1, queued 0
[DBG ][mClt]: M2MReportHandler::report()- send with VALUE change
[DBG ][mClt]: M2MNsdlInterface::observation_to_be_sent() uri 3336/0/5514
[INFO][mClt]: M2MNsdlInterface::send_resource_observation - uri 3336/0/5514
[INFO][mClt]: ======== Outgoing CoAP package ========
[INFO][mClt]: Status: COAP_STATUS_OK
[INFO][mClt]: Code: COAP_MSG_CODE_RESPONSE_CONTENT
[INFO][mClt]: Type: COAP_MSG_TYPE_CONFIRMABLE
[INFO][mClt]: Id: 48953
[INFO][mClt]: Token: 66:80:68:e2
[INFO][mClt]: Content-type: 0
[INFO][mClt]: Payload len: 0
[INFO][mClt]: Max-age: 0
[INFO][mClt]: Observe: 2
[INFO][mClt]: ======== End of CoAP package ========
[DBG ][mClt]: M2MNsdlInterface::send_to_server_callback(data size 12)
[DBG ][mClt]: M2MInterfaceImpl::coap_message_ready
[DBG ][mClt]: M2MInterfaceImpl::internal_event : new state 13
[DBG ][mClt]: M2MInterfaceImpl::state_engine

below was the call where i can see the payloan as 264

[INFO][mClt]: ======== Outgoing CoAP package ========
[INFO][mClt]: Status: COAP_STATUS_OK
[INFO][mClt]: Code: COAP_MSG_CODE_RESPONSE_CONTENT
[INFO][mClt]: Type: COAP_MSG_TYPE_CONFIRMABLE
[INFO][mClt]: Id: 62729
[INFO][mClt]: Token: 41:75:50:47
[INFO][mClt]: Content-type: 0
[INFO][mClt]: Payload len: 264
[INFO][mClt]: Max-age: 0
[INFO][mClt]: Observe: 2
[INFO][mClt]: ======== End of CoAP package ========

A part from above logs some times i am able to observe the below errors in my trace logs

-------------------±-------------------------------------±----------------------
++++++++++++++++++++ Step 8. Update Data on Mbed Cloud ++++++++++++++++++++++++
-------------------±-------------------------------------±----------------------
Update cloud data With Payload : 9020b601400c53544d2d444953434f2d3031597e40100e00c0d801fe6794152fd0040000000040100e00c0d801fe6794154600000000000040100e00c0d801fe67941555fa8fca73bad240100e00c0d801fe679415592cdd96e16e3940100e00c0d801fe67941559ec080b0a020440100e00c0d801fe6794155e0c02050e0f0c40100e00c0d801fe679415609cd643d78af44226401e736c616d43616c63756c61746f722e43616c63756c617465456e61626c65410474727565
[DBG ][mClt]: M2MResourceBase::set_value()
[DBG ][mClt]: M2MReportHandler::set_notification_trigger(): 0
[DBG ][mClt]: M2MReportHandler::schedule_report()
[DBG ][mClt]: M2MReportHandler::report() - current 0.000000, last 1.000000, notify 1, queued 0
[DBG ][mClt]: M2MReportHandler::report()- send with VALUE change
[DBG ][mClt]: M2MNsdlInterface::observation_to_be_sent() uri 3336/0/5514
[INFO][mClt]: M2MNsdlInterface::send_resource_observation - uri 3336/0/5514
[ERR ][coap]: sn_coap_protocol_linked_list_send_msg_store - failed to allocate message!
[DBG ][mClt]: M2MReportHandler::handle_timers()
[DBG ][mClt]: M2MResourceBase::report() - level 1
[DBG ][mClt]: M2MResourceBase::report() - combined level 1
[DBG ][mClt]: M2MResourceBase::report() - resource level

------------------------------ 2--------------------------------------------------------------------------
[INFO][esfs]: esfs_read - enter
[DBG ][PAAL]: arm_uc_paal_update.c:266: ARM_UCP_GetActiveFirmwareDetails
[DBG ][fcc ]: storage.c:441:storage_file_read_with_ctx:<===
[ERR ][PAAL]: arm_uc_pal_flashiap_implementation.c:696: unrecognized firmware header version
[INFO][fcc ]: key_config_manager.c:311:kcm_item_get_data:<=== kcm data size = 1
[ERR ][HUB ]: update_client_hub_state_machine.c:240: Firmware manager GetActiveFirmwareDetails failed error code ERR_NOT_READY
[DBG ][fcc ]: storage.c:360:storage_file_close:===>
[DBG ][HUB ]: update_client_hub_state_machine.c:322: ARM_UC_MONITOR_STATE_IDLE

-----------------------------------------3 -----------------------------------------------------------------------

[INFO][esfs]: esfs_file_size - enter
[DBG ][fcc ]: storage.c:410:storage_file_size_get_with_ctx:<===
[ERR ][fcc ]: storage.c:434:storage_file_read_with_ctx:<=== Buffer too small
[ERR ][fcc ]: key_config_manager.c:309:kcm_item_get_data:Failed reading file from storage (3)
[DBG ][fcc ]: storage.c:360:storage_file_close:===>

DBG ][fcc ]: storage.c:258:storage_file_create:===> file_name_length=24
[INFO][esfs]: esfs_file_size - enter
[INFO][esfs]: esfs_create - enter
[DBG ][fcc ]: storage.c:410:storage_file_size_get_with_ctx:<===
[ERR ][esfs]: esfs_create() - pal_fsFopen() for working dir file failed
[INFO][esfs]: esfs_read - enter
[ERR ][fcc ]: storage.c:283:storage_file_create:File already exist in ESFS (esfs_status 5)
[DBG ][fcc ]: storage.c:441:storage_file_read_with_ctx:<===
[DBG ][fcc ]: storage.c:291:storage_file_create:<===
[INFO][fcc ]: key_config_manager.c:311:kcm_item_get_data:<=== kcm data size = 16
[ERR ][fcc ]: storage.c:131:storage_file_write:<=== Failed to create new file
[DBG ][fcc ]: storage.c:360:storage_file_close:===>
[ERR ][fcc ]: key_config_manager.c:206:kcm_item_store:Failed writing file to storage
[INFO][esfs]: esfs_close - enter
[INFO][fcc ]: key_config_manager.c:210:kcm_item_store:<===
[DBG ][fcc ]: storage.c:369:storage_file_close:<===
[INFO][uccc]: ARM_UC_AddCertificate failed

---------------------4 --------------------------------------------------

[INFO][esfs]: esfs_create - enter
[ERR ][esfs]: esfs_create() - pal_fsFopen() for working dir file failed
[ERR ][fcc ]: storage.c:283:storage_file_create:File already exist in ESFS (esfs_status 5)
[DBG ][fcc ]: storage.c:291:storage_file_create:<===
[ERR ][fcc ]: storage.c:131:storage_file_write:<=== Failed to create new file
[ERR ][fcc ]: key_config_manager.c:206:kcm_item_store:Failed writing file to storage
[INFO][fcc ]: key_config_manager.c:210:kcm_item_store:<===
[ERR ][fcc ]: fcc_dev_flow.c:96:fcc_developer_flow:<=== Store status: 8, Failed to store mbed.UseBootstrap
[SMCC] Developer credentials already exist

Regards
Praveen.Thota
This happen with me also pls help