tedge-agent stop processing ill-formed software_update command payloads #3136
Description
Describe the bug
Publishing an invalid software_update command payload, results in the operation being stuck in the executing state, and the tedge-agent seems to stop processing the command without any error message being displayed in the logs.
Below shows a command used to publish an invalided formulated payload which erroneous adds the .updateList.[].modules.[].softwareType field (valid payloads do not have the softwareType as the software type is defined in the .updateList.[].type field).
tedge mqtt pub -r te/device/main///cmd/software_update/local-test001 '{
"status": "init",
"updateList": [
{
"type": "apt",
"modules": [
{
"name": "tedge",
"action": "install",
"version": "latest",
"softwareType": "invalid"
}
]
}
]
}'To Reproduce
-
Create a local software_update thin-edge.io operation via the local MQTT broker
tedge mqtt pub -r te/device/main///cmd/software_update/local-test001 '{ "status": "init", "updateList": [ { "type": "apt", "modules": [ { "name": "tedge", "action": "install", "version": "latest", "softwareType": "invalid" } ] } ] }'
-
Subscribe to command updates
tedge mqtt sub te/device/main///cmd/software_update/local-test001
The operation should be set to a final status (e.g.
successfulorfailed). The expected status depends on the implementation direction whether erroneous data formats should be rejected (and set to failed), or ignored (and set to successful).
Expected behavior
The following options could be considered
-
Option 1: Reject operations which don't match the expected format/schema. However the operation should set the
statustofailedwith an appropriatefailureReason, e.g.Invalid payload format. An invalid field was detected: 'softwareType' -
Option 2: Ignore unknown properties when parsing the operation structure. If all of the required information is provided in the command payload, then the operation should be processed as normal.
Implementing option 2 would be more useful as users can encode additional information into the command payload, and in the end tedge-agent should only care about the fields it knows about and should also preserve unknown data (if possible).
Screenshots
Environment (please complete the following information):
- OS [incl. version]:
any - Hardware [incl. revision]:
any - System-Architecture [e.g. result of "uname -a"]:
any - thin-edge.io version [e.g. 0.1.0]:
1.3.0
Additional context
The following shows the only logs after the command was created.
logs: software_update workflow
/var/log/tedge/agent# cat workflow-software_update-local-test001.log
==================================================================
Triggered software_update workflow
==================================================================
topic: te/device/main///cmd/software_update/local-test001
operation: software_update
cmd_id: local-test001
time: 2024-09-25T12:24:26.092299533Z
==================================================================
----------------------[ software_update @ init | time=2024-09-25T12:24:26.093471946Z ]----------------------
State: {"logPath":"/var/log/tedge/agent/workflow-software_update-local-test001.log","status":"init","updateList":[{"modules":[{"action":"install","name":"tedge","softwareType":"invalid","version":"latest"}],"type":"apt"}]}
Action: move to scheduled state
=> moving to software_update @ scheduled
----------------------[ software_update @ scheduled | time=2024-09-25T12:24:26.096593729Z ]----------------------
State: {"logPath":"/var/log/tedge/agent/workflow-software_update-local-test001.log","status":"scheduled","updateList":[{"modules":[{"action":"install","name":"tedge","softwareType":"invalid","version":"latest"}],"type":"apt"}]}
Action: execute builtin:software_update
=> moving to software_update @ executing
----------------------[ software_update @ executing | time=2024-09-25T12:24:26.101583048Z ]----------------------
State: {"logPath":"/var/log/tedge/agent/workflow-software_update-local-test001.log","status":"executing","updateList":[{"modules":[{"action":"install","name":"tedge","softwareType":"invalid","version":"latest"}],"type":"apt"}]}
Action: await sub-operation completion
logs: tedge-agent
journalctl -fu tedge-agent -n 100
(os error 2)
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203401522Z INFO sm-agent: tedge_agent::state_repository::state: Use "/etc/tedge/.agent/workflows" to store tedge-agent workflows state
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203415147Z INFO Runtime: Running TedgetoTeConverter-0
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203423938Z INFO Runtime: Running HttpFileTransferServer-1
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.20342673Z INFO Runtime: Running FileCacheActor-2
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203429105Z INFO Runtime: Running Signal-Handler-3
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.20343248Z INFO Runtime: Running MQTT-4
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203435022Z INFO Runtime: Running FsWatcher-5
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203437813Z INFO Runtime: Running Downloader-6
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203440688Z INFO Runtime: Running Uploader-7
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203443647Z INFO Runtime: Running ConfigManager-8
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203448647Z INFO Runtime: Running LogManager-9
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203451647Z INFO Runtime: Running RestartManagerActor-10
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203454272Z INFO Runtime: Running SoftwareManagerActor-11
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203456688Z INFO Runtime: Running Script-12
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.20345898Z INFO Runtime: Running WorkflowActor-13
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203461688Z INFO Runtime: Running HealthMonitorActor-14
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203595688Z INFO mqtt_channel::connection: MQTT connecting to broker: host=127.0.0.1:8883, session_name=Some("tedge-agent#te/device/main//")
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203672146Z INFO tedge_log_manager::actor: Reloading supported log types
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203682813Z INFO log_manager::config: Using the configuration from /etc/tedge/plugins/tedge-log-plugin.toml
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.203857229Z INFO tedge_config_manager::config: Using the configuration from /etc/tedge/plugins/tedge-configuration-plugin.toml
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.20396002Z ERROR tedge_agent::operation_workflows::actor: Fail to reload pending command requests from /etc/tedge/.agent/workflows due to: Could not read state from file `/etc/tedge/.agent/workflows`: No such file or directory (os error 2)
Sep 25 12:24:25 048ad0b33500 sudo[510]: tedge : PWD=/ ; USER=root ; COMMAND=/etc/tedge/sm-plugins/apt list
Sep 25 12:24:25 048ad0b33500 sudo[510]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Sep 25 12:24:25 048ad0b33500 sudo[510]: pam_unix(sudo:session): session closed for user root
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.210019253Z INFO plugin_sm::plugin_manager: Plugin activated: /etc/tedge/sm-plugins/apt
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.210056003Z INFO plugin_sm::plugin_manager: Default plugin type: Not configured
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.247785187Z INFO mqtt_channel::connection: MQTT connection established
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.293929056Z INFO tedge_agent::operation_workflows::actor: Moving software_list operation to state: scheduled
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.295150219Z INFO tedge_api::workflow::log::command_log: => moving to software_list @ scheduled
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.296243049Z INFO tedge_agent::operation_workflows::actor: Executing builtin:software_list operation scheduled step
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.298500459Z INFO tedge_api::workflow::log::command_log: => moving to software_list @ executing
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.299467831Z INFO tedge_agent::operation_workflows::actor: software_list operation executing: waiting for sub-operation completion
Sep 25 12:24:25 048ad0b33500 sudo[542]: tedge : PWD=/tmp ; USER=root ; COMMAND=/etc/tedge/sm-plugins/apt list
Sep 25 12:24:25 048ad0b33500 sudo[542]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
Sep 25 12:24:25 048ad0b33500 sudo[542]: pam_unix(sudo:session): session closed for user root
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.309207179Z INFO tedge_agent::software_manager::actor: Checking if tedge got self updated
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.309224012Z INFO tedge_agent::software_manager::actor: Current running version: 1.2.1~214+gab258fc
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.310049051Z INFO tedge_agent::software_manager::actor: Installed binary version: 1.2.1~214+gab258fc
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.31007426Z INFO tedge_agent::software_manager::actor: Checking if tedge got self updated
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.310077135Z INFO tedge_agent::software_manager::actor: Current running version: 1.2.1~214+gab258fc
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.310630591Z INFO tedge_agent::software_manager::actor: Installed binary version: 1.2.1~214+gab258fc
Sep 25 12:24:25 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:25.311098298Z INFO tedge_agent::operation_workflows::actor: Waiting successful software_list operation to be cleared
Sep 25 12:24:26 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:26.094257694Z INFO tedge_agent::operation_workflows::actor: Moving software_update operation to state: scheduled
Sep 25 12:24:26 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:26.095925106Z INFO tedge_api::workflow::log::command_log: => moving to software_update @ scheduled
Sep 25 12:24:26 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:26.098209891Z INFO tedge_agent::operation_workflows::actor: Executing builtin:software_update operation scheduled step
Sep 25 12:24:26 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:26.100780217Z INFO tedge_api::workflow::log::command_log: => moving to software_update @ executing
Sep 25 12:24:26 048ad0b33500 tedge-agent[500]: 2024-09-25T12:24:26.10278792Z INFO tedge_agent::operation_workflows::actor: software_update operation executing: waiting for sub-operation completion