c8y-log-plugin fails to upload binary due to 401 error

reubenmiller commented 1 year ago

Describe the bug

There is an intermittent error occurring when processing the Cumulocity IoT Log File Request operation, which results in the operation sometimes failing due to a HTTP 401 error (e.g. permission denied) when the log file is uploaded via HTTP to Cumulocity IoT.

In this error case, the following is shown in the "failureReason" property of the operation in Cumulocity IoT.

Handling of operation failed with Failed with HTTP error status 401 Unauthorized

However, subsequent log file request operations then work. It is unclear whether a 401 error triggers a token refresh, or the c8y-log-plugin service is not waiting for the requested token to be returned (or it receives an expired one).

To Reproduce

The exact steps have not been confirmed but I suspect it would be something like:

Start thin-edge.io and all of its components (including the c8y-log-plugin)
Leave the system running for over 1 hour
Request a log file via Cumulocity IoT. The operation should be successful. This is where I suspect the operation is failing (at least in some situations)
Request a second log file via Cumulocity IoT. Check if the second request passes or not

Expected behavior

The log file upload should be retried automatically by the component which is uploading the file to Cumulocity IoT. If a new token is required then it should fetch one. Relying on the user to resend the operation is results in a very negative user experience.

Screenshots

The journalctl logs were collected using the following commands:

journalctl -f -u "c8y-*" -u "tedge-*"

Log Output

Sep 06 10:41:31 lumber tedge-mapper-template[577]: 2023-09-06T10:41:31+02:00 INF Publishing new message. topic=c8y/s/us message=503,c8y_SoftwareUpdate delay=0
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.247352549Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.445391887Z  INFO mqtt_channel::connection: MQTT connection established
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.467384337Z  INFO c8y_api::http_proxy: JWT token requested
Sep 06 10:57:17 lumber tedge-mapper-template[577]: 2023-09-06T10:57:17+02:00 INF Received new c8y token len=790
Sep 06 10:57:17 lumber tedge-mapper-template[577]: 2023-09-06T10:57:17+02:00 INF Setting token to api client
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.516214961Z  INFO c8y_api::http_proxy: JWT token received
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.516849635Z  INFO mqtt_channel::connection: MQTT connection closed
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.533724474Z ERROR c8y_log_manager::actor: Handling of operation for log type software-management failed with: Failed with HTTP error status 401 Unauthorized
Sep 06 11:16:50 lumber c8y-log-plugin[5980]: 2023-09-06T09:16:50.221621513Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:16:50 lumber c8y-log-plugin[5980]: 2023-09-06T09:16:50.532015413Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:17:24 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:24.9694504Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:17:25 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:25.140903536Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:17:59 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:59.565731495Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:17:59 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:59.75566296Z  INFO c8y_log_manager::actor: Log request processed.

Environment (please complete the following information):

OS [incl. version]: Debian 11
Hardware [incl. revision]: Raspberry Pi 4
System-Architecture [e.g. result of "uname -a"]: Linux lumber 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023 aarch64 GNU/Linux
thin-edge.io version [e.g. 0.1.0]: 0.12.1~221+gd7c6e05

Additional context

A screenshot showing the failed log request operation:

reubenmiller commented 1 year ago

So it looks like that the invalid token (most likely an expired token) is not being refreshed for the first log file request after the token has expired (which is generally after 1 hour, though the token validity may differ on Cumulocity IoT installations).

