Device reboots twice when trying to install update with Suricatta WFX

101 views
Skip to first unread message

Adithya Balakumar

unread,
May 31, 2024, 11:16:58 AM5/31/24
to swupdate

Hi All,

 

I am currently trying to use WFX workflows with swupdate and I understand there is already a existing WFX integration available with the help of suricatta. I have updated the necessary configs in the suricatta section of swupdate.cfg file as below:

 

suricatta :

{

    id = "clientId";

    url = http://<WFX-SERVER-IP>/api/wfx/v1;

    polldelay = 5;

};

 

I am trying to use the Direct workflow which is part of the DAU workflow made available by WFX. I am trying this in qemu.

 

After I create the WFX job, I see that swupdate downloads and installs the update.

After the WFX state transitions from INSTALLING -> INSTALLED, the device reboots. Attaching a part of the journalctl logs.

 

-------------------------------------------------------------------------------------------------------------------------------------------------

May 31 11:27:35 demo swupdate.sh[360]: [INFO ] : SWUPDATE running :  [notify_helper] : Round Robin Handler: Setting bootloader environment: kernelfile=C:BOOT1:linux.efi

May 31 11:27:35 demo swupdate.sh[360]: [TRACE] : SWUPDATE running :  [l_handler_wrapper] : [Lua handler] returned: 0

May 31 11:27:35 demo swupdate.sh[360]: Probing config file at /tmp/mnt-bihjTK/BGENV.DAT.

May 31 11:27:35 demo swupdate.sh[360]: [INFO ] : SWUPDATE successful ! SWUPDATE successful !

May 31 11:27:35 demo systemd[1]: tmp-mnt\x2dbihjTK.mount: Deactivated successfully.

May 31 11:27:35 demo swupdate.sh[360]: [TRACE] : SWUPDATE running :  [network_initializer] : Main thread sleep again !

May 31 11:27:35 demo swupdate.sh[360]: [INFO ] : No SWUPDATE running :  Waiting for requests...

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header not processed: 'HTTP/1.1 100 Continue

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header not processed: '

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header not processed: 'HTTP/1.1 200 OK

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [notify_helper] : [100%] Finished.

May 31 11:27:35 demo swupdate.sh[360]: [INFO ] : SWUPDATE running :  [notify_helper] : Invoking transition REGULAR:INSTALLING → REGULAR:INSTALLED

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header not processed: 'HTTP/1.1 100 Continue

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header not processed: '

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header not processed: 'HTTP/1.1 200 OK

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header processed: Content-Type : application/json

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header processed: Vary : Origin

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header processed: X-Response-Filter : del(.context)

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header processed: Date : Fri, 31 May 2024 11:27:38 GMT

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header processed: Content-Length : 104

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [channel_callback_headers] : Header not processed: '

May 31 11:27:35 demo swupdate.sh[360]: [TRACE] : SWUPDATE running :  [channel_log_effective_url] : Channel's effective URL resolved to http://<WFX-SERVER-IP>/api/wfx/v1/jobs/24870055-7ebd-4834-885b-5b3a0257c3c4/status

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [notify_helper] : [100%] Finished.

May 31 11:27:35 demo swupdate.sh[360]: [INFO ] : SWUPDATE running :  [notify_helper] : Yielding to wfx.

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [start_suricatta] : No pending action to process.

May 31 11:27:35 demo swupdate.sh[360]: [DEBUG] : SWUPDATE running :  [suricatta_wait] : Sleeping for 5 seconds.

-- Boot c991253307894cd09f2536936738fbd0 --

