SDK can not start VirtualBox Build Engine

buschmann · 4 September 2020 09:17

I am not sure when the following issue started for me. Looking at my commits, I was using the SDK successfully the last time end of June. I think that was SDK version 3.1.7. I tried to install that again, but it requests current version even if I use the offline installer.

My system:
SailfishOS SDK 3.2.10.2
openSUSE Tumbleweed
Linux 5.8.4
glibc 2.31
VirtualBox 6.1.12

The SDK is not able to detect that the Build Engine VirtualBox VM has been started. Clicking on the icon to start the VM in the SDK starts the VM but than tells me that it could not have started it. But VirtualBox Manager tells me that it has been started and I can also connect to it via SSH.

I also tried to use the Docker Build Engine, but there I have another issue. (sb2d says it detected an buffer overflow and terminates.)

piggz · 4 September 2020 09:39

Same here (im also on tumbleweed). Kernel 5.8 broke VBox 6.1.12 i think, I had to upgrade to a pre-release version to even get it to work, and then the SDK still didnt work anyway. fortunately i was able to make docker work.

martyone · 4 September 2020 09:44

First of all, you installed a pre-release SDK version. Please find links to latest installers here https://sailfishos.org/wiki/Application_SDK and install that instead.

After that please paste the output of sfdk --debug engine exec true.

Should you need to use an older SDK version like 3.1.7 meanwhile, you can install it when you disable the “updates” repository in the installer settings. Works with online installers as well.

buschmann · 4 September 2020 09:55

I am also on 6.1.13 pre-release but wrote 6.1.12 here to not irritate people.

buschmann · 4 September 2020 09:56

Yes, I know that I am on a pre-release, but 3.2.10 had the same issue and when looking for older releases I found 3.2.10.2 and tried that.

martyone · 4 September 2020 10:07

OK let’s see if the debug output gives us any clue.

buschmann · 4 September 2020 10:18

Running sfdk --debug engine exec true gives the following, IMHO sadly not really helpful, output:

sfdk: [I] Starting the build engine…
sfdk.lib: [W] VmConnection: "Failed to start virtual machine \"Sailfish OS Build Engine\""
Failed to start the build engine

But the engine has been started.

Output of VBoxManage list vms:

"Sailfish OS Build Engine" {c01b6c51-46bf-4506-857f-aa4c07ab5649}
"Sailfish OS Emulator 3.3.0.16" {f9e89826-23aa-49da-ae74-cf432e122172}

One more note:
After SDK installation, all ports of the VMs (Build Engine SSH, Build Engine Web, Emulator SSH) are set to 1024. Trying to change them to the former default ports (2222, 8080, 2223) seems not to work. After restarting the SDK, the settings there tell me again that they are on port 1024.

martyone · 4 September 2020 10:41

The invalid port settings are interesting. Possibly vboxmanage changed its command line syntax or output formatting.

Please try (after stopping the VM) rm ~/.cache/SailfishSDK/libsfdk/vminfo.xml and get more detailed log with QT_LOGGING_RULES=sfdk.vms.debug=true sfdk --debug engine exec true.

buschmann · 4 September 2020 10:52

Output after deleting cache and running QT_LOGGING_RULES=sfdk.vms.debug=true sfdk --debug engine exec true:

sfdk.vms: [D] Creating VM "sfdkvm:VirtualBox#Sailfish OS Build Engine"
sfdk.vms: [D] Creating VM "sfdkvm:VirtualBox#Sailfish OS Emulator 3.3.0.16"
sfdk.vms: [D] Updating VM info cache
sfdk.vms: [D] Updating VM info cache
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:44.819") Refresh requested; synchronization: 1
sfdk: [I] Starting the build engine…
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:44.891") Connect requested
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:44.892") VM_STATE: VmOff --connect-requested--> VmStarting
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:44.892") Start fast VM state polling
sfdk.vms: [D] Starting "sfdkvm:VirtualBox#Sailfish OS Build Engine"
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:44.893") *** Disconnected --> Starting
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:54.523") VM starting timeout
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:54.523") VM_STATE: VmStarting --timeout-waiting-to-start--> VmStartingError
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:54.523") Stop fast VM state polling
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("12:50:54.523") *** Starting --> Error
sfdk.lib: [W] VmConnection: "Failed to start virtual machine \"Sailfish OS Build Engine\""
Failed to start the build engine

