search

saltstack / salt

Software to automate the management and configuration of any infrastructure or application at scale. Install Salt from the Salt package repositories here:
https://docs.saltproject.io/salt/install-guide/en/latest/
Apache License 2.0
14.19k stars 5.48k forks source link

virt.init with overlay_image=True fails to write the overlay image #56113

Open tash opened 4 years ago

tash commented 4 years ago

Description of Issue

On initializing a new VM image through virt.init and providing disks{..., 'overlay_image'=True, ...} an error is produced when the cmd is run internally with __salt__['cmd.run']():

[INFO    ] Cloning qcow2 image /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2 using copy on write
[INFO    ] Executing command ['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"', '"/pool/targethost_default.qcow2"'] in directory '/root'
[ERROR   ] Command '['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"', '"/pool/targethost_default.qcow2"']' failed with return code: 1
[ERROR   ] stdout: qemu-img: "/pool/targethost_default.qcow2": Could not open '"/pool/"/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"': No such file or directory
Could not open backing image to determine size.

It appears that for whatever reason the formatting/escape of double quotes breaks:

https://github.com/saltstack/salt/blob/81eb15264380d82267ffc3c1930410baf1f3fbf1/salt/modules/virt.py#L808-L812

Also, backing files should be provided with qemu-img create -b. Possible fix, that returns no error:

        try:
            if create_overlay and qcow2:
                log.info('Cloning qcow2 image %s using copy on write', sfn)
                __salt__['cmd.run'](
                    'qemu-img create -f qcow2 -o backing_file={0} {1}'
                    .format(sfn, img_dest).split())

Setup

salt-call -l debug virt.init targethost1 2 4096 start=False disk=None 'disks=[{'\''name'\'':'\''default'\'','\''image'\'':'\''/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2'\'','\''overlay_image'\'': True,}]' 'graphics={'\''type'\'':'\''spice'\'','\''port'\'':'\''-1'\'','\''tls_port'\'':'\''-1'\'',}' 'interfaces=[{'\''name'\'':'\''mytestproject-eth'\'','\''type'\'':'\''network'\'','\''source'\'':'\''mytestproject'\'','\''model'\'':'\''virtio'\'','\''mac'\'':'\''00:00:00:11:11:01'\''}]' nic=None

Steps to Reproduce Issue

salt minion with libvirt.