May 31 11:27:48 demo kernel: Linux version 6.1.90-cip20 (gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP PREEMPT_DYNAMIC Thu, 01 Jan 1970 01:00:00 +0000

May 31 11:27:48 demo kernel: Command line: console=tty0 console=ttyS0,115200 rootwait earlyprintk watchdog.handle_boot_enabled=0 iTCO_wdt.nowayout=1

May 31 11:27:48 demo kernel: BIOS-provided physical RAM map:

May 31 11:27:48 demo kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable

May 31 11:27:48 demo kernel: BIOS-e820: [mem 0x0000000000100000-0x0000000000805fff] usable

May 31 11:27:48 demo kernel: BIOS-e820: [mem 0x0000000000806000-0x0000000000807fff] ACPI NVS

May 31 11:27:48 demo kernel: BIOS-e820: [mem 0x0000000000808000-0x000000000080ffff] usable

May 31 11:27:48 demo kernel: BIOS-e820: [mem 0x0000000000810000-0x00000000008fffff] ACPI NVS

-------------------------------------------------------------------------------------------------------------------------------------------------------

 

After the device reboots, WFX state transitions from ACTIVATE -> ACTIVATING and then subsequently reboots the device again. (This reboot when the wfx state transitions to ACTIVATING is expected).

But the previous reboot is not expected.

 

By the way I am using SWUpdate from debian salsa. (Commit: 6ccd44a8539ebb880bf0dac408d5db5de7e2de99)

 

Would like to understand if I am missing something here.

Thanks and Regards,

Adithya Balakumar

Storm, Christian

unread,
Jun 3, 2024, 4:38:55 AM6/3/24
to swupdate, Adithya Balakumar
Hi Adithya,


> I am currently trying to use WFX workflows with swupdate and I understand there is already a existing WFX integration available with the help of suricatta.

Yes, there's `suricatta/server_wfx.lua` and it's documented here: https://sbabic.github.io/swupdate/suricatta.html#support-for-wfx.


> I have updated the necessary configs in the suricatta section of swupdate.cfg file as below:
>
> suricatta :
> {
> id = "clientId";
> url = http://<WFX-SERVER-IP>/api/wfx/v1;
> polldelay = 5;
> };
>
> I am trying to use the Direct workflow which is part of the DAU workflow made available by WFX. I am trying this in qemu.

So this one I presume: https://github.com/siemens/wfx/blob/main/workflow/dau/wfx.workflow.dau.direct.yml
Hm, `suricatta/server_wfx.lua` progress-sends `"reboot-mode" : "no-reboot"` (https://github.com/sbabic/swupdate/blob/master/suricatta/server_wfx.lua#L1466-L1467) which gets picked up by `swupdate-progress` (https://github.com/sbabic/swupdate/blob/master/tools/swupdate-progress.c#L357-L366) to precisely prevent that (for wfx) premature reboot.

If this message hasn't come through, then the regular reboot logics (https://github.com/sbabic/swupdate/blob/master/tools/swupdate-progress.c#L435-L437) kicks in and reboots after having installed the artifact(s) rather than while the activating stage.

Can you check whether you see this https://github.com/sbabic/swupdate/blob/master/tools/swupdate-progress.c#L349 INFO message in your logs?


> By the way I am using SWUpdate from debian salsa. (Commit: 6ccd44a8539ebb880bf0dac408d5db5de7e2de99)
>
> Would like to understand if I am missing something here.

You're using the Debian integration and this runs `swupdate-progress` with the `-r` option (https://salsa.debian.org/debian/swupdate/-/blob/debian/master/debian/swupdate.swupdate-progress.service?ref_type=heads#L6), i.e., reboot after a successful update. So that's fine.



Kind regards,
Christian

--
Dr. Christian Storm
Siemens AG, Technology, T CED OES-DE
Otto-Hahn-Ring 6, 81739 Munich, Germany

Adithya Balakumar

unread,
Jun 3, 2024, 8:27:29 AM6/3/24
to swupdate

Hi Christian,

Thanks for the response and for the details about the message handling by swupdate-progress service.
 
I am attaching the part of the logs that you seem to be interested in.

May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [  0%] Start INSTALL.}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": {"nil": { "reboot-mode" : "no-reboot"}}}
May 28 12:09:38 demo swupdate-progress[331]: Update started !
May 28 12:09:38 demo swupdate-progress[331]: Interface: BACKEND
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": {"VERSION" : "0.2"}}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 16%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 26%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 35%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 45%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 55%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 64%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 74%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 83%] Downloading artifact}
May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 93%] Downloading artifact}

In 2nd line of the above log ({"0": {"nil": { "reboot-mode" : "no-reboot"}}}), I see "nil". But looking at https://github.com/sbabic/swupdate/blob/master/suricatta/server_wfx.lua#L1466. shouldn't that be "1" because of suricatta.ipc.progress_cause.CAUSE_REBOOT_MODE

Thanks and Regards,
Adithya 

Storm, Christian

