Bug 1668713

Summary: Attempting to create Hosted Engine in Cockpit fails with qemu-kvm: -chardev pty,id=charserial0: Failed to create PTY: Operation not permitted
Product: [oVirt] ovirt-hosted-engine-setup Reporter: Max <thekigen>
Component: GeneralAssignee: Ido Rosenzwig <irosenzw>
Status: CLOSED NOTABUG QA Contact: Wei Wang <weiwang>
Severity: high Docs Contact:
Priority: urgent    
Version: 2.3.0CC: bugs, cshao, qiyuan, rbarry, stirabos, thekigen, weiwang, ycui
Target Milestone: ovirt-4.3.1Flags: rule-engine: ovirt-4.3+
rule-engine: blocker+
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-02-06 08:36:14 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Integration RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
messages log file
none
ovirt-hosted-engine-setup-ansible-bootstrap_local_vm none

Description Max 2019-01-23 11:51:34 UTC 
Description of problem:
When following the Hosted Engine wizard in Cockpit the VM fails to start with the error:
ERROR internal error: qemu unexpectedly closed the monitor: 2019-01-23T11:02:36.048859Z qemu-kvm: -chardev pty,id=charserial0: Failed to create PTY: Operation not permitted

Version-Release number of selected component (if applicable):


How reproducible:
Fails every time.


Steps to Reproduce:
1. Using OVH's CentOS 7 template.
2. Install oVirt Cockpit.
3. Follow Hosted Engine wizard.

Actual results:
Fails every time with:
 ERROR internal error: qemu unexpectedly closed the monitor: 2019-01-23T11:02:36.048859Z qemu-kvm: -chardev pty,id=charserial0: Failed to create PTY: Operation not permitted


Expected results:
Successful creation of the Hosted Engine VM.


Additional info:
This is a box rented from OVH.  OVH has their templates for CentOS.  I expanded the primary partition across two NVMe drives (RAID 0).  This creates a /dev/md2 device.  Appears to be multipath.  I have seen some multipath errors.

[10092.625557] device-mapper: uevent: version 1.0.3
[10092.625727] device-mapper: ioctl: 4.37.1-ioctl (2018-04-03) initialised: dm-devel
[10099.934714] device-mapper: multipath service-time: version 0.3.0 loaded
[10099.934841] device-mapper: table: 253:0: multipath: error getting device
[10099.934868] device-mapper: ioctl: error adding target to table
[10099.936987] device-mapper: table: 253:0: multipath: error getting device
[10099.937025] device-mapper: ioctl: error adding target to table

Unknown if they are related or not.
Comment 1 Ryan Barry 2019-01-24 00:08:38 UTC 
Is nested virtualization enabled? OVH also requires a peculiar configuration for additional network addresses

