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.

Sign up for GitHub

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

Jump to bottom

Cumulocity operation updates fails due to MqttServiceException with message Operation with id xxx for device id yyy not found #3429

Open
reubenmiller opened this issue Feb 26, 2025 · 4 comments
Open

Cumulocity operation updates fails due to MqttServiceException with message Operation with id xxx for device id yyy not found #3429

reubenmiller opened this issue Feb 26, 2025 · 4 comments
Assignees
@reubenmiller
Labels
bug Something isn't working

Comments

@reubenmiller
Copy link
Contributor

reubenmiller commented Feb 26, 2025 •
edited
Loading

Describe the bug

Cumulocity errors (published on the c8y/s/e topic) were discovered which indicate that a specific operation does not match the device id related to it. The error messages seem to be sent by the server when the operation status is updated via 504/505/506 SmartREST messages.

For example, the following operation was received via MQTT:

Topic: c8y/devicecontrol/notifications
Payload:

{
  "delivery": {
    "log": [],
    "time": "2025-02-26T16:58:09.449Z",
    "status": "PENDING"
  },
  "agentId": "3816339621",
  "creationTime": "2025-02-26T16:58:09.416Z",
  "deviceId": "7316341440",
  "id": "16340847",
  "status": "PENDING",
  "c8y_DownloadConfigFile": {
    "type": "CONFIG1_BINARY",
    "url": "https://qaenvironment.eu-latest.cumulocity.com/inventory/binaries/5216341469"
  },
  "description": "Send configuration snapshot CONFIG1_BINARY to device",
  "externalSource": {
    "externalId": "TST_slash_binary_apple:device:TST_pull_meek_ivy",
    "type": "c8y_Serial"
  }
}

When the mapper tries updating the operation status, then Cumulocity an error after each message reporting that the operation is not associated with the device. The 504/506 messages are show below along with the response from Cumulocity on the c8y/s/e topic:

Update operation to EXECUTING: 504,16340847

Feb 26 16:58:09 16094b31bc88 mqtt-logger[534]: {"timestamp":1740589089.597066820,"message":{"tst":"2025-02-26T16:58:09.597092Z+0000","topic":"c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy","qos":0,"retain":0,"payloadlen":12,"payload":"504,16340847"},}
Feb 26 16:58:09 16094b31bc88 mqtt-logger[534]: {"timestamp":1740589089.723054729,"message":{"tst":"2025-02-26T16:58:09.723079Z+0000","topic":"c8y/s/e","qos":0,"retain":0,"payloadlen":116,"payload":"50,,Error of type: MqttServiceException with message: Operation with id 16340847 for device id 3316341441 not found!"},}

Update operation to EXECUTING: 506,16340847

Feb 26 16:58:09 16094b31bc88 mqtt-logger[534]: {"timestamp":1740589089.818144444,"message":{"tst":"2025-02-26T16:58:09.818160Z+0000","topic":"c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy","qos":0,"retain":0,"payloadlen":12,"payload":"506,16340847"},}
Feb 26 16:58:09 16094b31bc88 mqtt-logger[534]: {"timestamp":1740589089.948972729,"message":{"tst":"2025-02-26T16:58:09.948997Z+0000","topic":"c8y/s/e","qos":0,"retain":0,"payloadlen":115,"payload":"50,,Error of type: MqttServiceException with message: Operation with id 16340847 for device id 3316341441not found!"},}

However later in the same test suite, the deviceId for the device with the same externalId has changed from 7316341440 to 3316341441! Though the operation was created about 12 minutes later.

Below shows a comparison between the two operations which both share the same external id TST_slash_binary_apple:device:TST_pull_meek_ivy, but have different deviceId:

Operation 1 (device=7316341440) Operation 2 (device=3316341441) 
{
  "delivery": {
    "log": [],
    "time": "2025-02-26T16:58:09.449Z",
    "status": "PENDING"
  },
  "agentId": "3816339621",
  "creationTime": "2025-02-26T16:58:09.416Z",
  "deviceId": "7316341440",
  "id": "16340847",
  "status": "PENDING",
  "c8y_DownloadConfigFile": {
    "type": "CONFIG1_BINARY",
    "url": "https://<redacted>/inventory/binaries/5216341469"
  },
  "description": "Send configuration snapshot CONFIG1_BINARY to device",
  "externalSource": {
    "externalId": "TST_slash_binary_apple:device:TST_pull_meek_ivy",
    "type": "c8y_Serial"
  }
}
 
