Dear Genodians
After updating to genode 24.04 we found an intermittent problem
involving the depot_download runscript in very specific circumstances.
The problem manifests itself by fetchurl getting stuck for more than 10
seconds downloading a signature file, then aborting with the message
'Error: Operation was aborted by an application callback (code=0)'. Next
fetchurl sucessfully downloads the archive file but then signature
verification fails because no signature was downloaded.
Some debugging revealed that in the error case the DNS response is
forwarded by the nic_router a few milliseconds after the request but is
not read by the fetchurl application until immediately before the
abortion message, e.g. more than 10 seconds later. Further debugging is
difficult since this Heisebug disappears when more output slows down
execution. For illustration I've added an excerpt from the log below.
The problem occurs infrequently and only under very specific circumstances:
* using kernel base-hw running on qemu
* on our gitlab CI/CD runner inside docker
* on two distinct physical servers at our hoster
We have unsucessfully tried to reproduce the problem as follows:
* on the same physical machines manually started inside and outside docker
* on other multiple physical machines using an identical gitlab CI/CD
runner setup
The problem occurs with both lxip and lwip network stack. The problem
seems to disappear when we run the network stack (lxip/lwip) inside the
fetchurl process instead of a separate vfs.
We think we hit a very peculiar corner case of signalling between the
network stack running in a separate vfs and the libc socket plugin.
We would greatly appriciate any insight of what might be amiss or any
suggestion how we could proceed with debugging.
Best regards
Stefan
[2024-07-03 09:17:20.687416] [init -> report_rom] report 'depot_download
-> state'
[2024-07-03 09:17:20.688199] [init -> report_rom] <state progress="yes">
[2024-07-03 09:17:20.689929] [init -> report_rom] <archive
path="gapstage/pkg/http_client_server_demo/2023-11-09" state="download"
total="0" now="0"/>
[2024-07-03 09:17:20.690572] [init -> report_rom] </state>
[2024-07-03 09:17:20.775999] [init -> depot_download ->
report_rom-fetchurl] report 'dynamic -> fetchurl -> progress'
[2024-07-03 09:17:20.776670] [init -> depot_download ->
report_rom-fetchurl] <progress>
[2024-07-03 09:17:20.778610] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz.sig";
total="0.0" now="0.0"/>
[2024-07-03 09:17:20.780845] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz";
total="0.0" now="0.0"/>
[2024-07-03 09:17:20.781492] [init -> depot_download ->
report_rom-fetchurl] </progress>
[2024-07-03 09:17:20.782465] [init -> report_rom] report 'depot_download
-> state'
[2024-07-03 09:17:20.783111] [init -> report_rom] <state progress="yes">
[2024-07-03 09:17:20.784645] [init -> report_rom] <archive
path="gapstage/pkg/http_client_server_demo/2023-11-09" state="download"
total="0" now="0"/>
[2024-07-03 09:17:20.784974] [init -> report_rom] </state>
[2024-07-03 09:17:20.786612] [init -> depot_download -> dynamic ->
fetchurl] fetch
http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz.sig
[2024-07-03 09:17:20.802449] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=9 name=
[2024-07-03 09:17:20.818176] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::write() >>>>> src.length=11 name=
[2024-07-03 09:17:20.819180] [init -> depot_download -> tcpip] Warning:
|
[2024-07-03 09:17:20.819871] [init -> depot_download -> tcpip] Warning:
| 10.0.2.3:53
[2024-07-03 09:17:20.822032] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=9 name=
[2024-07-03 09:17:20.824025] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::write() >>>>> src.length=40 name=
[2024-07-03 09:17:20.824679] [init -> depot_download -> tcpip] Warning:
|
[2024-07-03 09:17:20.826310] [init -> depot_download -> tcpip] Warning:
| CB...........dev.depot.gapfruit.com.....
[2024-07-03 09:17:20.829221] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:20.830848] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:21.065728] [init -> depot_download ->
report_rom-fetchurl] report 'dynamic -> fetchurl -> progress'
[2024-07-03 09:17:21.066344] [init -> depot_download ->
report_rom-fetchurl] <progress>
[2024-07-03 09:17:21.068594] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz.sig";
total="0.0" now="0.0"/>
[2024-07-03 09:17:21.070546] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz";
total="0.0" now="0.0"/>
[2024-07-03 09:17:21.071200] [init -> depot_download ->
report_rom-fetchurl] </progress>
... (many more reports of zero progress)
[2024-07-03 09:17:33.015603] [init -> depot_download ->
report_rom-fetchurl] report 'dynamic -> fetchurl -> progress'
[2024-07-03 09:17:33.016567] [init -> depot_download ->
report_rom-fetchurl] <progress>
[2024-07-03 09:17:33.018731] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz.sig";
total="0.0" now="0.0" timeout="true"/>
[2024-07-03 09:17:33.020665] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz";
total="0.0" now="0.0"/>
[2024-07-03 09:17:33.021626] [init -> depot_download ->
report_rom-fetchurl] </progress>
[2024-07-03 09:17:33.066395] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=12 name=
[2024-07-03 09:17:33.067928] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=56 name=
[2024-07-03 09:17:33.072760] [init -> depot_download -> dynamic ->
fetchurl] Error: Operation was aborted by an application callback
(code=0), failed to fetch
http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz.sig
[2024-07-03 09:17:33.074300] [init -> depot_download -> dynamic ->
fetchurl] fetch
http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz
[2024-07-03 09:17:33.080683] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=9 name=
[2024-07-03 09:17:33.094847] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::write() >>>>> src.length=11 name=
[2024-07-03 09:17:33.095631] [init -> depot_download -> tcpip] Warning:
|
[2024-07-03 09:17:33.096409] [init -> depot_download -> tcpip] Warning:
| 10.0.2.3:53
[2024-07-03 09:17:33.098564] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=9 name=
[2024-07-03 09:17:33.100202] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::write() >>>>> src.length=40 name=
[2024-07-03 09:17:33.100989] [init -> depot_download -> tcpip] Warning:
|
[2024-07-03 09:17:33.102030] [init -> depot_download -> tcpip] Warning:
| 2i...........dev.depot.gapfruit.com.....
[2024-07-03 09:17:33.104395] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.106800] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=12 name=
[2024-07-03 09:17:33.108505] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=56 name=
[2024-07-03 09:17:33.118989] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::write() >>>>> src.length=16 name=
[2024-07-03 09:17:33.119804] [init -> depot_download -> tcpip] Warning:
|
[2024-07-03 09:17:33.120599] [init -> depot_download -> tcpip] Warning:
| 83.166.133.92:80
[2024-07-03 09:17:33.122640] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.124381] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=15 name=
[2024-07-03 09:17:33.170773] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.173216] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=9 name=
[2024-07-03 09:17:33.175279] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=15 name=
[2024-07-03 09:17:33.177831] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=15 name=
[2024-07-03 09:17:33.180810] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=15 name=
[2024-07-03 09:17:33.181887] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::write() >>>>> src.length=143 name=
[2024-07-03 09:17:33.182025] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.182234] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.218590] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.220428] [init -> depot_download -> tcpip] Warning:
Lxip_vfs_file_handle::read() >>>>> dst.length=1690 name=
[2024-07-03 09:17:33.222224] [init -> depot_download ->
report_rom-fetchurl] report 'dynamic -> fetchurl -> progress'
[2024-07-03 09:17:33.222838] [init -> depot_download ->
report_rom-fetchurl] <progress>
[2024-07-03 09:17:33.225334] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz.sig";
total="0.0" now="0.0" timeout="true"/>
[2024-07-03 09:17:33.227218] [init -> depot_download ->
report_rom-fetchurl] <fetch
url="http://dev.depot.gapfruit.com/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz";
total="1412.0" now="1412.0"/>
[2024-07-03 09:17:33.228017] [init -> depot_download ->
report_rom-fetchurl] </progress>
[2024-07-03 09:17:33.235666] [init -> report_rom] report 'depot_download
-> state'
[2024-07-03 09:17:33.236203] [init -> report_rom] <state progress="yes">
[2024-07-03 09:17:33.237418] [init -> report_rom] <archive
path="gapstage/pkg/http_client_server_demo/2023-11-09" state="fetched"/>
[2024-07-03 09:17:33.238035] [init -> report_rom] </state>
[2024-07-03 09:17:33.238657] [init -> report_rom] report 'depot_download
-> state'
[2024-07-03 09:17:33.239417] [init -> report_rom] <state progress="yes">
[2024-07-03 09:17:33.240663] [init -> report_rom] <archive
path="gapstage/pkg/http_client_server_demo/2023-11-09" state="verify"/>
[2024-07-03 09:17:33.240973] [init -> report_rom] </state>
[2024-07-03 09:17:33.250585] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.252277] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.289341] [init -> depot_download -> dynamic ->
verify] /public/gapstage/pkg/http_client_server_demo/2023-11-09.tar.xz:
bad signature
[2024-07-03 09:17:33.291209] [init -> depot_download -> manager] Error:
signature check failed for
'gapstage/pkg/http_client_server_demo/2023-11-09' (bad signature)
[2024-07-03 09:17:33.292338] [init -> report_rom] report 'depot_download
-> state'
[2024-07-03 09:17:33.293402] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.294471] [init -> depot_download -> tcpip] Warning:
Lxip_factory::socket_progress() >>>>>
[2024-07-03 09:17:33.295748] [init -> report_rom] <state progress="yes">
[2024-07-03 09:17:33.296838] [init -> report_rom] <archive
path="gapstage/pkg/http_client_serveError: Test execution timed out
while waiting for
".*path="gapstage/pkg/http_client_server_demo/2023-11-09"
state="done".*.*path="genodelabs/pkg/wm/2019-03-17"
state="done".*.*path="genodelabs/index/19.03" state="failed".*"
make: *** [Makefile:449: run/depot_download-gapfruit-internal_init]
Error 254
r_demo/2023-11-09" state="corrupted"/>
[2024-07-03 09:17:33.297432] [init -> report_rom] </state>
[2024-07-03 09:17:33.311050] [init -> depot_download -> manager]
installation complete.
[2024-07-03 09:17:33.313447] [init -> report_rom] report 'depot_download
-> state'
[2024-07-03 09:17:33.313475] [init -> report_rom] <state>
[2024-07-03 09:17:33.313716] [init -> report_rom] <archive
path="gapstage/pkg/http_client_server_demo/2023-11-09" state="failed"/>
[2024-07-03 09:17:33.314796] [init -> report_rom] <archive
path="genodelabs/pkg/wm/2019-03-17" state="done"/>
[2024-07-03 09:17:33.315881] [init -> report_rom] <index
path="genodelabs/index/19.03" state="failed"/>
[2024-07-03 09:17:33.316150] [init -> report_rom] </state>
[2024-07-03 09:17:33.318112] [init -> depot_download -> manager]
installation complete.
_______________________________________________
users mailing list -- [email protected]
To unsubscribe send an email to [email protected]
Archived at
https://lists.genode.org/mailman3/hyperkitty/list/[email protected]/message/QN56ULJMUJJXBNSJSPMOC6DHQSE3ET27/