+ salt-call -l debug virt.init targethost1 2 4096 start=False disk=None 'disks=[{'\''name'\'':'\''default'\'','\''image'\'':'\''/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2'\'','\''overlay_image'\'': True,}]' 'graphics={'\''type'\'':'\''spice'\'','\''port'\'':'\''-1'\'','\''tls_port'\'':'\''-1'\'',}' 'interfaces=[{'\''name'\'':'\''mytestproject-eth'\'','\''type'\'':'\''network'\'','\''source'\'':'\''mytestproject'\'','\''model'\'':'\''virtio'\'','\''mac'\'':'\''00:00:00:11:11:01'\''}]' nic=None
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/mytestproject.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/mytestproject.conf
[DEBUG   ] Using cached minion ID from /etc/salt/minion_id: mytestproject-test02
[DEBUG   ] Configuration file path: /etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Grains refresh requested. Refreshing grains.
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/mytestproject.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/mytestproject.conf
[DEBUG   ] Error while parsing IPv4 address: ::1
[DEBUG   ] Expected 4 octets in '::1'
[DEBUG   ] Error while parsing IPv4 address: fe80::c634:6bff:fe5c:715e
[DEBUG   ] Expected 4 octets in 'fe80::c634:6bff:fe5c:715e'
[DEBUG   ] Unable to resolve address fe80::c634:6bff:fe5c:715e: [Errno 0] Resolver Error 0 (no error)
[DEBUG   ] Unable to resolve address 10.211.23.1: [Errno 0] Resolver Error 0 (no error)
[DEBUG   ] Elapsed time getting FQDNs: 0.11088824272155762 seconds
[DEBUG   ] Error while parsing IPv4 address: ::1
[DEBUG   ] Expected 4 octets in '::1'
[DEBUG   ] Error while parsing IPv4 address: fe80::c634:6bff:fe5c:715e
[DEBUG   ] Expected 4 octets in 'fe80::c634:6bff:fe5c:715e'
[DEBUG   ] LazyLoaded zfs.is_supported
[DEBUG   ] Connecting to master. Attempt 1 of 1
[DEBUG   ] Error while parsing IPv4 address: mytestproject-test01
[DEBUG   ] Expected 4 octets in 'mytestproject-test01'
[DEBUG   ] Error while parsing IPv6 address: mytestproject-test01
[DEBUG   ] At least 3 parts expected in 'mytestproject-test01'
[DEBUG   ] "mytestproject-test01" Not an IP address? Assuming it is a hostname.
[DEBUG   ] Master URI: tcp://10.200.126.41:4506
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'mytestproject-test02', 'tcp://10.200.126.41:4506')
[DEBUG   ] Generated random reconnect delay between '1000ms' and '11000ms' (3559)
[DEBUG   ] Setting zmq_reconnect_ivl to '3559ms'
[DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'mytestproject-test02', 'tcp://10.200.126.41:4506', 'clear')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://10.200.126.41:4506
[DEBUG   ] Trying to connect to: tcp://10.200.126.41:4506
[DEBUG   ] salt.crypt.get_rsa_pub_key: Loading public key
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] salt.crypt._get_key_with_evict: Loading private key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] salt.crypt.get_rsa_pub_key: Loading public key
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] Connecting the Minion to the Master publish port, using the URI: tcp://10.200.126.41:4505
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'mytestproject-test02', 'tcp://10.200.126.41:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'mytestproject-test02', 'tcp://10.200.126.41:4506')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://10.200.126.41:4506
[DEBUG   ] Trying to connect to: tcp://10.200.126.41:4506
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded virt.init
[DEBUG   ] LazyLoaded direct_call.execute
[DEBUG   ] LazyLoaded config.get
[DEBUG   ] key: virt.connect, ret: _|-
[DEBUG   ] key: libvirt:connection, ret: _|-
[DEBUG   ] key: virt:connection:uri, ret: _|-
[DEBUG   ] key: libvirt:hypervisor, ret: _|-
[DEBUG   ] key: libvirt:hypervisor, ret: _|-
[DEBUG   ] Using hypervisor kvm
[DEBUG   ] NIC profile is []
[DEBUG   ] Merged NICs: [{'name': 'mytestproject-eth', 'type': 'network', 'source': 'mytestproject', 'model': 'virtio', 'mac': '00:00:00:11:11:01'}]
[DEBUG   ] Image directory from config option `virt:images` is /pool/
[DEBUG   ] Creating disk for VM [ targethost ]: {'name': 'default', 'image': '/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2', 'overlay_image': True, 'format': 'qcow2', 'device': 'disk', 'model': 'virtio', 'filename': 'targethost_default.qcow2', 'source_file': '/pool/targethost_default.qcow2'}
[DEBUG   ] Image destination will be /pool/targethost_default.qcow2
[DEBUG   ] Image destination directory is /pool
[DEBUG   ] Create disk from specified image /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2
[DEBUG   ] LazyLoaded cp.cache_file
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'mytestproject-test02', 'tcp://10.200.126.41:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'mytestproject-test02', 'tcp://10.200.126.41:4506')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://10.200.126.41:4506
[DEBUG   ] Trying to connect to: tcp://10.200.126.41:4506
[DEBUG   ] LazyLoaded cmd.run
[INFO    ] Executing command 'qemu-img info "/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"' in directory '/root'
[DEBUG   ] stdout: image: /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2
file format: qcow2
virtual size: 8.0G (8589934592 bytes)
disk size: 1.4G
cluster_size: 65536
Format specific information:
    compat: 1.1
    lazy refcounts: false
    refcount bits: 16
    corrupt: false
[DEBUG   ] output: image: /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2
file format: qcow2
virtual size: 8.0G (8589934592 bytes)
disk size: 1.4G
cluster_size: 65536
Format specific information:
    compat: 1.1
    lazy refcounts: false
    refcount bits: 16
    corrupt: false
[INFO    ] Cloning qcow2 image /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2 using copy on write
[INFO    ] Executing command ['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"', '"/pool/targethost_default.qcow2"'] in directory '/root'
[ERROR   ] Command '['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"', '"/pool/targethost_default.qcow2"']' failed with return code: 1
[ERROR   ] stdout: qemu-img: "/pool/targethost_default.qcow2": Could not open '"/pool/"/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"': No such file or directory
Could not open backing image to determine size.
[ERROR   ] retcode: 1
[ERROR   ] Command '['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"', '"/pool/targethost_default.qcow2"']' failed with return code: 1
[ERROR   ] output: qemu-img: "/pool/targethost_default.qcow2": Could not open '"/pool/"/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"': No such file or directory
Could not open backing image to determine size.
[DEBUG   ] Apply umask and remove exec bit
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/salt/modules/virt.py", line 787, in _qemu_image_create
    os.chmod(img_dest, mode)
