Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Upgrade to Mirage 6 for solo5 PVH support #116

Merged
merged 3 commits into from Oct 28, 2020
Merged

Conversation

talex5
Copy link
Collaborator

@talex5 talex5 commented Aug 19, 2020

This PR updates the Dockerfile to collect together the various pins needed to test solo5 PVH support from e.g. mirage/mirage#1184.

Once this works, it will fix #29.

For me, it boots but then doesn't respond further (e.g. to qvm-run commands). Attempting to start a client just times out (probably because it doesn't connect the new network device).

$ test-mirage qubes_firewall.xen mirage-firewall-staging
Waiting for 'Ready'... OK
Uploading 'qubes_firewall.xen' (7340600 bytes) to "mirage-firewall-staging"
Waiting for 'Booting'... OK
Connecting to mirage-firewall-staging console...
Solo5: Xen console: port 0x2, ring @0x00000000FEFFF000
Solo5: using E820 memory map
            |      ___|
  __|  _ \  |  _ \ __ \
\__ \ (   | | (   |  ) |
____/\___/ _|\___/____/
Solo5: Bindings version v0.6.6-2-g20196872
Solo5: Memory map: 32 MB addressable:
Solo5:   reserved @ (0x0 - 0xfffff)
Solo5:       text @ (0x100000 - 0x2edfff)
Solo5:     rodata @ (0x2ee000 - 0x350fff)
Solo5:       data @ (0x351000 - 0x4b7fff)
Solo5:       heap >= 0x4b8000 < stack < 0x2000000
2020-08-19 13:42:26 -00:00: INF [qubes.rexec] waiting for client...
2020-08-19 13:42:26 -00:00: INF [qubes.gui] waiting for client...
2020-08-19 13:42:26 -00:00: INF [qubes.db] connecting to server...
2020-08-19 13:42:26 -00:00: INF [qubes.db] connected
2020-08-19 13:42:26 -00:00: INF [qubes.rexec] client connected, using protocol version 2

In dom0, I ran gdbsx -a $DOMID 64 9999 and then:

[tal@dom0 ~]$ gdb /var/lib/qubes/vm-kernels/mirage-firewall-staging/vmlinuz 
(gdb) target remote :9999
Remote debugging using :9999
warning: remote target does not support file transfer, attempting to access files from local filesystem.
warning: Unable to find dynamic linker breakpoint function.
GDB will be unable to debug shared library initializers
and track explicitly loaded dynamic code.
mirage_xen_evtchn_block_domain (v_deadline=<optimized out>) at bindings/evtchn.c:343
343	bindings/evtchn.c: No such file or directory.
(gdb) bt
#0  mirage_xen_evtchn_block_domain (v_deadline=<optimized out>) at bindings/evtchn.c:343
#1  0x00000000001a2191 in camlOS__Main__aux_141 () at lib/main.ml:56
#2  0x000000000010bb05 in camlMain__entry () at main.ml:5
#3  0x0000000000107e69 in caml_program ()
#4  0x0000000000282df4 in caml_start_program ()
#5  0x000000000026596c in caml_startup_common (argv=argv@entry=0x499c90 <unused_argv>, pooling=<optimized out>, 
    pooling@entry=0) at startup_nat.c:162
#6  0x00000000002659ab in caml_startup_exn (argv=argv@entry=0x499c90 <unused_argv>) at startup_nat.c:172
#7  caml_startup (argv=argv@entry=0x499c90 <unused_argv>) at startup_nat.c:172
#8  0x000000000026564c in solo5_app_main (si=si@entry=0x49b010 <si>) at bindings/main.c:114
#9  0x00000000001011a4 in _start2 (arg=<optimized out>) at xen/start.c:80
#10 0x00000000001010a2 in _newstack () at xen/boot.S:154
#11 0x0000000000000000 in ?? ()

/cc @mato

@mato
Copy link

mato commented Aug 19, 2020

#0 mirage_xen_evtchn_block_domain (v_deadline=) at bindings/evtchn.c:343

That's err, odd. Looks like it's just waiting for an event, but never gets one. Event delivery is very much working for me, tested also with mirage-skeleton device-usage/network, and presumably also for @palainp as we can see in mirage/mirage#1184.

You are on the latest Qubes OS 4, right?

@mato
Copy link

mato commented Aug 19, 2020

You are on the latest Qubes OS 4, right?

...specifically, what is your Xen version, as reported by xl info in Dom0?

@talex5
Copy link
Collaborator Author

talex5 commented Aug 19, 2020

This is Qubes 4.0, xen_version : 4.8.5-19.fc25. I've enabled the qubes-dom0-current-testing repo too.

@talex5 talex5 marked this pull request as draft August 19, 2020 14:35
@mato
Copy link

mato commented Aug 19, 2020

Ok, so that should be fine. Given that you have the version with type=pvh support fully added in, could you try and run device-usage/network from mirage-skeleton? You'll need to create a bridge in dom0 for it to connect to, but otherwise it should just work. If it works (and test it with e.g. ping -f) then at least we can rule out low-level event channels being broken.