martyone · 4 September 2020 11:43

Could you please paste the output of vboxmanage showvminfo "Sailfish OS Build Engine" executed while the VM is running according to vbox UI (after the failed sfdk engine exec command)?

buschmann · 4 September 2020 12:00

Output of VBoxManage showvminfo "Sailfish OS Build Engine":

Name:                        Sailfish OS Build Engine
Groups:                      /
Guest OS:                    Linux 2.6 / 3.x / 4.x (32-bit)
UUID:                        c01b6c51-46bf-4506-857f-aa4c07ab5649
Config file:                 /home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/Sailfish OS Build Engine/Sailfish OS Build Engine.vbox
Snapshot folder:             /home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/Sailfish OS Build Engine/Snapshots
Log folder:                  /home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/Sailfish OS Build Engine/Logs
Hardware UUID:               c01b6c51-46bf-4506-857f-aa4c07ab5649
Memory size                  4096MB
Page Fusion:                 disabled
VRAM size:                   10MB
CPU exec cap:                100%
HPET:                        disabled
CPUProfile:                  host
Chipset:                     piix3
Firmware:                    BIOS
Number of CPUs:              4
PAE:                         enabled
Long Mode:                   enabled
Triple Fault Reset:          disabled
APIC:                        enabled
X2APIC:                      disabled
Nested VT-x/AMD-V:           disabled
CPUID Portability Level:     0
CPUID overrides:             None
Boot menu mode:              message and menu
Boot Device 1:               Floppy
Boot Device 2:               DVD
Boot Device 3:               HardDisk
Boot Device 4:               Not Assigned
ACPI:                        enabled
IOAPIC:                      enabled
BIOS APIC mode:              APIC
Time offset:                 0ms
RTC:                         local time
Hardware Virtualization:     enabled
Nested Paging:               enabled
Large Pages:                 disabled
VT-x VPID:                   enabled
VT-x Unrestricted Exec.:     enabled
AMD-V Virt. Vmsave/Vmload:   enabled
Paravirt. Provider:          Default
Effective Paravirt. Prov.:   KVM
State:                       running (since 2020-09-04T11:58:55.736000000)
Graphics Controller:         VBoxVGA
Monitor count:               1
3D Acceleration:             disabled
2D Video Acceleration:       disabled
Teleporter Enabled:          disabled
Teleporter Port:             0
Teleporter Address:          
Teleporter Password:         
Tracing Enabled:             disabled
Allow Tracing to Access VM:  disabled
Tracing Configuration:       
Autostart Enabled:           disabled
Autostart Delay:             0
Default Frontend:            
VM process priority:         default
Storage Controller Name (0):            SATA
Storage Controller Type (0):            IntelAhci
Storage Controller Instance Number (0): 0
Storage Controller Max Port Count (0):  30
Storage Controller Port Count (0):      2
Storage Controller Bootable (0):        on
SATA (1, 0): /home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/mer.vdi (UUID: c549e6c2-e7b9-40f1-b9f5-e609c001e45c)
NIC 1:                       MAC: 080027B647FF, Attachment: NAT, Cable connected: on, Trace: off (file: none), Type: virtio, Reported speed: 0 Mbps, Boot priority: 0, Promisc Policy: deny, Bandwidth group: none
NIC 1 Settings:  MTU: 0, Socket (send: 64, receive: 64), TCP Window (send:64, receive: 64)

martyone · 4 September 2020 15:59

So it seems vboxmanage’s output format has changed. You should be able to work it around by providing a wrapper like this (not tested):

#!/bin/bash