unread,
Jun 3, 2024, 11:32:54 AM6/3/24
to swupdate, Adithya Balakumar
Hi,

> Thanks for the response and for the details about the message handling by swupdate-progress service.
>
> I am attaching the part of the logs that you seem to be interested in.
>
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 0%] Start INSTALL.}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": {"nil": { "reboot-mode" : "no-reboot"}}}
> May 28 12:09:38 demo swupdate-progress[331]: Update started !
> May 28 12:09:38 demo swupdate-progress[331]: Interface: BACKEND
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": {"VERSION" : "0.2"}}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 16%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 26%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 35%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 45%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 55%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 64%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 74%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 83%] Downloading artifact}
> May 28 12:09:38 demo swupdate-progress[331]: INFO : {"0": [ 93%] Downloading artifact}
>
> In 2nd line of the above log ({"0": {"nil": { "reboot-mode" : "no-reboot"}}}), I see "nil".

Exactly, this is the culprit: It is `nil` though it should be the number `1`.


> But looking at https://github.com/sbabic/swupdate/blob/master/suricatta/server_wfx.lua#L1466. shouldn't that be "1" because of suricatta.ipc.progress_cause.CAUSE_REBOOT_MODE

Well, `suricatta/server_wfx.lua` is "just" the interface specification. What is available at run-time to the suricatta Lua realm is defined in https://github.com/sbabic/swupdate/blob/master/suricatta/server_lua.c#L1515-L1677 and there it's missing so it resolves to `nil` at run-time.

I'll send a patch.

Thanks for finding this!

Adithya Balakumar

unread,
Jun 4, 2024, 7:48:30 AM6/4/24
to swupdate
Hello Christian,

Thanks for the patch you sent. I tried applying the patch (https://groups.google.com/g/swupdate/c/ELPp5c0kWrI) and verify once again. Unfortunately the issue persists. Although I see "1" instead of "nil" unlike previously,
The device reboots in the exact same stage as before. Currently I am unclear on what could be the problem.
 
Logs:
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [  0%] Start INSTALL.}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": {"1": { "reboot-mode" : "no-reboot"}}}
Jun 04 11:33:24 demo swupdate-progress[362]: Update started !
Jun 04 11:33:24 demo swupdate-progress[362]: Interface: BACKEND
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": {"VERSION" : "0.2"}}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 10%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 20%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 30%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 41%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 50%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 60%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 70%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 80%] Downloading artifact}
Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 90%] Downloading artifact}

Thanks and Regards,
Adithya 

Storm, Christian

unread,
Jun 4, 2024, 8:23:08 AM6/4/24
to swupdate, Adithya Balakumar
Hi,

> Thanks for the patch you sent. I tried applying the patch (https://groups.google.com/g/swupdate/c/ELPp5c0kWrI) and verify once again. Unfortunately the issue persists. Although I see "1" instead of "nil" unlike previously,
> The device reboots in the exact same stage as before. Currently I am unclear on what could be the problem.
>
> Logs:
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 0%] Start INSTALL.}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": {"1": { "reboot-mode" : "no-reboot"}}}
> Jun 04 11:33:24 demo swupdate-progress[362]: Update started !
> Jun 04 11:33:24 demo swupdate-progress[362]: Interface: BACKEND
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": {"VERSION" : "0.2"}}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 10%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 20%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 30%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 41%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 50%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 60%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 70%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 80%] Downloading artifact}
> Jun 04 11:33:24 demo swupdate-progress[362]: INFO : {"0": [ 90%] Downloading artifact}
>

Hm, this looks good so far. Could you please run the test again with the following changes and the complete log output of swupdate-progress that should print "SUCCESS !" somewhere prior to rebooting? I want to make sure that message has arrived, is properly applied and doesn't get reset until we hit the PROGRESS case in which swupdate-progress reboots for the wfx case...


