search

thin-edge / thin-edge.io

The open edge framework for lightweight IoT devices
https://thin-edge.io
Apache License 2.0
223 stars 55 forks source link

sm-plugin fails to download c8y resource when local proxy is using cert based authentication #3212

Open reubenmiller opened 4 weeks ago

reubenmiller commented 4 weeks ago

Describe the bug

The thin-edge.io software management plugin interface fails to download files from the Cumulocity Local Proxy service if local certificate-based authentication is being used.

The error appears when thin-edge.io tries to download the artifact from the Cumulocity Local Proxy (if the artifact's url is hosted in Cumulocity), before calling the sm-plugin install subcommand. Below shows the error in the tedge-agent logs:

Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]: 2024-10-29T10:16:24.153856163Z ERROR plugin_sm::plugin: Download error: DownloadError {
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]:     reason: "error sending request for url (https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602): error trying to connect: received corrupt message of type InvalidContentType",
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]:     url: "https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602",
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]:     source_err: "error trying to connect: received corrupt message of type InvalidContentType",
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]: }

Looking at the code, it seems that the tedge.toml setting; c8y.proxy.key_path, c8y.proxy.cert_path and c8y.proxy.ca_path are ignored, as shown in the following code (though please verify if this link is correct).

https://github.com/thin-edge/thin-edge.io/blob/94b992d7f6d92bc4d167b2008bddac8eba984c2a/crates/common/download/src/download.rs#L105-L106

To Reproduce

  1. Configure thin-edge.io to cert-based authentication for local services such as
  2. Create a software and version in the Cumulocity Software repository
  3. Install software with uses the url field (to download the artifact from the platform)

Expected behavior

Screenshots

Environment (please complete the following information):

Additional context

tedge-agent logs