path=${0%/*}
PATH=${PATH//$path:/}
real=$(which vboxmanage)

if [[ ! $real || $real == $0 ]]; then
    echo "Could not find real vboxmanage" >&2
    exit 1
fi

if [[ $1 == showvminfo ]]; then
    out=$("$real" "$@")
    rc=$?
    printf '%s\n' "$out"
    if [[ $out =~ State:\ +running ]]; then
        echo "Session name: headless"
    fi
    exit "$rc"
fi

exec "$real" "$@"

It should be OK to store it under ~/bin, provided that it is on your PATH.

buschmann · 4 September 2020 18:51

That at least brings me one step further. But sadly not to the final.

Using the wrapper script (and VBoxManage instead of vboxmanage, as that is the binary name on openSUSE) at least starts the VM partly successful. But than it can not connect to SSH. I also tried it in the SDK with the same result when trying to compile something. Here is my ouput:

sfdk.vms: [D] Creating VM "sfdkvm:VirtualBox#Sailfish OS Build Engine"
sfdk.vms: [D] Creating VM "sfdkvm:VirtualBox#Sailfish OS Emulator 3.3.0.16"
sfdk.vms: [D] Using cached VM info for "sfdkvm:VirtualBox#Sailfish OS Build Engine"
sfdk.vms: [D] Using cached VM info for "sfdkvm:VirtualBox#Sailfish OS Emulator 3.3.0.16"
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:35:59.509") Refresh requested; synchronization: 1
sfdk: [I] Starting the build engine…
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:35:59.593") Connect requested
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:35:59.595") VM_STATE: VmOff --connect-requested--> VmStarting
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:35:59.595") Start fast VM state polling
sfdk.vms: [D] Starting "sfdkvm:VirtualBox#Sailfish OS Build Engine"
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:35:59.595") *** Disconnected --> Starting
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:36:00.635") VM running: false --> true
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:36:00.635") VM_STATE: VmStarting --successfully-started--> VmRunning
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:36:00.635") Stop fast VM state polling
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:36:00.635") *** Starting --> Connecting
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:36:00.635") SSH_STATE: SshNotConnected --VM-running&connect-requested--> SshConnecting
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:36:00.669") SSH error: "SSH-Verbindungsfehler.\ncommand-line line 0: Bad port '0'.\r\n"
sfdk.vms: [D] "sfdkvm:VirtualBox#Sailfish OS Build Engine" QTime("20:36:01.588") SSH try connect - previous error: "SSH-Verbindungsfehler.\ncommand-line line 0: Bad port '0'.\r\n"

The last two lines are repeated until I kill sfdk. (SSH-Verbindungsfehler = SSH connection error)

As written I also tried it inside the SDK with manually setting the ports to values mentioned in a previous comment. There the similar error is as follows:

Error connecting to the build engine: SSH-Verbindungsfehler.
command-line line 0: Bad port '0'.

martyone · 4 September 2020 20:00

I would try reinstalling the SDK with the wrapper in place.

buschmann · 4 September 2020 20:32

That did not help. This is the part of the installation log without the simple file copying:

Komponente Sailfish OS Build Engine wird installiert
Virtual machine 'Sailfish OS Build Engine' is created and registered.
UUID: 6ef07b4d-e1a0-4bea-baa2-4a061feff85e
Settings file: '/home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/Sailfish OS Build Engine/Sailfish OS Build Engine.vbox'

UUID changed to: 570f6e04-12ca-4384-a41c-73a5b9beff23


Komponente Sailfish OS Build Targets wird installiert
/home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/targets/targets.repository
/home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/targets/targets.repository/Updates.xml
/home/buschmann/Dokumente/Entwicklung/SailfishOS/mersdk/targets/targets.repository/manage.sh

Komponente SailfishOS-latest (3.3.0.16) wird installiert
/home/buschmann/Dokumente/Entwicklung/SailfishOS/emulator/Sailfish OS Emulator 3.3.0.16
/home/buschmann/Dokumente/Entwicklung/SailfishOS/emulator/Sailfish OS Emulator 3.3.0.16/sailfishos.vdi
Virtual machine 'Sailfish OS Emulator 3.3.0.16' is created and registered.
UUID: 47588568-f09e-4d61-b83c-68df7d1031ca
Settings file: '/home/buschmann/Dokumente/Entwicklung/SailfishOS/emulator/Sailfish OS Emulator 3.3.0.16/Sailfish OS Emulator 3.3.0.16/Sailfish OS Emulator 3.3.0.16.vbox'

UUID changed to: ab851c44-706b-4ecc-ae4a-709c66d1d6f0


Komponente Qt QmlLive Integration for Sailfish IDE wird installiert

Komponente Sailfish OS Build Engine Integration for Sailfish IDE wird installiert
Generating keys...
Generating keys...

Komponente Common Sailfish OS Emulator Integration Bits for Sailfish IDE wird installiert
Error: Device model was not found.

Error: Device model was not found.

Error: Device model was not found.

Error: Device model was not found.


Komponente Sailfish OS Emulator Integration for Sailfish IDE wird installiert
VBoxManage: error:
Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)
VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error:
Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)
VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error:
Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)
VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)
VBoxManage: error:
Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)
VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)
VBoxManage: error:
Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

VBoxManage: error: Code NS_ERROR_INVALID_ARG (0x80070057) - Invalid argument value (extended info not available)

VBoxManage: error: Context: "RemoveRedirect(Bstr(ValueUnion.psz).raw())" at line 1926 of file VBoxManageModifyVM.cpp

0%...
10%...20
%...30%...
40%...50%...
60%...70%...80%...90%...
100%

Snapshot taken. UUID: 0783c7b4-6ea1-45fa-9b60-1c95b94b933d

Generating keys...
Generating keys...
Error: Emulator was not found.


Komponente SailfishOS-latest (3.3.0.16) wird installiert

Komponente SailfishOS-latest-armv7hl (3.3.0.16) wird installiert

Komponente SailfishOS-latest-i486 (3.3.0.16) wird installiert

Komponente Sailfish OS Build Target latest-i486 (3.3.0.16) Integration for Sailfish OS IDE wird installiert
Error: Id was not found.


Komponente Sailfish OS Build Target latest-armv7hl (3.3.0.16) Integration for Sailfish OS IDE wird installiert
Error: Id was not found.

Schreiben des Verwaltungswerkzeugs.

Installation abgeschlossen!

martyone · 7 September 2020 07:51

All the error messages in the log looks good/expected (vboxmanage lacks a --force like switch that would make it more quiet).

Is the port forwarding set up properly now? (Before they were all on 1024 you wrote.)

Would you be able to check for possible incompatibilities in output of vboxmanage showvminfo --machinereadable, which is parsed by this function? https://github.com/sailfishos/sailfish-qtcreator/blob/master/src/libs/sfdk/vboxvirtualmachine.cpp#L882 . If you find an incompatibility there, you should be able to extend the wrapper to cover that case as well.

(I am not able to really start debugging this on my side right now. Hopefully in couple of days.)

vige · 8 September 2020 05:04

I have a feeling this is the real cause of your issues, even though I can’t prove it. But you can! Please upgrade your virtualbox to 6.1.14, which was released a few days ago, and try again. You might have to reinstall the Sailfish SDK after that, as your vm settings are probably incorrect.

buschmann · 8 September 2020 11:17

Might be. I will test it when 6.1.14 hits the openSUSE repos.

vige · 8 September 2020 11:18

Please let us know how it goes then!

buschmann · 9 September 2020 14:16

I now tried a fresh install with VirtualBox 6.1.14, but now I can not even install the SDK. During installation I get the following error message:

Warning: VBoxManage: error: Invalid NIC type 'virtio' specified for NIC 1

A popup window shows up with the following text:

Error installing component org.merproject.mersdk:
Execution failed (Unexpected exit code: 1): "/usr/bin/VBoxManage modifyvm Sailfish OS Build Engine --ostype Linux26 --memory 1024 --vram 10 --ioapic on --pae on --nic1 nat --cableconnected1 on --nictype1 virtio --natpf1 guestssh,tcp,127.0.0.1,2222,,22 --natpf1 guestwww,tcp,127.0.0.1,8080,,9292 --nic2 intnet --cableconnected2 on --intnet2 SailfishSDK --nictype2 virtio --macaddress2 08005A11F155"

I tried with and without the wrapper. Looking at the help output of VBoxManage help modifyvm I have only the following options for --nictype, but not virtio: Am79C970A|Am79C973|Am79C960|82540EM|82543GC|82545EM