diff --git a/tools/swupdate-progress.c b/tools/swupdate-progress.c
index 584910d4..23245a34 100644
--- a/tools/swupdate-progress.c
+++ b/tools/swupdate-progress.c
@@ -356,6 +356,8 @@ int main(int argc, char **argv)
*/
n = sscanf(msg.info, "{\"%d\": { \"reboot-mode\" : \"%m[-a-z]\"}}",
&cause, &reboot_mode);
+ fprintf(stdout, "INFO : n=%d cause=%d mode=%s\n", n, cause, reboot_mode);
+ fprintf(stdout, "INFO : pre: disable_reboot=%s\n", disable_reboot ? "true" : "false");
if (n == 2) {
if (cause == CAUSE_REBOOT_MODE) {
if (!strcmp(reboot_mode, "no-reboot")) {
@@ -364,6 +366,7 @@ int main(int argc, char **argv)
}
free(reboot_mode);
}
+ fprintf(stdout, "INFO : post: disable_reboot=%s\n", disable_reboot ? "true" : "false");
}
msg.cur_image[sizeof(msg.cur_image) - 1] = '\0';

@@ -432,12 +435,15 @@ int main(int argc, char **argv)
psplash_write_fifo(psplash_pipe_path, buf);
}

+ fprintf(stdout, "INFO : SUCCESS/FAILURE: disable_reboot=%s\n", disable_reboot ? "true" : "false");
if ((msg.status == SUCCESS) && (msg.cur_step > 0) && opt_r && !disable_reboot) {
+ fprintf(stdout, "INFO : SUCCESS/FAILURE: rebooting device!\n");
reboot_device();
}
/*
* Reset per update variables after update.
*/
+ fprintf(stdout, "INFO : SUCCESS/FAILURE: Setting disable_reboot = false\n");
disable_reboot = false;
wait_update = true;
break;
@@ -450,6 +456,8 @@ int main(int argc, char **argv)
* by wfx but that's left for later when we have full
* JSON support here.
*/
+ fprintf(stdout, "INFO : PROGRESS msg.info=%s\n", msg.info);
+ fprintf(stdout, "INFO : PROGRESS disable_reboot=%s\n", disable_reboot ? "true" : "false");
if (strcasestr(msg.info, "\"module\": \"wfx\"") &&
strcasestr(msg.info, "\"state\": \"ACTIVATING\"") &&
strcasestr(msg.info, "\"progress\": 100")) {
@@ -459,6 +467,7 @@ int main(int argc, char **argv)
psplash_ok = 0;
}
if (opt_r && strcasestr(msg.info, "firmware")) {
+ fprintf(stdout, "INFO : PROGRESS/wfx ACTIVATE: firmware -> reboot.\n");
reboot_device();
break;

Adithya Balakumar

unread,
Jun 4, 2024, 12:03:38 PM6/4/24
to swupdate
Hi Christian,

I tried applying the above to check for the print messages. After applying the patch, I see that the swupdate-progress process crashes with a segfault as seen below:

Jun  4 15:46:05 demo swupdate.sh[360]: [INFO ] : SWUPDATE running :  [notify_helper] : Processing job ID 55f99225-7cb1-4a41-b2fa-2e1775e94430 in state INSTALL ...
Jun  4 15:46:05 demo swupdate.sh[360]: [INFO ] : SWUPDATE running :  [notify_helper] : Executing transition REGULAR:INSTALL → REGULAR:INSTALLING
Jun  4 15:46:05 demo swupdate.sh[360]: '
Jun  4 15:46:05 demo swupdate.sh[360]: '
Jun  4 15:46:05 demo swupdate.sh[360]: '
Jun  4 15:46:05 demo swupdate.sh[360]: '
Jun  4 15:46:05 demo kernel: swupdate-progre[361]: segfault at 350 ip 00007f92d359acb6 sp 00007fffc9040e68 error 4 in libc.so.6[7f92d3517000+155000] likely on CPU 1 (core 1, socket 0)
Jun  4 15:46:05 demo kernel: Code: 00 00 66 90 66 0f ef c0 66 0f ef c9 66 0f ef d2 66 0f ef db 48 89 f8 48 89 f9 48 81 e1 ff 0f 00 00 48 81 f9 cf 0f 00 00 77 6a <f3> 0f 6f 20 66 0f 74 e0 66 0f d7 d4 85 d2 74 04 0f bc c2 c3 48 83
Jun  4 15:46:05 demo systemd[1]: swupdate-progress.service: Main process exited, code=killed, status=11/SEGV
Jun  4 15:46:05 demo systemd[1]: swupdate-progress.service: Failed with result 'signal'.

This looks to happen just after the INSTALL -> INSTALLING transition.
Reply all
Reply to author
Forward
0 new messages