Oct 29 10:16:22 rpi5-d83add9f145a sudo[9460]:    tedge : PWD=/ ; USER=root ; COMMAND=/etc/tedge/sm-plugins/container-group list
Oct 29 10:16:22 rpi5-d83add9f145a tedge-agent[871]: 2024-10-29T10:16:22.352849542Z  INFO tedge_agent::operation_workflows::actor: software_update operation executing: waiting for sub-operation completion
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9460]: pam_unix(sudo:session): session closed for user root
Oct 29 10:16:22 rpi5-d83add9f145a tedge-agent[871]: 2024-10-29T10:16:22.633820361Z  INFO plugin_sm::plugin_manager: Plugin activated: /etc/tedge/sm-plugins/container-group
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9596]:    tedge : PWD=/ ; USER=root ; COMMAND=/etc/tedge/sm-plugins/container list
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9596]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9596]: pam_unix(sudo:session): session closed for user root
Oct 29 10:16:22 rpi5-d83add9f145a tedge-agent[871]: 2024-10-29T10:16:22.671496975Z  INFO plugin_sm::plugin_manager: Plugin activated: /etc/tedge/sm-plugins/container
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9620]:    tedge : PWD=/ ; USER=root ; COMMAND=/etc/tedge/sm-plugins/apt list
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9620]: pam_unix(sudo:session): session closed for user root
Oct 29 10:16:22 rpi5-d83add9f145a tedge-agent[871]: 2024-10-29T10:16:22.687532811Z  INFO plugin_sm::plugin_manager: Plugin activated: /etc/tedge/sm-plugins/apt
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9623]:    tedge : PWD=/tmp ; USER=root ; COMMAND=/etc/tedge/sm-plugins/container-group prepare
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9623]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Oct 29 10:16:22 rpi5-d83add9f145a sudo[9623]: pam_unix(sudo:session): session closed for user root
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]: 2024-10-29T10:16:24.153856163Z ERROR plugin_sm::plugin: Download error: DownloadError {
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]:     reason: "error sending request for url (https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602): error trying to connect: received corrupt message of type InvalidContentType",
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]:     url: "https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602",
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]:     source_err: "error trying to connect: received corrupt message of type InvalidContentType",
Oct 29 10:16:24 rpi5-d83add9f145a tedge-agent[871]: }
Oct 29 10:16:24 rpi5-d83add9f145a sudo[9722]:    tedge : PWD=/tmp ; USER=root ; COMMAND=/etc/tedge/sm-plugins/container-group finalize
Oct 29 10:16:24 rpi5-d83add9f145a sudo[9722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Oct 29 10:16:24 rpi5-d83add9f145a sudo[9722]: pam_unix(sudo:session): session closed for user root
Bravo555 commented 3 weeks ago

Using the tedge-demo-container, can't reproduce the issue.

tedge-agent logs:

Nov 04 11:50:48 tedge tedge-agent[2348]: 2024-11-04T10:50:48.585024933Z  INFO tedge_api::workflow::log::command_log: => moving to software_update @ executing
Nov 04 11:50:48 tedge tedge-agent[2348]: 2024-11-04T10:50:48.589098553Z  INFO tedge_agent::operation_workflows::actor: software_update operation executing: waiting for sub-operation completion
Nov 04 11:50:48 tedge sudo[2672]:    tedge : PWD=/ ; USER=root ; COMMAND=/etc/tedge/sm-plugins/container list
Nov 04 11:50:48 tedge sudo[2672]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Nov 04 11:50:48 tedge sudo[2672]: pam_unix(sudo:session): session closed for user root
Nov 04 11:50:48 tedge tedge-agent[2348]: 2024-11-04T10:50:48.6017242Z ERROR plugin_sm::plugin_manager: File /etc/tedge/sm-plugins/container in plugin directory does not support list operation and may not be a valid plugin, skipping.
Nov 04 11:50:48 tedge sudo[2689]:    tedge : PWD=/ ; USER=root ; COMMAND=/etc/tedge/sm-plugins/container-group list
Nov 04 11:50:48 tedge sudo[2689]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Nov 04 11:50:48 tedge sudo[2689]: pam_unix(sudo:session): session closed for user root
Nov 04 11:50:48 tedge tedge-agent[2348]: 2024-11-04T10:50:48.696850263Z ERROR plugin_sm::plugin_manager: File /etc/tedge/sm-plugins/container-group in plugin directory does not support list operation and may not be a valid plugin, skipping.
Nov 04 11:50:48 tedge sudo[2795]:    tedge : PWD=/ ; USER=root ; COMMAND=/etc/tedge/sm-plugins/apt list
Nov 04 11:50:48 tedge sudo[2795]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Nov 04 11:50:48 tedge sudo[2795]: pam_unix(sudo:session): session closed for user root
Nov 04 11:50:48 tedge tedge-agent[2348]: 2024-11-04T10:50:48.704479842Z  INFO plugin_sm::plugin_manager: Plugin activated: /etc/tedge/sm-plugins/apt
Nov 04 11:50:48 tedge sudo[2798]:    tedge : PWD=/tmp ; USER=root ; COMMAND=/etc/tedge/sm-plugins/apt prepare
Nov 04 11:50:48 tedge sudo[2798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Nov 04 11:50:49 tedge sudo[2798]: pam_unix(sudo:session): session closed for user root
Nov 04 11:50:49 tedge tedge-agent[2348]: 2024-11-04T10:50:49.663244973Z  INFO download::download: Downloading file from url="https://tedge:8001/c8y/inventory/binaries/539976", len=0
Nov 04 11:50:49 tedge sudo[2996]:    tedge : PWD=/tmp ; USER=root ; COMMAND=/etc/tedge/sm-plugins/apt update-list
Nov 04 11:50:49 tedge sudo[2996]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Nov 04 11:50:50 tedge sudo[2996]: pam_unix(sudo:session): session closed for user root
Nov 04 11:50:50 tedge sudo[3008]:    tedge : PWD=/tmp ; USER=root ; COMMAND=/etc/tedge/sm-plugins/apt finalize
Nov 04 11:50:50 tedge sudo[3008]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Nov 04 11:50:50 tedge sudo[3008]: pam_unix(sudo:session): session closed for user root

The file is downloaded from the proxy via HTTPS, but InvalidContentType error is not triggered.

reubenmiller commented 3 weeks ago

This is the full workflow output of the failed operation:

# cat workflow-software_update-c8y-mapper-40874295.log

==================================================================
Triggered software_update workflow
==================================================================

topic:     te/device/main///cmd/software_update/c8y-mapper-40874295
operation: software_update
cmd_id:    c8y-mapper-40874295
time:      2024-10-29T10:16:22.305738552Z

==================================================================

----------------------[ software_update @ init | time=2024-10-29T10:16:22.310615783Z ]----------------------

State:    {"logPath":"/var/log/tedge/agent/workflow-software_update-c8y-mapper-40874295.log","status":"init","updateList":[{"modules":[{"action":"install","name":"nodered","url":"https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602","version":"4.0.3-22-minimal (tedge network)"}],"type":"container-group"}]}

Action:   move to scheduled state

=> moving to software_update @ scheduled

----------------------[ software_update @ scheduled | time=2024-10-29T10:16:22.328086799Z ]----------------------

State:    {"logPath":"/var/log/tedge/agent/workflow-software_update-c8y-mapper-40874295.log","status":"scheduled","updateList":[{"modules":[{"action":"install","name":"nodered","url":"https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602","version":"4.0.3-22-minimal (tedge network)"}],"type":"container-group"}]}

Action:   execute builtin:software_update

=> moving to software_update @ executing

----------------------[ software_update @ executing | time=2024-10-29T10:16:22.345554944Z ]----------------------

State:    {"logPath":"/var/log/tedge/agent/workflow-software_update-c8y-mapper-40874295.log","status":"executing","updateList":[{"modules":[{"action":"install","name":"nodered","url":"https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602","version":"4.0.3-22-minimal (tedge network)"}],"type":"container-group"}]}

Action:   await sub-operation completion

----- $ /usr/bin/sudo "-n" "/etc/tedge/sm-plugins/container-group" "prepare"
Exit status: 0 (OK)

stderr <<EOF
Loading setting file: /etc/tedge-container-plugin/env
Using docker as the container cli
EOF

stdout (EMPTY)
----- $ Downloading: https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602 to /tmp/nodered_4.0.3-22-minimal%20%28tedge%20network%29
error: DownloadError error: "error sending request for url (https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602): error trying to connect: received corrupt message of type InvalidContentType" for "https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602"

Caused by: error trying to connect: received corrupt message of type InvalidContentType
----- $ /usr/bin/sudo "-n" "/etc/tedge/sm-plugins/container-group" "finalize"
Exit status: 0 (OK)

stderr <<EOF
Loading setting file: /etc/tedge-container-plugin/env
Using docker as the container cli
EOF

stdout (EMPTY)

----------------------[ software_update @ failed | time=2024-10-29T10:16:24.371881243Z ]----------------------

State:    {"failures":[{"modules":[],"type":"container-group"}],"logPath":"/var/log/tedge/agent/workflow-software_update-c8y-mapper-40874295.log","reason":"DownloadError error: \"error sending request for url (https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602): error trying to connect: received corrupt message of type InvalidContentType\" for \"https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602\"\n\nCaused by: error trying to connect: received corrupt message of type InvalidContentType, see device log file /var/log/tedge/agent/workflow-software_update-c8y-mapper-40874295.log","status":"failed","updateList":[{"modules":[{"action":"install","name":"nodered","url":"https://rpi5-d83add9f145a:8001/c8y/inventory/binaries/40663602","version":"4.0.3-22-minimal (tedge network)"}],"type":"container-group"}]}

Action:   wait for the requester to finalize the command
Bravo555 commented 3 weeks ago

The InvalidContentType error is returned e.g. when the server responds with plaintext to an HTTPS request, which can be quickly confirmed by:

server.rs:

use tokio::{io::AsyncWriteExt, net::TcpListener};

#[tokio::main]
async fn main() {
    let listener = TcpListener::bind("localhost:2137").await.unwrap();

    loop {
        let (mut stream, _) = listener.accept().await.unwrap();
        stream.write_all(b"hello there").await.unwrap();
    }
}

client.rs (reqwest 0.11):

#[tokio::main]
async fn main() {
    let error = reqwest::get("https://localhost:2137/").await.unwrap_err();
    println!("{error}");
}

output:

error sending request for url (https://localhost:2137/): error trying to connect: received corrupt message of type InvalidContentType

So one theory would be:

  1. tedge connect c8y
  2. proxy certificates are configured
  3. tedge-agent is restarted, tedge-mapper-c8y is not and the proxy still runs on HTTP
  4. tedge-agent attempts to connect to HTTP proxy on 8001 via HTTPS

But AFAIK this is not possible because when converting a c8y_SoftwareUpdate request, the mapper would put a tedgeUrl of the currently running proxy in the payload, i.e. "tedgeUrl": "http://...", so the agent wouldn't attempt to connect via https, but via http.

As I'm unable to find a codepath where this happens, and it's not clear how to reproduce the issue, it was decided that some other things could be improved to make these issues easier to debug: