Attachment 1447994 Details for Bug 1586280 – supervdsm logs

supervdsm logs

supervdsm.log (text/plain), 29.37 KB, created by Simone Tiraboschi on 2018-06-05 21:18:40 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Simone Tiraboschi

Created: 2018-06-05 21:18:40 UTC

Size: 29.37 KB

patch

obsolete

>restore-net::INFO::2018-06-05 17:51:18,115::restore_net_config::433::root::(restore) starting network restoration.
>restore-net::DEBUG::2018-06-05 17:51:18,117::cmdutils::150::root::(exec_cmd) lshw -json -disable usb -disable pcmcia -disable isapnp -disable ide -disable scsi -disable dmi -disable memory -disable cpuinfo (cwd None)
>restore-net::DEBUG::2018-06-05 17:51:18,245::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>restore-net::DEBUG::2018-06-05 17:51:18,281::restore_net_config::345::root::(_wait_for_for_all_devices_up) All devices are up.
>restore-net::ERROR::2018-06-05 17:51:18,287::restore_net_config::442::root::(restore) unified restoration failed.
>Traceback (most recent call last):
>  File "/usr/lib/python2.7/site-packages/vdsm/network/restore_net_config.py", line 436, in restore
>    unified_restoration()
>  File "/usr/lib/python2.7/site-packages/vdsm/network/restore_net_config.py", line 118, in unified_restoration
>    classified_conf = _classify_nets_bonds_config(available_config)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/restore_net_config.py", line 246, in _classify_nets_bonds_config
>    net_info = NetInfo(netswitch.configurator.netinfo())
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netswitch/configurator.py", line 323, in netinfo
>    _netinfo = netinfo_get(vdsmnets, compatibility)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netinfo/cache.py", line 137, in get
>    return _get(vdsmnets)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netinfo/cache.py", line 62, in _get
>    devices_info = _devices_report(ipaddrs, routes)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netinfo/cache.py", line 107, in _devices_report
>    devinfo = devs_report['bondings'][dev.name] = bonding.info(dev)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netinfo/bonding.py", line 72, in info
>    bond = Bond(link.name)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_driver.py", line 40, in __init__
>    super(BondSysFS, self).__init__(name, slaves, options)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/__init__.py", line 44, in __init__
>    self._import_existing()
>  File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_driver.py", line 129, in _import_existing
>    self._options = sysfs_options.get_options(self._properties)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options.py", line 142, in get_options
>    opts_keys = _filter_out_default_opts(bond_properties, opts_keys)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options.py", line 149, in _filter_out_default_opts
>    defaults = getDefaultBondingOptions(mode)
>  File "/usr/lib/python2.7/site-packages/vdsm/common/cache.py", line 41, in __call__
>    value = self.func(*args)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options.py", line 212, in getDefaultBondingOptions
>    defaults = getAllDefaultBondingOptions()
>  File "/usr/lib/python2.7/site-packages/vdsm/common/cache.py", line 41, in __call__
>    value = self.func(*args)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options.py", line 226, in getAllDefaultBondingOptions
>    with open(BONDING_DEFAULTS) as defaults:
>IOError: [Errno 2] No such file or directory: '/var/run/vdsm/bonding-defaults.json'
>MainThread::DEBUG::2018-06-05 18:06:48,636::supervdsm_server::287::SuperVdsm.Server::(main) Making sure I'm root - SuperVdsm
>MainThread::DEBUG::2018-06-05 18:06:48,636::supervdsm_server::296::SuperVdsm.Server::(main) Parsing cmd args
>MainThread::DEBUG::2018-06-05 18:06:48,636::supervdsm_server::299::SuperVdsm.Server::(main) Cleaning old socket /var/run/vdsm/svdsm.sock
>MainThread::DEBUG::2018-06-05 18:06:48,636::supervdsm_server::303::SuperVdsm.Server::(main) Setting up keep alive thread
>MainThread::DEBUG::2018-06-05 18:06:48,636::supervdsm_server::309::SuperVdsm.Server::(main) Creating remote object manager
>Thread-1::DEBUG::2018-06-05 18:06:48,637::concurrent::192::root::(run) START thread <Thread(Thread-1, started daemon 139850424829696)> (func=<bound method Server.serve_forever of <multiprocessing.managers.Server object at 0x7f31800ad390>>, args=(), kwargs={})
>MainThread::INFO::2018-06-05 18:06:48,638::fileUtils::246::storage.fileUtils::(chown) Changing owner for /var/run/vdsm/svdsm.sock, to (36:36)
>MainThread::DEBUG::2018-06-05 18:06:48,638::supervdsm_server::319::SuperVdsm.Server::(main) Started serving super vdsm object
>MainThread::DEBUG::2018-06-05 18:06:48,645::cmdutils::150::root::(exec_cmd) /usr/bin/systemctl status lldpad.service (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,695::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,695::cmdutils::150::root::(exec_cmd) /usr/sbin/lldptool -ping (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,720::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,720::cmdutils::150::root::(exec_cmd) lshw -json -disable usb -disable pcmcia -disable isapnp -disable ide -disable scsi -disable dmi -disable memory -disable cpuinfo (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,916::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,919::cmdutils::150::root::(exec_cmd) /usr/sbin/lldptool get-lldp -i eth0 adminStatus (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,924::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,924::cmdutils::150::root::(exec_cmd) /usr/sbin/lldptool set-lldp -i eth0 adminStatus=rx (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,927::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,928::cmdutils::150::root::(exec_cmd) /usr/sbin/lldptool get-lldp -i eth1 adminStatus (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,931::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,931::cmdutils::150::root::(exec_cmd) /usr/sbin/lldptool set-lldp -i eth1 adminStatus=rx (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,934::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,935::cmdutils::150::root::(exec_cmd) /usr/sbin/lldptool get-lldp -i eth2 adminStatus (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,938::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2018-06-05 18:06:48,938::cmdutils::150::root::(exec_cmd) /usr/sbin/lldptool set-lldp -i eth2 adminStatus=rx (cwd None)
>MainThread::DEBUG::2018-06-05 18:06:48,942::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>restore-net::INFO::2018-06-05 18:06:49,892::restore_net_config::433::root::(restore) starting network restoration.
>restore-net::DEBUG::2018-06-05 18:06:49,895::cmdutils::150::root::(exec_cmd) lshw -json -disable usb -disable pcmcia -disable isapnp -disable ide -disable scsi -disable dmi -disable memory -disable cpuinfo (cwd None)
>restore-net::DEBUG::2018-06-05 18:06:50,008::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>restore-net::DEBUG::2018-06-05 18:06:50,045::restore_net_config::345::root::(_wait_for_for_all_devices_up) All devices are up.
>restore-net::DEBUG::2018-06-05 18:06:50,079::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>restore-net::DEBUG::2018-06-05 18:06:50,082::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>restore-net::DEBUG::2018-06-05 18:06:50,082::cmdutils::150::root::(exec_cmd) /usr/share/openvswitch/scripts/ovs-ctl status (cwd None)
>restore-net::DEBUG::2018-06-05 18:06:50,095::cmdutils::158::root::(exec_cmd) FAILED: <err> = ''; <rc> = 1
>restore-net::INFO::2018-06-05 18:06:50,097::netconfpersistence::68::root::(setBonding) Adding bond0({'nics': ['eth1', 'eth2'], 'switch': 'legacy', 'options': 'miimon=100 mode=4'})
>restore-net::INFO::2018-06-05 18:06:50,097::restore_net_config::122::root::(unified_restoration) Remove networks ({}) and bonds ({}).
>restore-net::INFO::2018-06-05 18:06:50,098::restore_net_config::130::root::(unified_restoration) Setup networks ({}) and bonds ({}).
>restore-net::INFO::2018-06-05 18:06:50,098::restore_net_config::445::root::(restore) restoration completed successfully.
>MainProcess::DEBUG::2018-06-05 18:06:53,156::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call multipath_status with () {}
>MainProcess::DEBUG::2018-06-05 18:06:53,157::commands::65::storage.Misc.excCmd::(execCmd) /usr/bin/taskset --cpu-list 0-3 /usr/sbin/dmsetup status --target multipath (cwd None)
>MainProcess::DEBUG::2018-06-05 18:06:53,161::commands::86::storage.Misc.excCmd::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess::DEBUG::2018-06-05 18:06:53,162::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return multipath_status with {}
>MainProcess|hsm/init::DEBUG::2018-06-05 18:06:53,275::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call hbaRescan with () {}
>MainProcess|hsm/init::DEBUG::2018-06-05 18:06:53,275::commands::65::storage.HBA::(execCmd) /usr/bin/taskset --cpu-list 0-3 /usr/libexec/vdsm/fc-scan (cwd None)
>MainProcess|hsm/init::DEBUG::2018-06-05 18:06:53,406::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return hbaRescan with None
>MainProcess|vm/9e396244::DEBUG::2018-06-05 18:06:53,546::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call ovs_bridge with () {}
>MainProcess|vm/9e396244::DEBUG::2018-06-05 18:06:53,547::cmdutils::150::root::(exec_cmd) /usr/share/openvswitch/scripts/ovs-ctl status (cwd None)
>MainProcess|vm/9e396244::DEBUG::2018-06-05 18:06:53,569::cmdutils::158::root::(exec_cmd) FAILED: <err> = ''; <rc> = 1
>MainProcess|vm/9e396244::DEBUG::2018-06-05 18:06:53,569::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return ovs_bridge with None
>MainProcess|vm/9e396244::DEBUG::2018-06-05 18:06:53,592::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call prepareVmChannel with () {}
>MainProcess|vm/9e396244::ERROR::2018-06-05 18:06:53,593::supervdsm_server::100::SuperVdsm.ServerCallback::(wrapper) Error in prepareVmChannel
>Traceback (most recent call last):
>  File "/usr/lib/python2.7/site-packages/vdsm/supervdsm_server.py", line 98, in wrapper
>    res = func(*args, **kwargs)
>  File "/usr/lib/python2.7/site-packages/vdsm/supervdsm_api/virt.py", line 35, in prepareVmChannel
>    fsinfo = os.stat(socketFile)
>OSError: [Errno 2] No such file or directory: '/var/lib/libvirt/qemu/channels/9e396244-1978-4ff2-9bd4-1010d06ff1bc.com.redhat.rhevm.vdsm'
>MainProcess|jsonrpc/3::DEBUG::2018-06-05 18:07:13,190::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call ksmTune with () {}
>MainProcess|jsonrpc/3::DEBUG::2018-06-05 18:07:13,191::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return ksmTune with None
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,334::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call network_caps with () {}
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,383::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,389::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,391::nic::41::root::(speed) cannot read eth2 speed
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,391::nic::41::root::(speed) cannot read eth1 speed
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,392::nic::41::root::(speed) cannot read eth0 speed
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,392::nic::41::root::(speed) cannot read eth1 speed
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,393::nic::41::root::(speed) cannot read eth2 speed
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:21,394::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return network_caps with {'bridges': {'virbr0': {'ipv6autoconf': False, 'addr': '192.168.122.1', 'dhcpv6': False, 'ipv6addrs': [], 'gateway': '', 'dhcpv4': False, 'netmask': '255.255.255.0', 'ipv4defaultroute': False, 'stp': 'on', 'ipv4addrs': ['192.168.122.1/24'], 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['vnet0', 'virbr0-nic'], 'opts': {'multicast_last_member_count': '2', 'vlan_protocol': '0x8100', 'hash_elasticity': '4', 'multicast_query_response_interval': '1000', 'group_fwd_mask': '0x0', 'multicast_snooping': '1', 'multicast_startup_query_interval': '3125', 'hello_timer': '121', 'multicast_querier_interval': '25500', 'max_age': '2000', 'hash_max': '512', 'stp_state': '1', 'topology_change_detected': '0', 'priority': '32768', 'multicast_igmp_version': '2', 'multicast_membership_interval': '26000', 'root_path_cost': '0', 'root_port': '0', 'multicast_stats_enabled': '0', 'multicast_startup_query_count': '2', 'nf_call_iptables': '0', 'vlan_stats_enabled': '0', 'topology_change': '0', 'hello_time': '200', 'root_id': '8000.525400081815', 'bridge_id': '8000.525400081815', 'topology_change_timer': '0', 'ageing_time': '30000', 'nf_call_ip6tables': '0', 'multicast_mld_version': '1', 'gc_timer': '12092', 'nf_call_arptables': '0', 'group_addr': '1:80:c2:0:0:0', 'multicast_last_member_interval': '100', 'default_pvid': '1', 'multicast_query_interval': '12500', 'multicast_query_use_ifaddr': '0', 'tcn_timer': '0', 'multicast_router': '1', 'vlan_filtering': '0', 'multicast_querier': '0', 'forward_delay': '200'}}}, 'bondings': {'bond0': {'ipv4addrs': [], 'active_slave': '', 'ad_aggregator_id': '1', 'netmask': '', 'ad_partner_mac': '00:00:00:00:00:00', 'hwaddr': '00:1a:4a:16:01:71', 'speed': 0, 'gateway': '', 'ipv6autoconf': True, 'addr': '', 'dhcpv6': False, 'ipv6addrs': [], 'mtu': '1500', 'dhcpv4': True, 'switch': 'legacy', 'ipv4defaultroute': False, 'slaves': ['eth2', 'eth1'], 'ipv6gateway': '::', 'opts': {'miimon': '100', 'mode': '4'}}}, 'nameservers': ['192.168.1.1'], 'nics': {'eth2': {'permhwaddr': '00:1a:4a:16:01:72', 'ipv6autoconf': False, 'addr': '', 'speed': 0, 'dhcpv6': False, 'ipv6addrs': [], 'ad_aggregator_id': '2', 'dhcpv4': False, 'netmask': '', 'ipv4defaultroute': False, 'ipv4addrs': [], 'hwaddr': '00:1a:4a:16:01:71', 'mtu': '1500', 'ipv6gateway': '::', 'gateway': ''}, 'eth1': {'permhwaddr': '00:1a:4a:16:01:71', 'ipv6autoconf': False, 'addr': '', 'speed': 0, 'dhcpv6': False, 'ipv6addrs': [], 'ad_aggregator_id': '1', 'dhcpv4': False, 'netmask': '', 'ipv4defaultroute': False, 'ipv4addrs': [], 'hwaddr': '00:1a:4a:16:01:71', 'mtu': '1500', 'ipv6gateway': '::', 'gateway': ''}, 'eth0': {'ipv6autoconf': True, 'addr': '192.168.1.14', 'speed': 0, 'dhcpv6': False, 'ipv6addrs': [], 'mtu': '1500', 'dhcpv4': True, 'netmask': '255.255.255.0', 'ipv4defaultroute': True, 'ipv4addrs': ['192.168.1.14/24'], 'hwaddr': '00:1a:4a:16:01:70', 'ipv6gateway': '::', 'gateway': '192.168.1.1'}}, 'supportsIPv6': True, 'vlans': {'bond0.123': {'iface': 'bond0', 'ipv6autoconf': True, 'addr': '192.168.2.14', 'dhcpv6': False, 'ipv6addrs': [], 'vlanid': 123, 'mtu': '1500', 'dhcpv4': False, 'netmask': '255.255.255.0', 'ipv4defaultroute': False, 'ipv4addrs': ['192.168.2.14/24'], 'ipv6gateway': '::', 'gateway': ''}}, 'networks': {}}
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:24,325::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call get_pti with () {}
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:24,326::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return get_pti with 1
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:24,326::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call get_retp with () {}
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:24,326::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return get_retp with 1
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:24,326::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call get_ibrs with () {}
>MainProcess|jsonrpc/5::DEBUG::2018-06-05 18:07:24,326::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return get_ibrs with 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,222::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call setupNetworks with ({}, {u'connectivityCheck': u'true', u'connectivityTimeout': 120}) {}
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,222::api::202::root::(setupNetworks) Setting up network according to configuration: networks:{u'ovirtmgmt': {u'ipv6autoconf': True, u'vlan': u'123', u'ipaddr': u'192.168.2.14', u'switch': u'legacy', u'mtu': 1500, u'bonding': u'bond0', u'dhcpv6': False, u'STP': u'no', u'bridged': u'true', u'netmask': u'255.255.255.0', u'defaultRoute': True}}, bondings:{}, options:{u'connectivityCheck': u'true', u'connectivityTimeout': 120}
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,226::api::209::root::(setupNetworks) Validating configuration
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,263::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,268::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:07:25,270::netconfpersistence::68::root::(setBonding) Adding bond0({'nics': ['eth1', 'eth2'], 'switch': 'legacy', 'options': 'miimon=100 mode=4'})
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:07:25,271::netconfpersistence::57::root::(setNetwork) Adding network ovirtmgmt({u'ipv6autoconf': True, 'nameservers': ['192.168.1.1'], u'vlan': 123, u'ipaddr': u'192.168.2.14', u'bonding': u'bond0', u'mtu': 1500, u'switch': u'legacy', u'dhcpv6': False, 'stp': False, u'bridged': True, u'netmask': u'255.255.255.0', u'defaultRoute': True, 'bootproto': 'none'})
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,297::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,300::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:25,303::commands::65::root::(execCmd) /usr/bin/taskset --cpu-list 0-3 /usr/libexec/vdsm/hooks/before_network_setup/50_fcoe (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,223::commands::86::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:07:26,224::hooks::110::root::(_runHooksDir) /usr/libexec/vdsm/hooks/before_network_setup/50_fcoe: rc=0 err=
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,224::api::235::root::(_setup_networks) Applying...
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,265::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,269::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,298::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,301::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:07:26,303::netconfpersistence::68::root::(setBonding) Adding bond0({'nics': ['eth1', 'eth2'], 'switch': 'legacy', 'options': 'miimon=100 mode=4'})
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,304::legacy_switch::484::root::(bonds_setup) Starting bondings setup. bonds={u'bond0': {u'hwaddr': u'00:1a:4a:16:01:71', u'nics': [u'eth1', u'eth2'], u'switch': u'legacy', u'options': u'miimon=100 mode=4'}}, in_rollback=False
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,331::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,334::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,362::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,364::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,365::legacy_switch::549::root::(_bonds_edit) Editing bond u'bond0', removing slaves set([])
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,403::cmdutils::150::root::(exec_cmd) /sbin/tc qdisc show (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,406::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,408::legacy_switch::559::root::(_bonds_edit) Editing Bond(bond0: [Nic(eth1), Nic(eth2)]) with options u'mode=4 miimon=100'
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,408::cmdutils::150::root::(exec_cmd) /bin/systemctl status NetworkManager (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:26,437::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:07:28,467::dhclient::107::root::(kill) Stopping dhclient-4 on bond0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,469::cmdutils::150::root::(exec_cmd) /sbin/ip addr flush dev bond0 scope global (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,486::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,487::ifcfg::479::root::(_atomicBackup) Backed up /etc/sysconfig/network-scripts/ifcfg-bond0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,488::ifcfg::512::root::(_persistentBackup) backing up ifcfg-bond0: BONDING_OPTS="downdelay=0 miimon=100 mode=802.3ad updelay=0"
>TYPE=Bond
>BONDING_MASTER=yes
>PROXY_METHOD=none
>BROWSER_ONLY=no
>BOOTPROTO=dhcp
>DEFROUTE=yes
>IPV4_FAILURE_FATAL=no
>IPV6INIT=yes
>IPV6_AUTOCONF=yes
>IPV6_DEFROUTE=yes
>IPV6_FAILURE_FATAL=no
>IPV6_ADDR_GEN_MODE=stable-privacy
>NAME=bond0
>UUID=9041fd4a-c5b1-4d79-8a4d-91463d852ba1
>DEVICE=bond0
>ONBOOT=yes
>AUTOCONNECT_SLAVES=yes
>
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,488::ifcfg::462::root::(writeBackupFile) Persistently backed up /var/lib/vdsm/netconfback/ifcfg-bond0 (until next 'set safe config')
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,488::ifcfg::569::root::(writeConfFile) Writing to file /etc/sysconfig/network-scripts/ifcfg-bond0 configuration:
># Generated by VDSM version 4.20.29-1.git58011fd.el7
>DEVICE=bond0
>BONDING_OPTS='mode=4 miimon=100'
>MACADDR=00:1a:4a:16:01:71
>ONBOOT=yes
>BOOTPROTO=dhcp
>MTU=1500
>DEFROUTE=yes
>NM_CONTROLLED=no
>IPV6INIT=yes
>IPV6_AUTOCONF=yes
>
>MainProcess|jsonrpc/6::ERROR::2018-06-05 18:07:28,493::misc::50::root::(ifcfg_config) error reading ifcfg file /etc/sysconfig/network-scripts/ifcfg-eth1
>Traceback (most recent call last):
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netinfo/misc.py", line 43, in ifcfg_config
>    with open(ifcfg_file) as f:
>IOError: [Errno 2] No such file or directory: u'/etc/sysconfig/network-scripts/ifcfg-eth1'
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,507::cmdutils::150::root::(exec_cmd) /sbin/ip addr flush dev eth1 scope global (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,510::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,511::ifcfg::512::root::(_persistentBackup) backing up ifcfg-eth1: # original file did not exist
>
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,511::ifcfg::462::root::(writeBackupFile) Persistently backed up /var/lib/vdsm/netconfback/ifcfg-eth1 (until next 'set safe config')
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,511::ifcfg::569::root::(writeConfFile) Writing to file /etc/sysconfig/network-scripts/ifcfg-eth1 configuration:
># Generated by VDSM version 4.20.29-1.git58011fd.el7
>DEVICE=eth1
>MASTER=bond0
>SLAVE=yes
>ONBOOT=yes
>MTU=1500
>DEFROUTE=no
>NM_CONTROLLED=no
>IPV6INIT=no
>
>MainProcess|jsonrpc/6::ERROR::2018-06-05 18:07:28,512::misc::50::root::(ifcfg_config) error reading ifcfg file /etc/sysconfig/network-scripts/ifcfg-eth2
>Traceback (most recent call last):
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netinfo/misc.py", line 43, in ifcfg_config
>    with open(ifcfg_file) as f:
>IOError: [Errno 2] No such file or directory: u'/etc/sysconfig/network-scripts/ifcfg-eth2'
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,524::cmdutils::150::root::(exec_cmd) /sbin/ip addr flush dev eth2 scope global (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,527::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,528::ifcfg::512::root::(_persistentBackup) backing up ifcfg-eth2: # original file did not exist
>
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,528::ifcfg::462::root::(writeBackupFile) Persistently backed up /var/lib/vdsm/netconfback/ifcfg-eth2 (until next 'set safe config')
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,528::ifcfg::569::root::(writeConfFile) Writing to file /etc/sysconfig/network-scripts/ifcfg-eth2 configuration:
># Generated by VDSM version 4.20.29-1.git58011fd.el7
>DEVICE=eth2
>MASTER=bond0
>SLAVE=yes
>ONBOOT=yes
>MTU=1500
>DEFROUTE=no
>NM_CONTROLLED=no
>IPV6INIT=no
>
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:28,529::cmdutils::150::root::(exec_cmd) /sbin/ifdown bond0 (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:31,164::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = ''; <rc> = 0
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:07:31,168::sysfs_driver::102::root::(set_options) Bond bond0 options set: {u'miimon': u'100', u'mode': u'4'}.
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:07:31,168::cmdutils::150::root::(exec_cmd) /usr/bin/systemd-run --scope --unit=bdcea40b-d7c9-40e6-b8a2-7d981492444d --slice=vdsm-dhclient /sbin/ifup bond0 (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:33,180::cmdutils::158::root::(exec_cmd) FAILED: <err> = 'Running scope as unit bdcea40b-d7c9-40e6-b8a2-7d981492444d.scope.\nError: Connection activation failed: No suitable device found for this connection.\nError: Connection activation failed: No suitable device found for this connection.\n'; <rc> = 1
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:33,180::logutils::317::root::(_report_stats) ThreadedHandler is ok in the last 104 seconds (max pending: 4)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:33,181::cmdutils::150::root::(exec_cmd) /sbin/ifdown bond0 (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:36,062::cmdutils::158::root::(exec_cmd) FAILED: <err> = ''; <rc> = 1
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:08:36,076::ifcfg::487::root::(restoreAtomicBackup) Rolling back configuration (restoring atomic backup)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:36,076::ifcfg::491::root::(restoreAtomicBackup) Removing empty configuration backup /etc/sysconfig/network-scripts/ifcfg-eth1
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:36,076::ifcfg::442::root::(_removeFile) Removed file /etc/sysconfig/network-scripts/ifcfg-eth1
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:08:36,076::ifcfg::496::root::(restoreAtomicBackup) Restored /etc/sysconfig/network-scripts/ifcfg-eth1
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:36,076::ifcfg::491::root::(restoreAtomicBackup) Removing empty configuration backup /etc/sysconfig/network-scripts/ifcfg-eth2
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:36,077::ifcfg::442::root::(_removeFile) Removed file /etc/sysconfig/network-scripts/ifcfg-eth2
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:08:36,077::ifcfg::496::root::(restoreAtomicBackup) Restored /etc/sysconfig/network-scripts/ifcfg-eth2
>MainProcess|jsonrpc/6::INFO::2018-06-05 18:08:36,077::ifcfg::496::root::(restoreAtomicBackup) Restored /etc/sysconfig/network-scripts/ifcfg-bond0
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:36,078::cmdutils::150::root::(exec_cmd) /usr/bin/systemd-run --scope --unit=bfd052cf-c487-427d-868e-e6b5fd63384a --slice=vdsm-dhclient /sbin/ifup bond0 (cwd None)
>MainProcess|jsonrpc/6::DEBUG::2018-06-05 18:08:36,315::cmdutils::158::root::(exec_cmd) SUCCESS: <err> = 'Running scope as unit bfd052cf-c487-427d-868e-e6b5fd63384a.scope.\n'; <rc> = 0
>MainProcess|jsonrpc/6::ERROR::2018-06-05 18:08:36,316::supervdsm_server::100::SuperVdsm.ServerCallback::(wrapper) Error in setupNetworks
>Traceback (most recent call last):
>  File "/usr/lib/python2.7/site-packages/vdsm/supervdsm_server.py", line 98, in wrapper
>    res = func(*args, **kwargs)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/api.py", line 217, in setupNetworks
>    _setup_networks(networks, bondings, options)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/api.py", line 238, in _setup_networks
>    netswitch.configurator.setup(networks, bondings, options, in_rollback)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netswitch/configurator.py", line 140, in setup
>    _setup_legacy(legacy_nets, legacy_bonds, options, in_rollback)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/netswitch/configurator.py", line 157, in _setup_legacy
>    in_rollback)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/legacy_switch.py", line 488, in bonds_setup
>    _bonds_edit(edit, configurator, _netinfo)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/legacy_switch.py", line 560, in _bonds_edit
>    configurator.editBonding(bond, _netinfo)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/configurators/ifcfg.py", line 196, in editBonding
>    _exec_ifup(bond)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/configurators/ifcfg.py", line 942, in _exec_ifup
>    _exec_ifup_by_name(iface.name, cgroup)
>  File "/usr/lib/python2.7/site-packages/vdsm/network/configurators/ifcfg.py", line 928, in _exec_ifup_by_name
>    raise ConfigNetworkError(ERR_FAILED_IFUP, out[-1] if out else '')
>ConfigNetworkError: (29, '\n')
>MainProcess|libvirt/events::DEBUG::2018-06-05 18:11:32,638::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) call rmAppropriateMultipathRules with () {}
>MainProcess|libvirt/events::DEBUG::2018-06-05 18:11:32,638::logutils::317::root::(_report_stats) ThreadedHandler is ok in the last 179 seconds (max pending: 7)
>MainProcess|libvirt/events::DEBUG::2018-06-05 18:11:32,639::supervdsm_server::103::SuperVdsm.ServerCallback::(wrapper) return rmAppropriateMultipathRules with []
>restore-net::INFO::2018-06-05 18:11:37,558::restore_net_config::428::root::(restore) networks already restored. doing nothing.
>MainThread::DEBUG::2018-06-05 18:11:44,813::supervdsm_server::326::SuperVdsm.Server::(main) Terminated normally

Actions: View

Attachments on bug 1586280: 1447994