Bug 1274063

Summary: vdsm fails to start due to incorrect permissions on /tmp/ovirt.log
Product: [oVirt] vdsm Reporter: Ivan Bulatovic <combuster>
Component: GeneralAssignee: Dan Kenigsberg <danken>
Status: CLOSED NEXTRELEASE QA Contact: Meni Yakove <myakove>
Severity: urgent Docs Contact:
Priority: urgent    
Version: ---CC: bugs, danken, dfediuck, didi, fdeutsch, lveyde, rmartins, sbonazzo, stirabos
Target Milestone: ovirt-3.6.1Flags: danken: ovirt-3.6.z?
danken: ovirt-4.0.0?
rule-engine: planning_ack?
fdeutsch: devel_ack+
rule-engine: testing_ack?
Target Release: 4.17.11   
Hardware: x86_64   
OS: Linux   
Whiteboard: network
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-11-18 10:49:30 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Network RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
Attachments:
Description Flags
chown the /tmp/ovirt.log none

Description Ivan Bulatovic 2015-10-21 19:42:53 UTC
Description of problem:

On a clean install from ovirt-3.6-snapshot repo, vdsm fails to start during hosted-engine deployment or adding a node to the existing engine.

systemctl status vdsmd.service:

Process: 25532 ExecStart=/usr/share/vdsm/daemonAdapter -0 /dev/null -1 /dev/null -2 /dev/null /usr/share/vdsm/vdsm (code=exited, status=1/FAILURE)
 Main PID: 25532 (code=exited, status=1/FAILURE);         : 25577 (vdsmd_init_comm)

Snip from /var/log/mom.log

2015-10-21 21:19:04,556 - mom - INFO - MOM starting
2015-10-21 21:19:04,581 - mom.HostMonitor - INFO - Host Monitor starting
2015-10-21 21:19:04,581 - mom - INFO - hypervisor interface vdsmxmlrpc
2015-10-21 21:19:07,372 - mom - ERROR - Failed to initialize MOM threads
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/mom/__init__.py", line 29, in run
    hypervisor_iface = self.get_hypervisor_interface()
  File "/usr/lib/python2.7/site-packages/mom/__init__.py", line 216, in get_hypervisor_interface
    module = __import__('mom.HypervisorInterfaces.' + name + 'Interface', None, None, name)
  File "/usr/lib/python2.7/site-packages/mom/HypervisorInterfaces/vdsmxmlrpcInterface.py", line 24, in <module>
    from vdsm import vdscli
  File "/usr/lib/python2.7/site-packages/vdsm/vdscli.py", line 29, in <module>
    from . import sslutils
  File "/usr/lib/python2.7/site-packages/vdsm/sslutils.py", line 28, in <module>
    from vdsm.utils import (
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 66, in <module>
    from ovirtnode import ovirtfunctions
  File "/usr/lib/python2.7/site-packages/ovirtnode/ovirtfunctions.py", line 1867, in <module>
    logger = setup_custom_logger()
  File "/usr/lib/python2.7/site-packages/ovirtnode/ovirtfunctions.py", line 1858, in setup_custom_logger
    handler = logging.FileHandler(log_file)
  File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__
    StreamHandler.__init__(self, self._open())
  File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open
    stream = open(self.baseFilename, self.mode)
IOError: [Errno 13] Permission denied: '/tmp/ovirt.log'

Changing permissions from root:root to vdsm:kvm on /tmp/ovirt.log fixes the issue, and vdsm starts successfully.

Selinux is in permissive mode, but it was enforced during the installation of the components (no denials from the logs as far as I can tell).

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

vdsm-4.17.9-15.git1a7d1d3.el7.noarch
mom-0.5.1-2.el7.noarch
ovirt-node-3.3.0-0.14.ovirt36.20151012220735.git5f84da0.el7

Comment 2 Dan Kenigsberg 2015-10-22 11:18:33 UTC
Apparently, the mere

   from ovirtnode import ovirtfunctions

logs onto /tmp/ovirt.log.

If the first import happened to be in root context, we'd get this error.

Comment 3 Red Hat Bugzilla Rules Engine 2015-10-22 11:18:36 UTC
This bug is not marked for z-stream, yet the milestone is for a z-stream version, therefore the milestone has been reset.
Please set the correct milestone or add the z-stream flag.

Comment 5 Ivan Bulatovic 2015-10-22 18:48 UTC
Created attachment 1085643 [details]
chown the /tmp/ovirt.log

When I remove ovirt.log from the tmp directory and reboot, vdsm starts successfully. Supervdsmd creates the temporary log file with root privileges, and when vdsm starts with user privileges, it changes ownership of /tmp/ovirt.log to vdsm:kvm.

Comment 6 Fabian Deutsch 2015-10-23 07:15:32 UTC
This is an relict from old ovirt-node times.
The logging is setup when ovirtnode.ovirtfunctions is getting imported, which is not good.

Normally the import happens because of persistence, in that case ovirt.node.utils.fs.Config can be used these days, which should not suffer the import problems.

Comment 7 Red Hat Bugzilla Rules Engine 2015-10-23 10:06:53 UTC
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.

Comment 8 Ivan Bulatovic 2015-10-23 18:44:20 UTC
(In reply to Fabian Deutsch from comment #6)
> 
> Normally the import happens because of persistence, in that case
> ovirt.node.utils.fs.Config can be used these days, which should not suffer
> the import problems.

Yes, forcing import from ovirt.node.utils.fs (commenting out importing from ovirtnode) in vdsm/utils.py does not prevent mom-vdsm and vdsm units from starting anymore.

Thanks Fabian, I caught this by accident, thought I should report it (even though I don't fully understand implications of it all, yet).

Comment 9 Fabian Deutsch 2015-11-03 11:17:12 UTC
Ivan, cool, nice to hear that it worked.

Comment 10 Fabian Deutsch 2015-11-03 11:18:39 UTC
Moving this over to vdsm where the patch resides.