Please provide logs from ovirt-hosted-engine-setup and qemu, but we may not be able to help on OVH, unfortunately
Comment 2 Max 2019-01-24 18:29:16 UTC 
Nested was not enabled.  I enabled it but no change.  OVH requires provisioning of a MAC address and usage of that MAC address for VMs (I've used XenServer and oVirt in the past with OVH).

/var/log/qemu-ga is empty.
/var/log/ovirt-hosted-engine-setup contain multiple files which appear to contain the passwords and other sensitive information.

I will attach messages.
Comment 3 Max 2019-01-24 18:29:45 UTC 
Created attachment 1523277 [details]
messages log file
Comment 4 Ryan Barry 2019-01-24 18:31:16 UTC 
As far as I know, HE logs shouldn't contain sensitive information. If they do, sounds like a bug to me.

Is it possibly for you to sanitize those and attach them also?
Comment 5 Max 2019-01-25 09:59:26 UTC 
Created attachment 1523470 [details]
ovirt-hosted-engine-setup-ansible-bootstrap_local_vm

Let me know if you need the other files.
Comment 6 Simone Tiraboschi 2019-01-28 08:40:19 UTC 
The creation of bootstrap VM is failing with:

Jan 22 07:58:03 ovirt python: ansible-command Invoked with warn=True executable=None _uses_shell=False _raw_params=virt-install -n HostedEngineLocal --os-variant rhel7 --virt-type kvm --memory 4096 --vcpus 4 --network network=default,mac=02:00:00:62:dd:2f,model=virtio --disk /var/tmp/localvmcAQyER/images/c1de0d8f-b042-49e5-8976-366750201f1a/2021bbcb-9b9d-4bf8-a168-75600b18991c --import --disk path=/var/tmp/localvmcAQyER/seed.iso,device=cdrom --noautoconsole --rng /dev/random --graphics vnc --video vga --sound none --controller usb,model=none --memballoon none --boot hd,menu=off --clock kvmclock_present=yes removes=None argv=None creates=None chdir=None stdin=None
Jan 22 07:58:03 ovirt systemd: Listening on Virtual machine log manager socket.
Jan 22 07:58:03 ovirt systemd: Started Virtual machine log manager.
Jan 22 07:58:03 ovirt lldpad: recvfrom(Event interface): No buffer space available
Jan 22 07:58:03 ovirt kernel: virbr0: port 2(vnet0) entered blocking state
Jan 22 07:58:03 ovirt kernel: virbr0: port 2(vnet0) entered disabled state
Jan 22 07:58:03 ovirt kernel: device vnet0 entered promiscuous mode
Jan 22 07:58:03 ovirt kernel: virbr0: port 2(vnet0) entered blocking state
Jan 22 07:58:03 ovirt kernel: virbr0: port 2(vnet0) entered listening state
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9284] manager: (vnet0): new Tun device (/org/freedesktop/NetworkManager/Devices/16)
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9356] device (vnet0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9371] keyfile: add connection in-memory (d10d9ee7-08c0-4e4a-8c7a-38dfe1ac85d0,"vnet0")
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9375] device (vnet0): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9378] device (vnet0): Activation: starting connection 'vnet0' (d10d9ee7-08c0-4e4a-8c7a-38dfe1ac85d0)
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9379] device (vnet0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9381] device (vnet0): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9382] device (vnet0): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9382] device (virbr0): bridge port vnet0 was attached
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9382] device (vnet0): Activation: connection 'vnet0' enslaved, continuing activation
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9383] device (vnet0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9387] device (vnet0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9388] device (vnet0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
Jan 22 07:58:03 ovirt NetworkManager[3786]: <info>  [1548161883.9397] device (vnet0): Activation: successful, device activated.
Jan 22 07:58:03 ovirt dbus[3668]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Jan 22 07:58:03 ovirt systemd: Starting Network Manager Script Dispatcher Service...
Jan 22 07:58:03 ovirt dbus[3668]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jan 22 07:58:03 ovirt systemd: Started Network Manager Script Dispatcher Service.
Jan 22 07:58:03 ovirt nm-dispatcher: req:1 'up' [vnet0]: new request (4 scripts)
Jan 22 07:58:03 ovirt nm-dispatcher: req:1 'up' [vnet0]: start running ordered scripts...
Jan 22 07:58:03 ovirt dbus[3668]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service'
Jan 22 07:58:03 ovirt systemd: Starting Virtual Machine and Container Registration Service...
Jan 22 07:58:03 ovirt dbus[3668]: [system] Successfully activated service 'org.freedesktop.machine1'
Jan 22 07:58:03 ovirt systemd: Started Virtual Machine and Container Registration Service.
Jan 22 07:58:03 ovirt systemd-machined: New machine qemu-1-HostedEngineLocal.
Jan 22 07:58:03 ovirt systemd: Started Virtual Machine qemu-1-HostedEngineLocal.
Jan 22 07:58:04 ovirt systemd: Unit iscsi.service cannot be reloaded because it is inactive.
Jan 22 07:58:04 ovirt libvirtd: 2019-01-22 12:58:04.119+0000: 19513: info : libvirt version: 4.5.0, package: 10.el7_6.3 (CentOS BuildSystem <http://bugs.centos.org>, 2018-11-28-20:51:39, x86-01.bsys.centos.org)
Jan 22 07:58:04 ovirt libvirtd: 2019-01-22 12:58:04.119+0000: 19513: info : hostname: ovirt
Jan 22 07:58:04 ovirt libvirtd: 2019-01-22 12:58:04.119+0000: 19513: error : qemuMonitorIORead:609 : Unable to read from monitor: Connection reset by peer
Jan 22 07:58:04 ovirt kernel: virbr0: port 2(vnet0) entered disabled state
Jan 22 07:58:04 ovirt kernel: device vnet0 left promiscuous mode
Jan 22 07:58:04 ovirt kernel: virbr0: port 2(vnet0) entered disabled state
Jan 22 07:58:04 ovirt libvirtd: 2019-01-22 12:58:04.120+0000: 19513: error : qemuProcessReportLogError:1898 : internal error: qemu unexpectedly closed the monitor: 2019-01-22T12:58:04.111867Z qemu-kvm: -chardev pty,id=charserial0: Failed to create PTY: Operation not permitted
Jan 22 07:58:04 ovirt NetworkManager[3786]: <info>  [1548161884.1326] device (vnet0): state change: activated -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
Jan 22 07:58:04 ovirt NetworkManager[3786]: <info>  [1548161884.1329] device (virbr0): bridge port vnet0 was detached
Jan 22 07:58:04 ovirt NetworkManager[3786]: <info>  [1548161884.1329] device (vnet0): released from master device virbr0
Jan 22 07:58:04 ovirt nm-dispatcher: req:2 'down' [vnet0]: new request (4 scripts)
Jan 22 07:58:04 ovirt nm-dispatcher: req:2 'down' [vnet0]: start running ordered scripts...
Jan 22 07:58:04 ovirt systemd-machined: Machine qemu-1-HostedEngineLocal terminated.

Max, can you please set "log_level = 3" in /etc/libvirt/libvirtd.conf and try again?
Comment 7 Simone Tiraboschi 2019-01-28 08:53:04 UTC 
Not sure if really relevant since I don't have any OVH environment,
but on OVF forums somebody reports to set 'devpts /dev/pts devpts gid=5,mode=620 0 0' in /etc/fstab and then execute 'mount -o remount /dev/pts' to avoid this kind of issues.
Comment 8 Simone Tiraboschi 2019-01-28 09:16:16 UTC 
(In reply to Ryan Barry from comment #4)
> As far as I know, HE logs shouldn't contain sensitive information. If they
> do, sounds like a bug to me.
> 
> Is it possibly for you to sanitize those and attach them also?

OK, opening a separate bug on that topic here: https://bugzilla.redhat.com/1669971
Comment 9 Simone Tiraboschi 2019-01-28 09:18:53 UTC 
Failed to reproduce on our environments, I tend to think it's OVH specific.
A possible, untested, workaround in comment 7. Postponing for now.

Max, can you please report if the workaround https://bugzilla.redhat.com/show_bug.cgi?id=1668713#c7 works for you?
Comment 10 Max 2019-01-29 23:15:50 UTC 
The workaround fixed this particularly bug.  Thank you.

I've ran into other issues but I will see if I can workaround them.
Comment 11 Sandro Bonazzola 2019-02-06 08:36:14 UTC 
Closing accordingly to previous comments being an OVH specific issue.