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

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

> 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.

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