Bug 1329387

Summary: Useless 'cannot stat /var/run/vdsm/netconf' message from vdsm
Product: [oVirt] vdsm Reporter: Fabrice Bacchella <fabrice.bacchella>
Component: CoreAssignee: Edward Haas <edwardh>
Status: CLOSED CURRENTRELEASE QA Contact: Meni Yakove <myakove>
Severity: low Docs Contact:
Priority: medium    
Version: 4.18.0CC: bugs, danken, edwardh, fabrice.bacchella, nsoffer, ybronhei
Target Milestone: ovirt-4.0.6Flags: rule-engine: ovirt-4.2?
rule-engine: planning_ack?
rule-engine: devel_ack?
rule-engine: testing_ack?
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-01-19 07:36:55 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Network RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1329323    

Description Fabrice Bacchella 2016-04-21 19:11:34 UTC
From an host, in the log :
On a host, in upgrade.log:
MainThread::DEBUG::2016-04-14 16:38:08,656::utils::689::root::(execCmd) SUCCESS: <err> = 'cp: cannot stat \xe2\x80\x98/var/run/vdsm/netconf\xe2\x80\x99: No such file or directory\n'; <rc> = 0

a DEBUG log that I didn't request, a SUCCESS with an error, a totally fucked up command.

Why debug log level ? I didn't request it.

Why a SUCCESS on a message that says 'cannot stat' ?

Where are those \xe2\x80 comming from ?

Comment 1 Red Hat Bugzilla Rules Engine 2016-04-24 06:10:42 UTC
Bug tickets must have version flags set prior to targeting them to a release. Please ask maintainer to set the correct version flags and only then set the target milestone.

Comment 2 Yaniv Bronhaim 2016-04-24 12:27:12 UTC
Dear Fabrice, please try to avoid personal feelings statements about issues and describe the steps you did to reproduce this print. 
Vdsm reports DEBUG level logs by default. you can modify it in /etc/vdsm/logger.conf file. second, I think it relates to the same issue specified in Bug 1324731, but I'll check it more deeply, same for the unicode odd characters that you see. steps for reproduction will help. did you upgrade vdsm from certain version? can you share vdsm.log as well?

Edy, please check. upgrade.log relates to network flows, can you investigate it?

Comment 3 Fabrice Bacchella 2016-04-25 15:31:18 UTC
I have just reformatted and reinstalled from scratch an host after removed it from ovirt, and got the exact same message:

MainThread::DEBUG::2016-04-25 16:31:20,637::utils::689::root::(execCmd) SUCCESS: <err> = 'cp: cannot stat \xe2\x80\x98/var/run/vdsm/netconf\xe2\x80\x99: No such file or directory\n'; <rc> = 0

So upgrade.log is generated even before starting vdsm, as the first line of vdsm.log is :
MainThread::INFO::2016-04-25 16:31:22,204::vdsm::162::vds::(run) (PID: 6628) I am the actual vdsm 4.17.26-0.el7.centos XXXX (3.10.0-327.13.1.el7.x86_64)