{
  "delivery": {
    "log": [],
    "time": "2025-02-26T17:11:17.040Z",
    "status": "PENDING"
  },
  "agentId": "3816339621",
  "creationTime": "2025-02-26T17:11:17.008Z",
  "deviceId": "3316341441",
  "id": "16347308",
  "status": "PENDING",
  "c8y_DownloadConfigFile": {
    "type": "CONFIG1",
    "url": "https://<redacted>/inventory/binaries/4616345349"
  },
  "description": "Send configuration snapshot CONFIG1 to device",
  "externalSource": {
    "externalId": "TST_slash_binary_apple:device:TST_pull_meek_ivy",
    "type": "c8y_Serial"
  }
}

To Reproduce

The unexpected behaviour was detected during a failed system test run for an unrelated PR.

Test Suite: Configuration Operation
Tests:

  • Set Configuration when file does not exist
  • Set Configuration when file exists and agent run normally
  • Set Configuration when file exists and tedge run by root
  • Set Configuration when tedge-write is in another location
  • Set configuration with broken url
  • Get Unknown Configuration Type From Device
  • Update configuration plugin config via cloud
  • Modify configuration plugin config via local filesystem overwrite
  • Update configuration plugin config via local filesystem move (different directory)
  • Update configuration plugin config via local filesystem move (same directory)

Expected behavior

Screenshots

Environment (please complete the following information):

Additional context

Below is the log file containing the full test run:

log.html.zip
@reubenmiller reubenmiller added the bug Something isn't working label Feb 26, 2025
@reubenmiller
Copy link
Contributor Author

After parsing all of the operations received via JSON, it shows that the operations for the same external id get allocated with different deviceId values (either 3316341441 or 7316341440),

{"delivery":{"log":[],"time":"2025-02-26T16:58:06.309Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T16:58:06.270Z","deviceId":"3316341441","id":"16340838","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1","url":"https://<redacted>.cumulocity.com/inventory/binaries/5016340837"},"description":"Send configuration snapshot CONFIG1 to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T16:58:09.449Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T16:58:09.416Z","deviceId":"7316341440","id":"16340847","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1_BINARY","url":"https://<redacted>.cumulocity.com/inventory/binaries/5216341469"},"description":"Send configuration snapshot CONFIG1_BINARY to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:00:14.303Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:00:14.266Z","deviceId":"7316341440","id":"16341151","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG-ROOT","url":"https://<redacted>.cumulocity.com/inventory/binaries/3216342201"},"description":"Send configuration snapshot CONFIG-ROOT to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:02:24.556Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:02:24.521Z","deviceId":"3316341441","id":"16343440","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1","url":"https://<redacted>.cumulocity.com/inventory/binaries/9016342321"},"description":"Send configuration snapshot CONFIG1 to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:02:27.741Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:02:27.708Z","deviceId":"7316341440","id":"16343454","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1_BINARY","url":"https://<redacted>.cumulocity.com/inventory/binaries/1016343453"},"description":"Send configuration snapshot CONFIG1_BINARY to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:04:33.017Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:04:32.983Z","deviceId":"7316341440","id":"16343767","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG-ROOT","url":"https://<redacted>.cumulocity.com/inventory/binaries/8716343766"},"description":"Send configuration snapshot CONFIG-ROOT to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:06:52.364Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:06:52.268Z","deviceId":"7316341440","id":"16344082","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1","url":"https://<redacted>.cumulocity.com/inventory/binaries/5116344525"},"description":"Send configuration snapshot CONFIG1 to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:08:55.727Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:08:55.698Z","deviceId":"3316341441","id":"16347232","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1_BINARY","url":"https://<redacted>.cumulocity.com/inventory/binaries/6916345340"},"description":"Send configuration snapshot CONFIG1_BINARY to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:09:04.972Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:09:04.943Z","deviceId":"7316341440","id":"16347254","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG-ROOT","url":"https://<redacted>.cumulocity.com/inventory/binaries/5516345343"},"description":"Send configuration snapshot CONFIG-ROOT to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:11:17.040Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:11:17.008Z","deviceId":"3316341441","id":"16347308","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1","url":"https://<redacted>.cumulocity.com/inventory/binaries/4616345349"},"description":"Send configuration snapshot CONFIG1 to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:11:20.645Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:11:20.610Z","deviceId":"7316341440","id":"16347310","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1_BINARY","url":"https://<redacted>.cumulocity.com/inventory/binaries/3916344598"},"description":"Send configuration snapshot CONFIG1_BINARY to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:13:28.407Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:13:28.372Z","deviceId":"7316341440","id":"16347315","status":"PENDING","c8y_DownloadConfigFile":{"type":"CONFIG1","url":"invalid://hellö.zip"},"description":"Send configuration snapshot CONFIG1 to device","externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:15:41.552Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:15:41.522Z","deviceId":"3316341441","id":"16347321","status":"PENDING","description":"Retrieve CONFIG1 configuration snapshot from device","c8y_UploadConfigFile":{"type":"CONFIG1"},"externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:16:17.876Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:16:17.845Z","deviceId":"7316341440","id":"16347323","status":"PENDING","description":"Retrieve CONFIG1_BINARY configuration snapshot from device","c8y_UploadConfigFile":{"type":"CONFIG1_BINARY"},"externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:18:26.793Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:18:26.759Z","deviceId":"7316341440","id":"16347327","status":"PENDING","description":"Retrieve unknown_type configuration snapshot from device","c8y_UploadConfigFile":{"type":"unknown_type"},"externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:19:03.932Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:19:03.898Z","deviceId":"3316341441","id":"16347331","status":"PENDING","description":"Retrieve CONFIG1 configuration snapshot from device","c8y_UploadConfigFile":{"type":"CONFIG1"},"externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:19:53.805Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:19:53.771Z","deviceId":"3316341441","id":"16347337","status":"PENDING","description":"Retrieve CONFIG3 configuration snapshot from device","c8y_UploadConfigFile":{"type":"CONFIG3"},"externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}
{"delivery":{"log":[],"time":"2025-02-26T17:20:47.167Z","status":"PENDING"},"agentId":"3816339621","creationTime":"2025-02-26T17:20:47.137Z","deviceId":"3316341441","id":"16347344","status":"PENDING","description":"Retrieve [email protected] configuration snapshot from device","c8y_UploadConfigFile":{"type":"[email protected]"},"externalSource":{"externalId":"TST_slash_binary_apple:device:TST_pull_meek_ivy","type":"c8y_Serial"}}