FileNotFoundError: [Errno 2] No such file or directory: '/pool/targethost_default.qcow2'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/salt/cli/caller.py", line 237, in call
    ret['return'] = self.minion.executors[fname](self.opts, data, func, args, kwargs)
  File "/usr/lib/python3.6/site-packages/salt/executors/direct_call.py", line 12, in execute
    return func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/salt/modules/virt.py", line 1478, in init
    img_dest = _qemu_image_create(_disk, create_overlay, saltenv)
  File "/usr/lib/python3.6/site-packages/salt/modules/virt.py", line 792, in _qemu_image_create
    .format(disk_image, err)
salt.exceptions.CommandExecutionError: Problem while copying image. /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2 - [Errno 2] No such file or directory: '/pool/targethost_default.qcow2'
Error running 'virt.init': Problem while copying image. /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2 - [Errno 2] No such file or directory: '/pool/targethost_default.qcow2'

Versions Report

Note: This being openSUSE, the Salt Version might be misleading.

   Static hostname: mytestproject-test02
         Icon name: computer-desktop
           Chassis: desktop
        Machine ID: 65078f94e082487ca37c39de13bd8d7d
           Boot ID: b93b7cbfa06e4ba796578b84150cbfcd
  Operating System: openSUSE Leap 15.1
       CPE OS Name: cpe:/o:opensuse:leap:15.1
            Kernel: Linux 4.12.14-lp151.28.36-default
      Architecture: x86-64
Salt Version:
           Salt: 2019.2.0

Dependency Versions:
           cffi: 1.11.2
       cherrypy: Not Installed
       dateutil: 2.7.3
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.10.1
        libgit2: 0.26.8
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: 2.17
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: 0.26.0
         Python: 3.6.9 (default, Oct 29 2019, 10:39:36) [GCC]
   python-gnupg: Not Installed
         PyYAML: 3.13
          PyZMQ: 17.0.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.2.3

System Versions:
           dist:
         locale: UTF-8
        machine: x86_64
        release: 4.12.14-lp151.28.36-default
         system: Linux
        version: Not Installed
DmitryKuzmenko commented 4 years ago

Reproduction steps:

# mkdir /pool/
# qemu-img create -f qcow2 /pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2 8G
# salt-call --local -l debug virt.init targethost1 2 4096 start=False disk=None disks="[{'name':'default','image':'/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2','overlay_image': True,}]"

Output on default configuration is slightly different because virt:images path is default value:

[ERROR   ] Command '['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"', '"/srv/salt-images/targethost1_default.qcow2"']' failed with return code: 1
[ERROR   ] stdout: qemu-img: "/srv/salt-images/targethost1_default.qcow2": Could not open '"/srv/salt-images/"/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"': No such file or directory
Could not open backing image to determine size.
[ERROR   ] retcode: 1
[ERROR   ] Command '['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"', '"/srv/salt-images/targethost1_default.qcow2"']' failed with return code: 1
[ERROR   ] output: qemu-img: "/srv/salt-images/targethost1_default.qcow2": Could not open '"/srv/salt-images/"/pool/mytestproject-Leap-15.1.x86_64-1.15.1.qcow2"': No such file or directory
Could not open backing image to determine size.

Reproducible on Salt >= 2019.2.1.

The fix mentioned by @tash resolves the issue but it's not a proper fix because it will break paths with spaces.

tash commented 4 years ago

~~Yeah, my solution is just a bandaid. ~~

Also: https://github.com/saltstack/salt/blob/81eb15264380d82267ffc3c1930410baf1f3fbf1/salt/modules/qemu_img.py#L44-L50

Similar call, can someone check this?

tash commented 4 years ago

@DmitryKuzmenko Apparently providing " to account for spaces in given paths is superfluous. At some point a subprocess call is made. This does not work (same error as reported):

>>> subprocess.run(['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/this is a test.qcow2"', '/pool/itworks.qcow2'])
qemu-img: /pool/itworks.qcow2: Could not open '/pool/"/pool/this is a test.qcow2"': No such file or directory
Could not open backing image to determine size.
CompletedProcess(args=['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file="/pool/this is a test.qcow2"', '/pool/itworks.qcow2'], returncode=1)

This does work:

>>> subprocess.run(['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file=/pool/this is a test.qcow2', '/pool/itworks.qcow2'])
Formatting '/pool/itworks.qcow2', fmt=qcow2 size=8589934592 backing_file=/pool/this is a test.qcow2 cluster_size=65536 lazy_refcounts=off refcount_bits=16
CompletedProcess(args=['qemu-img', 'create', '-f', 'qcow2', '-o', 'backing_file=/pool/this is a test.qcow2', '/pool/itworks.qcow2'], returncode=0)
DmitryKuzmenko commented 4 years ago

@tash I've just put a note for a person who will be fixing this issue. This PR #52160 introduced that quotes as a try to resolve some issues with spaces. Your issue shows that it's not enough and we still have to work on fixing this. Thank you for PR and analysis. Your issue will be fixed in one of future releases.