The full upgrade.log is:
MainThread::DEBUG::2016-04-25 16:31:20,394::upgrade::90::upgrade::(apply_upgrade) Running upgrade upgrade-unified-persistence
MainThread::DEBUG::2016-04-25 16:31:20,414::libvirtconnection::161::root::(get) trying to connect libvirt
MainThread::DEBUG::2016-04-25 16:31:20,624::utils::671::root::(execCmd) /usr/bin/taskset --cpu-list 0-31 /sbin/ip route show to 0.0.0.0/0 table main (cwd None)
MainThread::DEBUG::2016-04-25 16:31:20,626::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2016-04-25 16:31:20,626::unified_persistence::46::root::(run) upgrade-unified-persistence upgrade persisting networks {} and bondings {}
MainThread::INFO::2016-04-25 16:31:20,626::netconfpersistence::187::root::(_clearDisk) Clearing /var/run/vdsm/netconf/nets/ and /var/run/vdsm/netconf/bonds/
MainThread::DEBUG::2016-04-25 16:31:20,627::netconfpersistence::195::root::(_clearDisk) No existent config to clear.
MainThread::INFO::2016-04-25 16:31:20,627::netconfpersistence::187::root::(_clearDisk) Clearing /var/run/vdsm/netconf/nets/ and /var/run/vdsm/netconf/bonds/
MainThread::DEBUG::2016-04-25 16:31:20,627::netconfpersistence::195::root::(_clearDisk) No existent config to clear.
MainThread::INFO::2016-04-25 16:31:20,627::netconfpersistence::131::root::(save) Saved new config RunningConfig({}, {}) to /var/run/vdsm/netconf/nets/ and /var/run/vdsm/netconf/bonds/
MainThread::DEBUG::2016-04-25 16:31:20,627::utils::671::root::(execCmd) /usr/bin/taskset --cpu-list 0-31 /usr/share/vdsm/vdsm-store-net-config unified (cwd None)
MainThread::DEBUG::2016-04-25 16:31:20,637::utils::689::root::(execCmd) SUCCESS: <err> = 'cp: cannot stat \xe2\x80\x98/var/run/vdsm/netconf\xe2\x80\x99: No such file or directory\n'; <rc> = 0
MainThread::DEBUG::2016-04-25 16:31:20,637::upgrade::51::upgrade::(_upgrade_seal) Upgrade upgrade-unified-persistence successfully performed

I don't know if it's linked, but locale for this server is C:
$ locale
LANG=C
LC_CTYPE="C"
LC_NUMERIC="C"
LC_TIME="C"
LC_COLLATE="C"
LC_MONETARY="C"
LC_MESSAGES="C"
LC_PAPER="C"
LC_NAME="C"
LC_ADDRESS="C"
LC_TELEPHONE="C"
LC_MEASUREMENT="C"
LC_IDENTIFICATION="C"
LC_ALL=

Comment 4 Nir Soffer 2016-05-09 13:52:07 UTC
Fabrice,

Let me translate these logs for you:

MainThread::DEBUG::2016-04-25 16:31:20,627::utils::671::root::(execCmd) /usr/bin/taskset --cpu-list 0-31 /usr/share/vdsm/vdsm-store-net-config unified (cwd None)

Here we run the command:

    /usr/bin/taskset --cpu-list 0-31 /usr/share/vdsm/vdsm-store-net-config unified

MainThread::DEBUG::2016-04-25 16:31:20,637::utils::689::root::(execCmd) SUCCESS: <err> = 'cp: cannot stat \xe2\x80\x98/var/run/vdsm/netconf\xe2\x80\x99: No such file or directory\n'; <rc> = 0

Here the command terminated with exit code 0 - so this is a SUCCESS.

The command wrote some data to stderr:

    'cp: cannot stat \xe2\x80\x98/var/run/vdsm/netconf\xe2\x80\x99: No such file or directory\n'

We log stderr of all commands - why we do this is good question. Maybe the
the contents of stderr was useful for debugging in the past.

What are the xe2\x80\x98 - good question - our networking team responsible for
this command (/usr/share/vdsm/vdsm-store-net-config) should answer this.

Why we log DEBUG message? it help us to support the system. We plan to move to 
INFO level by default in future version.

Edi, can you take a look at the error message from vdsm-store-net-config?

Nir

Comment 5 Edward Haas 2016-07-14 13:48:31 UTC
In vdsm-store-net-config, running-config is persisted by copying it to a dedicated location.
If for some edge case scenario, the running-config is absent an error message appeared in the log but without failing the script run.

Q1: Do we still need the upgrade step in 4.x? (it fails in that scenario)
Q2: Are we ok with the missing running config? If we are, the proposed patch handles it.

Comment 6 Edward Haas 2017-01-19 07:36:55 UTC
The patch that avoids the mentioned error message has been merged long ago, closing this bug.