The number of operations (18 in total) seem to be split almost evenly between the two different Device ID values:

Device Id No. of Operations
3316341441 8
7316341440 10

@reubenmiller
Copy link
Contributor Author

Log file from the test run: log.html.zip

@reubenmiller
Copy link
Contributor Author

The deviceId 3316341441 seems to be the "correct" deviceId as the tests which used it resulted in the operations being processed successfully. Below shows a comparison between a passing test and a failing test (from the same report and both are for the Child Device)

Test Case - Passes (when deviceId=3316341441)

Test case

Set Configuration from Device   Text file (Child Device)    ${CHILD_SN}    ${PARENT_SN}:device:${CHILD_SN}    CONFIG1    /etc/config1.json    /home/runner/work/thin-edge.io/thin-edge.io/tests/RobotFramework/tests/cumulocity/configuration/config1-version2.json    640    tedge:tedge    delete_file_before=${true}

The test case creates an operation for the "correct" 3316341441 deviceId.

${operation} = {"deviceId": "3316341441", "description": "Send configuration snapshot CONFIG1 to device", "status": "PENDING", "deviceName": "MQTT Device TST_slash_binary_apple:device:TST_pull_meek_ivy", "c8y_Downlo...

Result

[attempt=2] Successful assert_success
${operation} = {'deviceId': '3316341441', 'description': 'Send configuration snapshot CONFIG1 to device', 'status': 'SUCCESSFUL', 'delivery': {'log': [{'time': '2025-02-26T16:58:06.309Z', 'status': 'PENDING'}, {'tim...

Operation (as received by the device)

Note: the operation associated with the test case was identified using the deliver timestamp:

{
    "delivery": {
        "log": [],
        "time": "2025-02-26T16:58:06.309Z",
        "status": "PENDING"
    },
    "agentId": "3816339621",
    "creationTime": "2025-02-26T16:58:06.270Z",
    "deviceId": "3316341441",
    "id": "16340838",
    "status": "PENDING",
    "c8y_DownloadConfigFile": {
        "type": "CONFIG1",
        "url": "https://<redacted>.cumulocity.com/inventory/binaries/5016340837"
    },
    "description": "Send configuration snapshot CONFIG1 to device",
    "externalSource": {
        "externalId": "TST_slash_binary_apple:device:TST_pull_meek_ivy",
        "type": "c8y_Serial"
    }
}

Test Case - Fails (when deviceId=7316341440)

Test case

Set Configuration from Device   Binary file (Child Device)    ${CHILD_SN}    ${PARENT_SN}:device:${CHILD_SN}    CONFIG1_BINARY    /etc/binary-config1.tar.gz    /home/runner/work/thin-edge.io/thin-edge.io/tests/RobotFramework/tests/cumulocity/configuration/binary-config1.tar.gz    640    tedge:tedge    delete_file_before=${true}

The test case creates an operation for the "incorrect" 7316341440 deviceId:

${operation} = {"deviceId": "7316341440", "description": "Send configuration snapshot CONFIG1_BINARY to device", "status": "PENDING", "deviceName": "TST_pull_meek_ivy", "c8y_DownloadConfigFile": {"type": "CONFIG1_BI...

Result

Expected operation (id=16340847) to be SUCCESSFUL, but got: PENDING (failureReason: )

Operation (as received by the device)

{
    "delivery": {
        "log": [],
        "time": "2025-02-26T16:58:09.449Z",
        "status": "PENDING"
    },
    "agentId": "3816339621",
    "creationTime": "2025-02-26T16:58:09.416Z",
    "deviceId": "7316341440",
    "id": "16340847",
    "status": "PENDING",
    "c8y_DownloadConfigFile": {
        "type": "CONFIG1_BINARY",
        "url": "https://<redacted>.cumulocity.com/inventory/binaries/5216341469"
    },
    "description": "Send configuration snapshot CONFIG1_BINARY to device",
    "externalSource": {
        "externalId": "TST_slash_binary_apple:device:TST_pull_meek_ivy",
        "type": "c8y_Serial"
    }
}

@reubenmiller
Copy link
Contributor Author

Looking at the "deviceName" which is added automatically to the operation (after the operation is created via REST API), the devices names are very similar,

Status deviceId device Name Note
OK 3316341441 MQTT Device TST_slash_binary_apple:device:TST_pull_meek_ivy The MQTT Device name prefix is a by product of auto device creation
ERROR 7316341440 TST_pull_meek_ivy

This would suggest that there might be a race condition between the registration of a child device via the 101 SmartREST message and the auto creation that occurs when trying to publish data to the c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy topic. Below shows a snippet of the MQTT messages that are sent to the server in quick succession, and since they are sent to different topics (c8y/s/us vs c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy), the order is not guaranteed on the server side (as documented in the MQTT spec):

{"timestamp":1740589076.738949648,"message":{"tst":"2025-02-26T16:57:56.739035Z+0000","topic":"c8y/s/us","qos":0,"retain":0,"payloadlen":88,"payload":"101,TST_slash_binary_apple:device:TST_pull_meek_ivy,TST_pull_meek_ivy,thin-edge.io-child"}}
{"timestamp":1740589076.739155013,"message":{"tst":"2025-02-26T16:57:56.739169Z+0000","topic":"c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy","qos":0,"retain":0,"payloadlen":21,"payload":"114,c8y_DeviceProfile"}}
{"timestamp":1740589076.739267584,"message":{"tst":"2025-02-26T16:57:56.739292Z+0000","topic":"c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy","qos":0,"retain":0,"payloadlen":33,"payload":"114,c8y_DeviceProfile,c8y_Restart"}}
{"timestamp":1740589076.739365011,"message":{"tst":"2025-02-26T16:57:56.739379Z+0000","topic":"c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy","qos":0,"retain":0,"payloadlen":52,"payload":"114,c8y_DeviceProfile,c8y_LogfileRequest,c8y_Restart"}}
{"timestamp":1740589076.739458636,"message":{"tst":"2025-02-26T16:57:56.739473Z+0000","topic":"c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy","qos":0,"retain":0,"payloadlen":23,"payload":"118,software-management"}}
{"timestamp":1740589076.739528126,"message":{"tst":"2025-02-26T16:57:56.739540Z+0000","topic":"c8y/s/us/TST_slash_binary_apple:device:TST_pull_meek_ivy","qos":0,"retain":0,"payloadlen":73,"payload":"114,c8y_DeviceProfile,c8y_LogfileRequest,c8y_Restart,c8y_UploadConfigFile"}}

@reubenmiller reubenmiller self-assigned this Feb 27, 2025
@reubenmiller reubenmiller mentioned this issue Feb 27, 2025
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@reubenmiller reubenmiller

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@reubenmiller