@talex5
Copy link
Collaborator Author

talex5 commented Aug 19, 2020

I tried pinging it from sys-net (that seemed easier). It worked for a bit, then stopped:

[user@sys-net ~]$ sudo ping -f 10.137.0.11 
PING 10.137.0.11 (10.137.0.11) 56(84) bytes of data.
........................................................................................................................................................................................................................................................................................^C
--- 10.137.0.11 ping statistics ---
1521 packets transmitted, 1241 received, 18.4089% packet loss, time 13298ms

Sometimes it doesn't complete booting. e.g. here are two runs where the first one failed:

~/w/m/s/d/network (master) $ test-mirage network.xen mirage-test
Waiting for 'Ready'... OK
Uploading 'network.xen' (6207232 bytes) to "mirage-test"
Waiting for 'Booting'... OK
Connecting to mirage-test console...
Solo5: Xen console: port 0x2, ring @0x00000000FEFFF000
Solo5: using E820 memory map
            |      ___|
  __|  _ \  |  _ \ __ \
\__ \ (   | | (   |  ) |
____/\___/ _|\___/____/
Solo5: Bindings version v0.6.6-2-g20196872
Solo5: Memory map: 32 MB addressable:
Solo5:   reserved @ (0x0 - 0xfffff)
Solo5:       text @ (0x100000 - 0x293fff)
Solo5:     rodata @ (0x294000 - 0x2e5fff)
Solo5:       data @ (0x2e6000 - 0x3fffff)
Solo5:       heap >= 0x400000 < stack < 0x2000000
2020-08-19 15:02:12 -00:00: INF [net-xen frontend] connect 0
2020-08-19 15:02:12 -00:00: INF [net-xen frontend] create: id=0 domid=1
2020-08-19 15:02:12 -00:00: INF [net-xen frontend]  sg:true gso_tcpv4:true rx_copy:true rx_flip:false smart_poll:false
2020-08-19 15:02:12 -00:00: INF [net-xen frontend] MAC: 00:16:3e:5e:6c:00
^C

~/w/m/s/d/network (master) $ test-mirage network.xen mirage-test
Waiting for 'Ready'... OK
Uploading 'network.xen' (6207232 bytes) to "mirage-test"
Waiting for 'Booting'... OK
Connecting to mirage-test console...
Solo5: Xen console: port 0x2, ring @0x00000000FEFFF000
Solo5: using E820 memory map
            |      ___|
  __|  _ \  |  _ \ __ \
\__ \ (   | | (   |  ) |
____/\___/ _|\___/____/
Solo5: Bindings version v0.6.6-2-g20196872
Solo5: Memory map: 32 MB addressable:
Solo5:   reserved @ (0x0 - 0xfffff)
Solo5:       text @ (0x100000 - 0x293fff)
Solo5:     rodata @ (0x294000 - 0x2e5fff)
Solo5:       data @ (0x2e6000 - 0x3fffff)
Solo5:       heap >= 0x400000 < stack < 0x2000000
2020-08-19 15:03:31 -00:00: INF [net-xen frontend] connect 0
2020-08-19 15:03:31 -00:00: INF [net-xen frontend] create: id=0 domid=1
2020-08-19 15:03:31 -00:00: INF [net-xen frontend]  sg:true gso_tcpv4:true rx_copy:true rx_flip:false smart_poll:false
2020-08-19 15:03:31 -00:00: INF [net-xen frontend] MAC: 00:16:3e:5e:6c:00
2020-08-19 15:03:31 -00:00: INF [ethernet] Connected Ethernet interface 00:16:3e:5e:6c:00
2020-08-19 15:03:31 -00:00: INF [ARP] Sending gratuitous ARP for 10.137.0.11 (00:16:3e:5e:6c:00)
2020-08-19 15:03:31 -00:00: INF [udp] UDP interface connected on 10.137.0.11
2020-08-19 15:03:31 -00:00: INF [tcpip-stack-direct] stack assembled: mac=00:16:3e:5e:6c:00,ip=10.137.0.11

@palainp
Copy link
Member

palainp commented Aug 20, 2020

Not sure what I've done wrong, but I got :

Solo5: Memory map: 64 MB addressable:
Solo5:   reserved @ (0x0 - 0xfffff)
Solo5:       text @ (0x100000 - 0x2affff)
Solo5:     rodata @ (0x2b0000 - 0x308fff)
Solo5:       data @ (0x309000 - 0x43afff)
Solo5:       heap >= 0x43b000 < stack < 0x4000000
network: too many arguments, don't know what to do with `None'
Usage: network [OPTION]... 
Try `network --help' for more information.
Solo5: solo5_exit(64) called

@talex5
Copy link
Collaborator Author

talex5 commented Aug 20, 2020

@palainp : I got that too. Somehow, the default Qubes kernel arguments were the literal string "None", rather than the empty string. Can be fixed with qvm-prefs app kernelopts ''.

@palainp
Copy link
Member

palainp commented Aug 20, 2020

@talex5 thank you, I was pretty sure that I had allready run this days ago.
With that fixed I can confirm that the vm runs normally (each times) and I can ping it from sys-firewall. I have xen_version : 4.8.5-22.fc25.

@mato
Copy link

mato commented Aug 21, 2020

(device-usage/network)

I tried pinging it from sys-net (that seemed easier). It worked for a bit, then stopped:

Sometimes it doesn't complete booting. e.g. here are two runs where the first one failed:

Both of those cases point to event delivery not working properly. I wonder why I didn't get anything like that, but it may just be that it's a race and my hardware (X201) is too old/slow to show the problem.

Unfortunately, this will be a pain to debug, especially since Qubes uses a custom version of Xen, so I can't really involve the mainline Xen folks.

Out of interest, what generation and model of CPU are you both on @talex5, @palainp?

@talex5
Copy link
Collaborator Author

talex5 commented Aug 21, 2020

I'm testing on an Intel Core i7 9700K (9th gen, 8 cores).

@palainp
Copy link
Member

palainp commented Aug 22, 2020

I've tested on a I5 8th gen 4 cores, and now I'm trying on a I5 with 2 cores (from 2012 or 2013) but I'm currently not able to compile the unikernel (based on my own procedure from mirage/mirage#1184 (comment)) :
EDIT : Solved by getting back to ocaml 4.10

[user@dev qubes-mirage-firewall]$ make depend
opam pin add -k path --no-action --yes mirage-unikernel-qubes_firewall-qubes . && opam depext --yes --update mirage-unikernel-qubes_firewall-qubes ; opam pin remove --no-action mirage-unikernel-qubes_firewall-qubes
Package mirage-unikernel-qubes_firewall-qubes does not exist, create as a NEW
package? [Y/n] y
[mirage-unikernel-qubes_firewall-qubes.~dev] synchronised from file:///home/user/qubes-mirage-firewall
[WARNING] Failed checks on mirage-unikernel-qubes_firewall-qubes package
          definition from source at file:///home/user/qubes-mirage-firewall:
  warning 37: Missing field 'dev-repo'
  warning 49: The following URLs don't use version control but look like
              version control URLs:
              "https://github.com/mirage/qubes-mirage-firewall.git#master"
mirage-unikernel-qubes_firewall-qubes is now pinned to file:///home/user/qubes-mirage-firewall (version ~dev)
# Detecting depexts using vars: arch=x86_64, os=linux, os-distribution=fedora, os-family=fedora
[ERROR] No solution for mirage-unikernel-qubes_firewall-qubes: Sorry, no solution found: there seems to be a problem with your request.


Command failed: opam list --readonly --external  --resolve=mirage-unikernel-qubes_firewall-qubes returned 20
Ok, mirage-unikernel-qubes_firewall-qubes is no longer pinned to file:///home/user/qubes-mirage-firewall (version ~dev)
opam install -y --deps-only .
[WARNING] Failed checks on mirage-unikernel-qubes_firewall-qubes package
          definition from source at
          git+file:///home/user/qubes-mirage-firewall#master:
  warning 37: Missing field 'dev-repo'
  warning 49: The following URLs don't use version control but look like
              version control URLs:
              "https://github.com/mirage/qubes-mirage-firewall.git#master"
Sorry, no solution found: there seems to be a problem with your request.

No solution found, exiting
make: *** [Makefile:15: depend] Error 20

@talex5
Copy link
Collaborator Author

talex5 commented Aug 22, 2020

@palainp : I get the same error as you when installing with your instructions. It's because opam now defaults to the just-released OCaml 4.11, which isn't supported. I don't know why it doesn't give any error message, but you can see the problem by switching to an alternative solver. e.g.

[user@my-new-qube qubes-mirage-firewall]$ opam install opam-0install
[user@my-new-qube qubes-mirage-firewall]$ opam-0install mirage-unikernel-qubes_firewall-qubes ocaml.4.11.0
[...]
- ocaml -> ocaml.4.11.0
    User requested = 4.11.0
- ocaml-freestanding -> (problem)
    bigstringaf 0.6.1 requires not(< 0.4.1)
    mirage-xen 6.0.0 requires >= 0.6.0
    Rejected candidates:
      ocaml-freestanding.0.6.2: Requires ocaml >= 4.08.0 & < 4.11.0
      ocaml-freestanding.0.6.0: Requires ocaml >= 4.08.0 & < 4.11.0
      ocaml-freestanding.0.5.0: Incompatible with restriction: >= 0.6.0
      ocaml-freestanding.0.4.7: Incompatible with restriction: >= 0.6.0
      ocaml-freestanding.0.4.6: Incompatible with restriction: >= 0.6.0

@palainp
Copy link
Member

palainp commented Aug 22, 2020

Yes I got the same conclusion about ocaml 4.11, I just typed opam switch create 4.10.0 and all was good again

@palainp
Copy link
Member

palainp commented Aug 23, 2020

With the official network unikernel all seems good for me (it starts each times, I can ping or netcat the vm) but I can reproduce the same beahavior as in qubes-mirage-firewall with a modified mirage-skeleton/device-usage/network (see below) config.ml unikernel.ml.
This gives the same assertion failed message (which do not occurs if we growth the OS.Time.sleep promise's timeout):

Solo5: Xen console: port 0x2, ring @0x00000000FEFFF000
Solo5: using E820 memory map
            |      ___|
  __|  _ \  |  _ \ __ \
\__ \ (   | | (   |  ) |
____/\___/ _|\___/____/
Solo5: Bindings version v0.6.6-2-g20196872
Solo5: Memory map: 64 MB addressable:
Solo5:   reserved @ (0x0 - 0xfffff)
Solo5:       text @ (0x100000 - 0x2affff)
Solo5:     rodata @ (0x2b0000 - 0x308fff)
Solo5:       data @ (0x309000 - 0x43afff)
Solo5:       heap >= 0x43b000 < stack < 0x4000000
2020-08-23 12:14:37 -00:00: INF [net-xen frontend] connect 0
2020-08-23 12:14:37 -00:00: INF [qubes.db] connecting to server...
2020-08-23 12:14:37 -00:00: INF [qubes.db] connected
2020-08-23 12:14:37 -00:00: INF [net-xen frontend] create: id=0 domid=1
2020-08-23 12:14:37 -00:00: INF [net-xen frontend]  sg:true gso_tcpv4:true rx_copy:true rx_flip:false smart_poll:false
2020-08-23 12:14:37 -00:00: INF [net-xen frontend] MAC: 00:16:3e:5e:6c:00
2020-08-23 12:14:38 -00:00: INF [ethernet] Connected Ethernet interface 00:16:3e:5e:6c:00
2020-08-23 12:14:38 -00:00: INF [ARP] Sending gratuitous ARP for 10.137.0.50 (00:16:3e:5e:6c:00)
2020-08-23 12:14:38 -00:00: INF [udp] UDP interface connected on 10.137.0.50
2020-08-23 12:14:38 -00:00: INF [tcpip-stack-direct] stack assembled: mac=00:16:3e:5e:6c:00,ip=10.137.0.50
2020-08-23 12:14:38 -00:00: INF [qubes.rexec] waiting for client...
2020-08-23 12:14:38 -00:00: INF [qubes.rexec] client connected, using protocol version 2
2020-08-23 12:14:38 -00:00: INF [application] ready to listen for new packets
dlmalloc.i:3228: Assertion `sz == m->topsize' failed
Aborted
Solo5: solo5_abort() called

As a side note, not sure if this is related : I tried with both mirage configure -t qubes and -t xen : with the -t xen the ip (10.0.0.2) is not the right one as the qubesdb is not read but just before the "assertion failed" message I see a INF [ARP] ignoring ARP reply for 10.0.0.2 (static advertised arp entry in cache) which do not appears with the -t qubes configuration.

talex5 added a commit to talex5/mirage-skeleton that referenced this pull request Aug 23, 2020
@talex5
Copy link
Collaborator Author

talex5 commented Aug 23, 2020

Edit: ignore this comment, it looks like I was building with an Alpine base image by mistake.

I also see the crash when compiled using the native Fedora 32 Qubes compiler, but not when compiling in a Fedora 32 Docker container. I'm using OCaml 4.10.0 in both cases. Opam package versions are the same. The generated code is different. For example, the Qubes one has references to __stack_chk_guard.

Qubes-compiled version:

2020-08-23 15:28:06 -00:00: INF [application] ready to listen for new packets
dlmalloc.i:3228: Assertion `sz == m->topsize' failed
Aborted
Solo5: solo5_abort() called
00000000001010b0 <_start2>:
  1010b0:	48 83 ec 28          	sub    $0x28,%rsp
  1010b4:	48 8b 05 4d cf 20 00 	mov    0x20cf4d(%rip),%rax        # 30e008 <__stack_chk_guard>
  1010bb:	48 89 44 24 18       	mov    %rax,0x18(%rsp)
  1010c0:	31 c0                	xor    %eax,%eax
  1010c2:	e8 39 46 00 00       	callq  105700 <platform_cmdline>

Docker-compiled version (responds to pings for a while, then hangs):

00000000001010b0 <_start2>:
  1010b0:	48 83 ec 18          	sub    $0x18,%rsp
  1010b4:	e8 87 56 00 00       	callq  106740 <platform_cmdline>

talex5 added a commit to talex5/mirage-skeleton that referenced this pull request Aug 23, 2020
From mirage/qubes-mirage-firewall#116 (comment)

This works OK for me when compiled using the `Dockerfile.fedora`, but
crashes when compiled on native Qubes, with the same versions of Fedora,
GCC, OCaml and the opam libraries.
@palainp
Copy link
Member

palainp commented Aug 24, 2020

I do not use docker, but it seems to me that the gcc canaries are a a good thing have ?
Surprinsingly, the crash does not occurs when I do not hide the qrexec symbol (understand : use qrexec >>= fun qrexec2 -> instead of qrexec >>= fun qrexec ->). It's the same for qubes-mirage-firewall, the vm starts correctly, respond to pings, but I still have the Netif: ERROR response when trying to run wget commands.
EDIT : I may have a bad testing configuration as I currently cannot reproduce it :(

@palainp
Copy link
Member

palainp commented Aug 26, 2020

Some progress : I tracked down the code to a vchan_xen disconnection which may interfere with the unikernel. With the diff below for mirage-qubes (EDIT) v0.8.3 I do not have the crash anymore and I have the following log using qvm-prefs mirage-test kernelopts '-l "*:debug"'. Note that it may introduce a memory leak as I am not sure when the flow must be created and destroyed (@talex5 the two send calls in the first block (EDIT) of Lwt.finalize in the close function seems to resolve correctly, have you an idea about how to track the bug further ? (EDIT) In fact I don't know if it's a normal behavior to close the flow here, but as the unikernel runs fine in hvm mode I guess that it is, and when we close it, I can understand why that the messages received later are not well processed resulting in getting a heap corruption.).
With this patch on, qubes-mirage-firwall unikernel boots too but it still crash with Netif: ERROR response when I try to download anything or when I try to reconnect the unikernel vm after a crash (with a frameQ decr from 10 to 0).

[user@my-new-qube mirage-qubes]$ git diff
diff --git a/lib/rExec.ml b/lib/rExec.ml
index 67e4ffc..32cc411 100644
--- a/lib/rExec.ml
+++ b/lib/rExec.ml
@@ -117,7 +117,8 @@ module Flow = struct
         send flow.dstream ~ty:`Data_exit_code msg >>!= fun () ->
         return (`Ok ())
       )
-      (fun () -> QV.disconnect flow.dstream)
+      (Log.debug(fun f -> f "We were supposed to close the flow here"); fun () -> return (()))
+      (*(fun () -> QV.disconnect flow.dstream)*)
 end
 
 module Client_flow = struct
Solo5: Xen console: port 0x2, ring @0x00000000FEFFF000
Solo5: using E820 memory map
            |      ___|
  __|  _ \  |  _ \ __ \
\__ \ (   | | (   |  ) |
____/\___/ _|\___/____/
Solo5: Bindings version v0.6.6-2-g20196872
Solo5: Memory map: 64 MB addressable:
Solo5:   reserved @ (0x0 - 0xfffff)
Solo5:       text @ (0x100000 - 0x2affff)
Solo5:     rodata @ (0x2b0000 - 0x308fff)
Solo5:       data @ (0x309000 - 0x43afff)
Solo5:       heap >= 0x43b000 < stack < 0x4000000
2020-08-26 13:13:43 -00:00: INF [net-xen frontend] connect 0
2020-08-26 13:13:43 -00:00: INF [qubes.db] connecting to server...
2020-08-26 13:13:43 -00:00: INF [qubes.db] connected
2020-08-26 13:13:43 -00:00: INF [net-xen frontend] create: id=0 domid=3
2020-08-26 13:13:43 -00:00: INF [net-xen frontend]  sg:true gso_tcpv4:true rx_copy:true rx_flip:false smart_poll:false
2020-08-26 13:13:43 -00:00: INF [net-xen frontend] MAC: 00:16:3e:5e:6c:00
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/type" = "AppVM"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-vm-updateable" = "False"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-vm-type" = "ProxyVM"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-vm-persistence" = "rw-only"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-usb-devices" = ""
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-timezone" = "Europe/Paris"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-service/meminfo-writer" = "1"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-secondary-dns" = "10.139.1.2"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-random-seed" = "cW08j3YNke93wFpShrLS7mJr3+DYA6CrfpQRzuIlCDB4soH1DxoPkk2KRNRGbhlvI7eH1YG2s0VNt0fAEiD9OQ=="
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-primary-dns" = "10.139.1.1"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-netvm-secondary-dns" = "10.139.1.2"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-netvm-primary-dns" = "10.139.1.1"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-netvm-network" = "10.137.0.50"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-netvm-netmask" = "255.255.255.255"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-netvm-gateway" = "10.137.0.50"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-netmask" = "255.255.255.255"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-mac" = "00:16:3e:5e:6c:00"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-iptables-error" = ""
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-ip" = "10.137.0.50"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-gateway" = "10.137.0.3"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-debug-mode" = "1"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-block-devices" = ""
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/qubes-base-template" = "fedora-32"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/name" = "mirage-test"
2020-08-26 13:13:43 -00:00: DBG [qubes.db] "/default-user" = "user"
2020-08-26 13:13:43 -00:00: INF [ethernet] Connected Ethernet interface 00:16:3e:5e:6c:00
2020-08-26 13:13:43 -00:00: INF [ARP] Sending gratuitous ARP for 10.137.0.50 (00:16:3e:5e:6c:00)
2020-08-26 13:13:43 -00:00: INF [udp] UDP interface connected on 10.137.0.50
2020-08-26 13:13:43 -00:00: INF [tcpip-stack-direct] stack assembled: mac=00:16:3e:5e:6c:00,ip=10.137.0.50
2020-08-26 13:13:43 -00:00: DBG [tcpip-stack-direct] Establishing or updating listener for stack mac=00:16:3e:5e:6c:00,ip=10.137.0.50
2020-08-26 13:13:43 -00:00: INF [qubes.rexec] waiting for client...
2020-08-26 13:13:43 -00:00: INF [qubes.rexec] client connected, using protocol version 2
2020-08-26 13:13:43 -00:00: INF [application] ready to listen for new packets
2020-08-26 13:13:43 -00:00: DBG [tcpip-stack-direct] Establishing or updating listener for stack mac=00:16:3e:5e:6c:00,ip=10.137.0.50
2020-08-26 13:13:44 -00:00: DBG [qubes.rexec] Execute "user:QUBESRPC qubes.SetMonitorLayout dom0\000"
2020-08-26 13:13:44 -00:00: DBG [qubes.rexec] "QUBESRPC qubes.SetMonitorLayout dom0" returned exit status 0
2020-08-26 13:13:44 -00:00: DBG [qubes.rexec] We were supposed to close the flow here
2020-08-26 13:13:52 -00:00: DBG [qubes.rexec] Execute "user:QUBESRPC qubes.WaitForSession dom0\000"
2020-08-26 13:13:52 -00:00: DBG [qubes.rexec] "QUBESRPC qubes.WaitForSession dom0" returned exit status 0
2020-08-26 13:13:52 -00:00: DBG [qubes.rexec] We were supposed to close the flow here

@mato
Copy link

mato commented Aug 27, 2020

@talex5

I also see the crash when compiled using the native Fedora 32 Qubes compiler, but not when compiling in a Fedora 32 Docker container. I'm using OCaml 4.10.0 in both cases. Opam package versions are the same. The generated code is different. For example, the Qubes one has references to __stack_chk_guard.

Interesting. The Solo5 + ocaml-freestanding build infrastructure should be force-enabling stack canaries on all compilers, so it's odd that the Docker-compiled version does not have any. Having said that, the generated assembly looks fine, and if the generated SSP code were triggering the malloc corruption directly, I'd expect to see aborts due to SSP failures as well.

@palainp

Some progress : I tracked down the code to a vchan_xen disconnection which may interfere with the unikernel.

Ah, that's useful. @talex5 pointed out to me that the vchan test unikernels do not test any disconnections. It'd be useful to add that. @djs55, feel like some hacking? :-)

@talex5
Copy link
Collaborator Author

talex5 commented Aug 27, 2020

Ah, looks like I messed up the testing somehow. An image built with the Docker Fedora base does include the stack check, but building with Alpine doesn't. Sorry for the confusion!

@talex5
Copy link
Collaborator Author

talex5 commented Aug 27, 2020

Commenting out this line in mirage-xen seems to help:

free(mapping->start_addr);

With that, the network VM survived a flood ping, and the firewall works.

https://github.com/mato/mirage-xen/blob/528d6c2d83cc49b363b21da8049e0089cd0c173b/lib/bindings/gnttab.c#L320

@palainp
Copy link
Member

palainp commented Aug 27, 2020

@talex5 great job, I can confirm that it starts correctly and I am able to get some web pages with firefox, but the unikernel crashes when I try to load some big traffic (for example : https://www.nperf.com/en/) with qvm-prefs memory and maxmem set to 64MB with this logs (I'm pretty sure that we can get rid of this bug soon ! 😛):

Io_page: memalign(4096, 4096) failed, even after GC.
Fatal error: exception Out of memory
Raised by primitive operation at file "lib/io_page.ml", line 42, characters 8-27
Called from file "lib/io_page.ml", line 44, characters 4-22
Called from file "lib/io_page.ml", line 59, characters 25-32
Called from file "lib/frontend.ml", line 152, characters 18-35
Called from file "lib/frontend.ml", line 231, characters 6-26
Called from file "src/core/lwt.ml", line 1867, characters 23-26
Re-raised at file "src/core/lwt.ml", line 3027, characters 20-29
Called from file "lib/main.ml", line 36, characters 10-20
Called from file "main.ml" (inlined), line 5, characters 12-25
Called from file "main.ml", line 80, characters 5-10
Solo5: solo5_exit(2) called

@talex5
Copy link
Collaborator Author

talex5 commented Aug 27, 2020

Here's a version that leaks address space rather than RAM (0x40000000 is the end of physical memory for me, based on the memory map solo5 outputs at boot time; adjust as appropriate):

talex5/mirage-xen@5e4c6b5

I was hoping to trigger a page fault when the use-after-free happens, but it seems to be running fine.

@palainp
Copy link
Member

palainp commented Aug 29, 2020

With this call to free deleted the unikernel still may encounter an memory allocation problem even if it's later now right? (unless the ocmal GC can deals with this?)
However, downloading a large file does not seem to be a problem now, but even if I have removed all the printed informations for limitating the impact of IOs, I observe a drop in speed of about 30% and a load that goes from negligible (for sys-firewall fedora 32) at 99% CPU for an http download and for a load test of my internet connection a division by 300 of the speed with a CPU load going from 25% to 99%. As I think it's in majority due to the CPU load is there any tool like callgrind that can I play with for finding the bottlenecks?

@talex5
Copy link
Collaborator Author

talex5 commented Aug 30, 2020

With this call to free deleted the unikernel still may encounter an memory allocation problem even if it's later now right?

In my branch I removed the alloc call too, so it won't run out of RAM. This memory isn't actually needed for anything; the solo5 mirage-xen branch was just (wastefully) allocating memory as a way a reserving some memory addresses. My test branch just keeps increasing a pointer to get fresh addresses. Eventually it will wrap and Bad Things will happen, but it's a 64-bit address incremented in page-sized chunks, so it might handle about 2^52 allocations before that.

As I think it's in majority due to the CPU load is there any tool like callgrind that can I play with for finding the bottlenecks?

I'm not sure. There's some (old) information about getting a flamegraph for a Xen Mirage unikernel here:

http://www.brendangregg.com/blog/2016-01-27/unikernel-profiling-from-dom0.html

I also did a few profiling experiments years ago, but I suspect they'd need quite a bit of updating to work now:

https://roscidus.com/blog/blog/2014/08/15/optimising-the-unikernel/

@palainp
Copy link
Member

palainp commented Sep 4, 2020

Thanks for theese very interesting links. I managed to find that the CPU overload is due to a massive communication between the unikernel vm and dom0 (during a test using curl -4 -o /dev/null https://mirrors.edge.kernel.org/qubes/iso/Qubes-R4.0.3-x86_64.iso I got theese 3 dom0 processes using about 130% CPU : qmemmand, xenstored and systemd-journal with a lots of writing in the qubes' logs).
This massive dialog between the unikernel and dom0 is caused by the "divide by 0" in the memory_pressure.ml status function. We have a NaN compared to 0.9 which results in using the else statement that triggers the garbage collector and a memory usage report to xen (and that fills the logs). We can avoid that by testing the result of the mm_stubs function OS.MM.Heap_pages.total (see palainp@079f7c3) and we have with similar performances compared to the linux kernel but this leads me to an abort call in solo5 after downloading something like 240 to 260MB with a unikernel memory fixed to 64MB.
As we give some adress space pieces to the unikernel and we never free the memory in the unmap function, I think we have to tell the GC that there is something to clean from times to times, but unfortunatly if the status function to returns Memory_critical the unikernel stops running after the Memory low - dropping packet and resetting NAT table before reseting My_nat.reset.

@talex5
Copy link
Collaborator Author

talex5 commented Sep 4, 2020

Ah, the NaN causing extra communication due to memory stats reporting makes sense - nice find!

We probably shouldn't be doing a GC manually, but there were some bugs in the past (maybe fixed now; not sure):

BTW, @mato pointed me at https://github.com/Solo5/solo5/blob/master/bindings/xen/platform.c#L74, which says:

    /*
     * Highest mapped physical address, currently 4GB. Note that Xen maps
     * various structures just below 4GB in the guest-physical address space.
     */
    uint64_t paddr_end = PLATFORM_MAX_MEM_SIZE;

So probably we'll fail when we get near to 4 GB, long before exhausting the 64-bit address space. And maybe the page tables beyond that aren't set up either.

I guess solo5 should tell OCaml a range of addresses that it isn't using, and OCaml should use that to work out where to map things and pass the address to the solo5 map function.

@hannesm
Copy link
Member

hannesm commented Oct 15, 2020

@palainp thanks for your report -- I guess you're using mirage 3.8.1 (and OCaml >= 4.10) -- would you mind to try passing --allocation-policy=best-fit to the unikernel (which then uses the best fit allocator for OCaml data, which in my experiments works much nicer).

On a related topic, there's a statistical memory profiler in OCaml (but not yet supported with MirageOS) -- this blog article has a nice description on how to use it for finding memory leaks. I'd soon like to play a bit with load tests of qubes-mirage firewall and see whether I'm able to spot memory leaks. Since you mention "long running, not many VMs start & stop", do you have an intuition whether there are lots of network packets (and/or network flows) involved?

@palainp
Copy link
Member

palainp commented Oct 15, 2020

@hannesm yes i have mirage 3.8.1 and i have compiled the kernel with ocaml 4.10.0.

I have set the parameter kernelopts - --allocation-policy = best-fit in qubes vm preferences but the "low memory" message still appears after something like 2h of random web use (3 vm: one with discord and almost no packets except what discord can send by itself, two vms with Firefox and no special activity).

I am not currently able to caracterize what situation leads to the low memory situation but I will try with a wireshark somewhere to estimate more precisely what is my network consumption.

What bothers me the most is that dropping the nat table does not put free memory to a higher value, I will check if mallinfo gives more accurate information about the actual memory consumption when we call the GC .

@palainp
Copy link
Member

palainp commented Oct 16, 2020

I'm still not sure what's causing the low memory status (if it's related to a leak, a high number of concurrent flows or a too pesimistic estimation of the free memory) and it's hard to set it up.

For now I'm trying the kernel with this patch to qubes-mirage-firewall (plus the really_used() function in mirage-xen using mallinfo() as in mato/mirage-xen@7cea1f3) to check against the third option :

[user@dev qubes-mirage-firewall]$ git diff
diff --git a/memory_pressure.ml b/memory_pressure.ml
index ed5b7e5..5125265 100644
--- a/memory_pressure.ml
+++ b/memory_pressure.ml
@@ -42,8 +42,10 @@ let status () =
   else (
     Gc.full_major ();
     let used = OS.MM.Heap_pages.used () in
-    report_mem_usage used;
-    let frac = float_of_int used /. float_of_int total_pages in
+    let really_used = OS.MM.Heap_pages.really_used () in
+    report_mem_usage really_used;
+    Log.info (fun f -> f "memory reported: used %d / really_used %d kB" used really_used);
+    let frac = float_of_int really_used /. float_of_int total_pages in
     if frac > 0.9 then `Memory_critical
     else `Ok
   )

@mato
Copy link

mato commented Oct 26, 2020

@palainp FYI, mirage 3.9.0 is now released to OPAM with all the Xen changes. This PR will need to be updated for the OS.MM interface changes (mirage/mirage-xen#26) but otherwise you should be able to run the firewall now with no pins or custom OPAM repositories.

let meminfo stats =
let { OS.Memory.free_words; heap_words; _ } = stats in
let mem_total = heap_words * wordsize_in_bytes in
let mem_free = free_words * wordsize_in_bytes in
Log.info (fun f -> f "Writing meminfo: free %d / %d kB (%.2f %%)"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
Log.info (fun f -> f "Writing meminfo: free %d / %d kB (%.2f %%)"
Log.info (fun f -> f "Writing meminfo: free %d / %d B (%.2f %%)"

previously, pages were reported and kilobytes printed, now words are reported and bytes printed. It may on the other side make sense to still report kilobytes (i.e. divide by 1024 above).

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point. I've updated it to use Fmt.bi_byte_size instead (though still untested, because it doesn't finish booting for me).

@talex5 talex5 marked this pull request as ready for review October 26, 2020 15:29
@talex5 talex5 changed the title WIP: test solo5 PVH support Upgrade to Mirage 6 for solo5 PVH support Oct 26, 2020
@talex5
Copy link
Collaborator Author

talex5 commented Oct 26, 2020

I've switched the base image in the Dockerfile from Alpine to Fedora, and it seems to be working now.

For me, this mostly hangs at:
```
2020-10-26 11:16:31 -00:00: INF [qubes.rexec] waiting for client...
2020-10-26 11:16:31 -00:00: INF [qubes.gui] waiting for client...
2020-10-26 11:16:31 -00:00: INF [qubes.db] connecting to server...
```

Sometimes it gets a bit further:
```
2020-10-26 11:14:19 -00:00: INF [qubes.rexec] waiting for client...
2020-10-26 11:14:19 -00:00: INF [qubes.gui] waiting for client...
2020-10-26 11:14:19 -00:00: INF [qubes.db] connecting to server...
2020-10-26 11:14:19 -00:00: INF [qubes.db] connected
2020-10-26 11:14:19 -00:00: INF [qubes.rexec] client connected, using protocol version 2
2020-10-26 11:14:19 -00:00: INF [qubes.gui] client connected (screen size: 3840x2160 depth: 24 mem: 32401x)
2020-10-26 11:14:19 -00:00: INF [unikernel] GUI agent connected
```
There seems to be a problem with Xen events getting lost on Alpine.
@talex5 talex5 force-pushed the solo5 branch 2 times, most recently from e5324c4 to 03c7cba Compare October 28, 2020 10:06
README.md Show resolved Hide resolved
@talex5 talex5 merged commit 089f349 into mirage:master Oct 28, 2020
@talex5 talex5 deleted the solo5 branch October 28, 2020 12:11
@xaki23
Copy link
Contributor

xaki23 commented Oct 28, 2020

build of 03c7cba (so i was missing the last readme update) through qubes-builder(*) just worked ...
resulting kernel deployed as dom0-kernel, fired up a standalone based on it, just works ...
now deployed in the usual "lets try this out" minor role (dedicated mfw for my "goes up and down every hour" external-backup-sync vm), first push seems to just work ...

so LGTM

(*) only change required: in Makefile.builder

-       opam depext -i -y mirage.3.8.0 lwt.5.3.0
+       opam depext -i -y mirage

(which is basicly the same as one of your last changes to the Dockerfile)

want a separate PR?

(heh, epic racecondition on submit+merge there)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

HVM support
5 participants