$ journalctl -f -u "c8y-*" -u "tedge-*"
-- Journal begins at Tue 2023-08-15 14:24:36 CEST. --
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.516849635Z  INFO mqtt_channel::connection: MQTT connection closed
Sep 06 10:57:17 lumber c8y-log-plugin[5980]: 2023-09-06T08:57:17.533724474Z ERROR c8y_log_manager::actor: Handling of operation for log type software-management failed with: Failed with HTTP error status 401 Unauthorized
Sep 06 11:16:50 lumber c8y-log-plugin[5980]: 2023-09-06T09:16:50.221621513Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:16:50 lumber c8y-log-plugin[5980]: 2023-09-06T09:16:50.532015413Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:17:24 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:24.9694504Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:17:25 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:25.140903536Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:17:59 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:59.565731495Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:17:59 lumber c8y-log-plugin[5980]: 2023-09-06T09:17:59.75566296Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:26:45 lumber c8y-log-plugin[5980]: 2023-09-06T09:26:45.783670891Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:26:46 lumber c8y-log-plugin[5980]: 2023-09-06T09:26:46.133900795Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:28:03 lumber c8y-log-plugin[5980]: 2023-09-06T09:28:03.45620921Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:28:03 lumber c8y-log-plugin[5980]: 2023-09-06T09:28:03.666784925Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:28:22 lumber c8y-log-plugin[5980]: 2023-09-06T09:28:22.450445602Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:28:22 lumber c8y-log-plugin[5980]: 2023-09-06T09:28:22.715158829Z  INFO c8y_log_manager::actor: Log request processed.
Sep 06 11:28:36 lumber c8y-log-plugin[5980]: 2023-09-06T09:28:36.110326236Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 11:28:36 lumber c8y-log-plugin[5980]: 2023-09-06T09:28:36.258583047Z  INFO c8y_log_manager::actor: Log request processed.

Then 1 hour later, requesting a new log file will fail the first time. Subsequent log file requests are successful.

Sep 06 12:32:41 lumber c8y-log-plugin[5980]: 2023-09-06T10:32:41.144185156Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 12:32:41 lumber c8y-log-plugin[5980]: 2023-09-06T10:32:41.347005191Z  INFO mqtt_channel::connection: MQTT connection established
Sep 06 12:32:41 lumber c8y-log-plugin[5980]: 2023-09-06T10:32:41.369537436Z  INFO c8y_api::http_proxy: JWT token requested
Sep 06 12:32:41 lumber tedge-mapper-template[577]: 2023-09-06T12:32:41+02:00 INF Received new c8y token len=790
Sep 06 12:32:41 lumber tedge-mapper-template[577]: 2023-09-06T12:32:41+02:00 INF Setting token to api client
Sep 06 12:32:41 lumber c8y-log-plugin[5980]: 2023-09-06T10:32:41.41350176Z  INFO c8y_api::http_proxy: JWT token received
Sep 06 12:32:41 lumber c8y-log-plugin[5980]: 2023-09-06T10:32:41.4143938Z  INFO mqtt_channel::connection: MQTT connection closed
Sep 06 12:32:41 lumber c8y-log-plugin[5980]: 2023-09-06T10:32:41.435513903Z ERROR c8y_log_manager::actor: Handling of operation for log type software-management failed with: Failed with HTTP error status 401 Unauthorized
Sep 06 12:33:06 lumber c8y-log-plugin[5980]: 2023-09-06T10:33:06.879192691Z  INFO c8y_log_manager::actor: Log request received on topic: c8y/s/ds
Sep 06 12:33:07 lumber c8y-log-plugin[5980]: 2023-09-06T10:33:07.144523552Z  INFO c8y_log_manager::actor: Log request processed.

And here is the screenshot from the Cumulocity IoT Device Management App

reubenmiller commented 1 year ago

Note, this seems to also affect the c8y-configuration-plugin as well. So we should check all components which use the token on any HTTP requests (either upload or download). Looking at the linked PR the fix seems to be implemented by a single actor, but I just want to make sure we have a full coverage against such bugs.

gligorisaev commented 1 year ago

QA has thoroughly checked the feature and here are the results:

[ ] Test for ticket exists in the test suite.
[x] QA has tested the bug and could not reproduce it anymore.

thin-edge / thin-edge.io

c8y-log-plugin fails to upload binary due to 401 error #2222