Re: [ovirt-users] Unknown libvirterror - where to start?

On 06 Nov 2015, at 13:35, Martin Sivak <msivak(a)redhat.com&gt; wrote: Hi, > Thread-8108::DEBUG::2015-11-03 08:47:31,410::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 > message: metadata not found: Requested metadata element is not present we fixed this on vdsm side of oVirt 3.6 too: https://gerrit.ovirt.org/#/c/45799/ But Nir is correct. This was just noise, it went away when any QoS was defined for the VM and was not important otherwise. >> VM Channels Listener::DEBUG::2015-11-03 08:47:34,386::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 125. > We've seen this as well. I don't think there's a specific bug filed on this issue. I wonder if they related.

No relation to the metadata log messages. Can't help here. Best regards -- Martin Sivak SLA / oVirt On Fri, Nov 6, 2015 at 1:14 PM, Christophe TREFOIS <christophe.trefois(a)uni.lu&gt; wrote: > Dear Nir, > > Thank you for your help. I shall ignore the messages then :) > > Kind regards, > > — > Christophe > > Dr Christophe Trefois, Dipl.-Ing. > Technical Specialist / Post-Doc > > UNIVERSITÉ DU LUXEMBOURG > > LUXEMBOURG CENTRE FOR SYSTEMS BIOMEDICINE > Campus Belval | House of Biomedicine > 6, avenue du Swing > L-4367 Belvaux > T: +352 46 66 44 6124 > F: +352 46 66 44 6949 > http://www.uni.lu/lcsb > > > > ---- > This message is confidential and may contain privileged information. > It is intended for the named recipient only. > If you receive it in error please notify me and permanently delete the original message and any copies. > ---- > > > >> On 06 Nov 2015, at 12:23, Nir Soffer <nsoffer(a)redhat.com&gt; wrote: >> >> On Tue, Nov 3, 2015 at 10:30 AM, Yaniv Kaul <ykaul(a)redhat.com&gt; wrote: >>> On Tue, Nov 3, 2015 at 9:52 AM, Christophe TREFOIS >>> <christophe.trefois(a)uni.lu&gt; wrote: >>>> >>>> Hi, >>>> >>>> I checked the logs on my hypervisor that contains also the overt-engine >>>> (self-hosted) and I see strange unknown libvirterrors that come periodically >>>> in the vdsm.log file. The storage is glusterFS running on the hypervisor as >>>> well, one NFS export domain and an ISO domain. A NFS domain from another >>>> place is in maintenance mode. >>>> >>>> I am running oVirt 3.5.3. >>>> >>>> Thank you for any pointers as to where to start fixing this issue. >>>> >>>> — log excerpt -- >>>> >>>> Thread-1947641::DEBUG::2015-11-03 >>>> 08:47:31,398::stompReactor::163::yajsonrpc.StompServer::(send) Sending >>>> response >>>> Thread-8108::DEBUG::2015-11-03 >>>> 08:47:31,410::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>> >>> >>> This (depending on your host OS version, 6.x or 7.x) is either >>> https://bugzilla.redhat.com/show_bug.cgi?id=1220474 or >>> https://bugzilla.redhat.com/show_bug.cgi?id=1260864 >>> Y. >> >> The error about missing metadata is just noise in the log, nothing to >> worry about. >> >> Adding Martin >> >>> >>>> Dummy-1895260::DEBUG::2015-11-03 >>>> 08:47:31,477::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) dd >>>> if=/rhev/data-center/00000002-0002-0002-0002-0000000003d5/mastersd/dom_md/inbox >>>> iflag=direct,fullblock count=1 bs=1024000 (cwd None) >>>> Dummy-1895260::DEBUG::2015-11-03 >>>> 08:47:31,501::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) >>>> SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) >>>> copied, 0.00331278 s, 309 MB/s\n'; <rc> = 0 >>>> Thread-7913::DEBUG::2015-11-03 >>>> 08:47:32,298::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-5682::DEBUG::2015-11-03 >>>> 08:47:32,417::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Detector thread::DEBUG::2015-11-03 >>>> 08:47:32,591::protocoldetector::187::vds.MultiProtocolAcceptor::(_add_connection) >>>> Adding connection from 127.0.0.1:44671 >>>> Detector thread::DEBUG::2015-11-03 >>>> 08:47:32,598::protocoldetector::201::vds.MultiProtocolAcceptor::(_remove_connection) >>>> Connection removed from 127.0.0.1:44671 >>>> Detector thread::DEBUG::2015-11-03 >>>> 08:47:32,599::protocoldetector::247::vds.MultiProtocolAcceptor::(_handle_connection_read) >>>> Detected protocol xml from 127.0.0.1:44671 >>>> Detector thread::DEBUG::2015-11-03 >>>> 08:47:32,599::BindingXMLRPC::1173::XmlDetector::(handleSocket) xml over http >>>> detected from ('127.0.0.1', 44671) >>>> Thread-1947642::DEBUG::2015-11-03 >>>> 08:47:32,602::task::595::Storage.TaskManager.Task::(_updateState) >>>> Task=`1d99a166-cb9a-4025-8211-a48e210b5234`::moving from state init -> state >>>> preparing >>>> Thread-1947642::INFO::2015-11-03 >>>> 08:47:32,603::logUtils::44::dispatcher::(wrapper) Run and protect: >>>> repoStats(options=None) >>>> Thread-1947642::INFO::2015-11-03 >>>> 08:47:32,603::logUtils::47::dispatcher::(wrapper) Run and protect: >>>> repoStats, Return response: {u'de9eb737-691f-4622-9070-891531d599a0': >>>> {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': >>>> '0.000373613', 'lastCheck': '2.5', 'valid': True}, >>>> u'fe4fd19a-8714-44e0-ae41-663a4b62da7a': {'code': 0, 'actual': True, >>>> 'version': 0, 'acquired': True, 'delay': '0.000409446', 'lastCheck': '6.4', >>>> 'valid': True}, u'8253a89b-651e-4ff4-865b-57adef05d383': {'code': 0, >>>> 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000520671', >>>> 'lastCheck': '1.8', 'valid': True}, 'b18eb29e-8bb1-45b9-a60e-a8e07210e066': >>>> {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': >>>> '0.000424445', 'lastCheck': '6.5', 'valid': True}} >>>> Thread-1947642::DEBUG::2015-11-03 >>>> 08:47:32,603::task::1191::Storage.TaskManager.Task::(prepare) >>>> Task=`1d99a166-cb9a-4025-8211-a48e210b5234`::finished: >>>> {u'de9eb737-691f-4622-9070-891531d599a0': {'code': 0, 'actual': True, >>>> 'version': 0, 'acquired': True, 'delay': '0.000373613', 'lastCheck': '2.5', >>>> 'valid': True}, u'fe4fd19a-8714-44e0-ae41-663a4b62da7a': {'code': 0, >>>> 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000409446', >>>> 'lastCheck': '6.4', 'valid': True}, u'8253a89b-651e-4ff4-865b-57adef05d383': >>>> {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': >>>> '0.000520671', 'lastCheck': '1.8', 'valid': True}, >>>> 'b18eb29e-8bb1-45b9-a60e-a8e07210e066': {'code': 0, 'actual': True, >>>> 'version': 3, 'acquired': True, 'delay': '0.000424445', 'lastCheck': '6.5', >>>> 'valid': True}} >>>> Thread-1947642::DEBUG::2015-11-03 >>>> 08:47:32,603::task::595::Storage.TaskManager.Task::(_updateState) >>>> Task=`1d99a166-cb9a-4025-8211-a48e210b5234`::moving from state preparing -> >>>> state finished >>>> Thread-1947642::DEBUG::2015-11-03 >>>> 08:47:32,604::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) >>>> Owner.releaseAll requests {} resources {} >>>> Thread-1947642::DEBUG::2015-11-03 >>>> 08:47:32,604::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) >>>> Owner.cancelAll requests {} >>>> Thread-1947642::DEBUG::2015-11-03 >>>> 08:47:32,604::task::993::Storage.TaskManager.Task::(_decref) >>>> Task=`1d99a166-cb9a-4025-8211-a48e210b5234`::ref 0 aborting False >>>> Thread-6348::DEBUG::2015-11-03 >>>> 08:47:33,261::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-7286::DEBUG::2015-11-03 >>>> 08:47:33,462::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Dummy-1895260::DEBUG::2015-11-03 >>>> 08:47:33,514::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) dd >>>> if=/rhev/data-center/00000002-0002-0002-0002-0000000003d5/mastersd/dom_md/inbox >>>> iflag=direct,fullblock count=1 bs=1024000 (cwd None) >>>> Dummy-1895260::DEBUG::2015-11-03 >>>> 08:47:33,540::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) >>>> SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) >>>> copied, 0.00385901 s, 265 MB/s\n'; <rc> = 0 >>>> Thread-7627::DEBUG::2015-11-03 >>>> 08:47:33,938::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-7951::DEBUG::2015-11-03 >>>> 08:47:33,938::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-3882::DEBUG::2015-11-03 >>>> 08:47:33,940::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-7967::DEBUG::2015-11-03 >>>> 08:47:33,940::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-7899::DEBUG::2015-11-03 >>>> 08:47:33,951::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,383::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 133. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,383::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 135. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,383::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 136. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,383::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 146. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,384::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 160. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,384::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 161. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,384::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 167. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,384::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 171. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,384::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 172. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,384::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 159. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,385::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 189. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,385::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 190. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,385::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 195. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,385::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 197. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,385::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 198. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,385::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 213. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,386::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 215. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,386::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 98. >>>> VM Channels Listener::DEBUG::2015-11-03 >>>> 08:47:34,386::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 125. >>> >>> >>> We've seen this as well. I don't think there's a specific bug filed on this >>> issue. I wonder if they related. >>> Y. >> >> Adding Vinzenz >> >>> >>>> >>>> JsonRpc (StompReactor)::DEBUG::2015-11-03 >>>> 08:47:34,412::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling >>>> message <StompFrame command='SEND'> >>>> JsonRpcServer::DEBUG::2015-11-03 >>>> 08:47:34,413::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting >>>> for request >>>> Thread-1947643::DEBUG::2015-11-03 >>>> 08:47:34,437::stompReactor::163::yajsonrpc.StompServer::(send) Sending >>>> response >>>> Thread-7613::DEBUG::2015-11-03 >>>> 08:47:34,713::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-6393::DEBUG::2015-11-03 >>>> 08:47:34,713::libvirtconnection::143::root::(wrapper) Unknown libvirterror: >>>> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata >>>> element is not present >>>> Thread-226941::DEBUG::2015-11-03 >>>> 08:47:35,511::task::595::Storage.TaskManager.Task::(_updateState) >>>> Task=`bdf26401-324c-4220-9034-19c7d816f642`::moving from state init -> state >>>> preparing >>>> Thread-4709::DEBUG::2015-11-03 >>>> 08:47:35,511::task::595::Storage.TaskManager.Task::(_updateState) >>>> Task=`0ac2f854-41e3-4427-a0f4-5eaa1842e212`::moving from state init -> state >>>> preparing >>>> >>>> -- >>>> >>>> Christophe >>>> >>>> >>>> >>>> _______________________________________________ >>>> Users mailing list >>>> Users(a)ovirt.org >>>> http://lists.ovirt.org/mailman/listinfo/users >>>> >>> >>> >>> _______________________________________________ >>> Users mailing list >>> Users(a)ovirt.org >>> http://lists.ovirt.org/mailman/listinfo/users > _______________________________________________ Users mailing list Users(a)ovirt.org http://lists.ovirt.org/mailman/listinfo/users