10:13 a.m.
Hi,
Test failed: [ test-repo_ovirt_experimental_master ]
Link to suspected patches: N/A
Link to Job:
http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/
Link to all logs:
http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/art...
Error snippet from the log:
<error>
2017-05-14 03:56:31,782-0400 ERROR (jsonrpc/3) [storage.TaskManager.Task]
(Task='661acb48-075b-494a-8fb4-64c04ed99bcb') Unexpected error (task:871)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 878,
in _run
return fn(*args, **kargs)
File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line 52, in
wrapper
res = f(*args, **kwargs)
File "/usr/share/vdsm/storage/hsm.py", line 2172, in getAllTasksInfo
allTasksInfo = self._pool.getAllTasksInfo()
File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line
77, in wrapper
raise SecureError("Secured object is not in safe state")
SecureError: Secured object is not in safe state
2017-05-14 03:56:31,785-0400 INFO (jsonrpc/3) [storage.TaskManager.Task]
(Task='661acb48-075b-494a-8fb4-64c04ed99bcb') aborting: Task is aborted:
u'Secured object is not in safe state' - code 100 (task:1176)
2017-05-14 03:56:31,786-0400 ERROR (jsonrpc/3) [storage.Dispatcher] Secured
object is not in safe state (dispatcher:81)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line
73, in wrapper
result = ctask.prepare(func, *args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 106,
in wrapper
return m(self, *a, **kw)
File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1184,
in prepare
raise self.error
SecureError: Secured object is not in safe state
2017-05-14 03:56:31,786-0400 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC
call Host.getAllTasksInfo failed (error 654) in 0.00 seconds (__init__:577)
2017-05-14 03:56:31,796-0400 INFO (jsonrpc/5) [dispatcher] Run and
protect: getAllTasksStatuses(spUUID=None, options=None) (logUtils:51)
2017-05-14 03:56:31,797-0400 ERROR (jsonrpc/5) [storage.TaskManager.Task]
(Task='568f515e-365b-47e4-8b2f-24e15deb6ae9') Unexpected error (task:871)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 878,
in _run
return fn(*args, **kargs)
File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line 52, in
wrapper
res = f(*args, **kwargs)
File "/usr/share/vdsm/storage/hsm.py", line 2132, in getAllTasksStatuses
allTasksStatus = self._pool.getAllTasksStatuses()
File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line
77, in wrapper
raise SecureError("Secured object is not in safe state")
SecureError: Secured object is not in safe state
2017-05-14 03:56:31,797-0400 INFO (jsonrpc/5) [storage.TaskManager.Task]
(Task='568f515e-365b-47e4-8b2f-24e15deb6ae9') aborting: Task is aborted:
u'Secured object is not in safe state' - code 100 (task:1176)
2017-05-14 03:56:31,798-0400 ERROR (jsonrpc/5) [storage.Dispatcher] Secured
object is not in safe state (dispatcher:81)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line
73, in wrapper
result = ctask.prepare(func, *args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 106,
in wrapper
return m(self, *a, **kw)
File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1184,
in prepare
raise self.error
SecureError: Secured object is not in safe state
<error>
Best Regards,
Shlomi Ben-David | Software Engineer | Red Hat ISRAEL
RHCSA | RHCVA | RHCE
IRC: shlomibendavid (on #rhev-integ, #rhev-dev, #rhev-ci)
OPEN SOURCE - 1 4 011 && 011 4 1
12:12 p.m.
On Sun, May 14, 2017 at 5:14 PM Shlomo Ben David <sbendavi(a)redhat.com wrote:
File
"/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 878,
> in _run
> return fn(*args, **kargs)
> File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line 52, in
> wrapper
> res = f(*args, **kwargs)
> File "/usr/share/vdsm/storage/hsm.py", line 2132, in getAllTasksStatuses
> allTasksStatus = self._pool.getAllTasksStatuses()
> File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line
> 77, in wrapper
> raise SecureError("Secured object is not in safe state")
> SecureError: Secured object is not in safe state
This means that getAllTasksStatuses (SPM verb) was called on a host
which is not the SPM. This is an error in the caller, not in vdsm.
We already have a bug abut this:
https://bugzilla.redhat.com/1426429
However this build logs do not contain enough info. These
patches adds more info that can help to identify the caller:
https://gerrit.ovirt.org/76771
This error is not related to the real error in this build.
Nir
Link to suspected patches: N/A
Link to Job:
http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/
Link to all logs:
http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/art...
Error snippet from the log:
Traceback (most recent call last):
5:40 a.m.
I agree with Nir that the above issue is not related to the job failure.
I see that there is a timeout for:
2017-05-14 04:10:04,215-04 DEBUG
[org.ovirt.vdsm.jsonrpc.client.reactors.stomp.StompCommonClient]
(org.ovirt.thread.pool-7-thread-12) [] Message sent: SEND
destination:jms.topic.vdsm_requests
content-length:377
reply-to:jms.topic.vdsm_responses
<JsonRpcRequest id: "846f4741-5c7d-4396-8ed7-ce995d426728", method:
Host.setupNetworks, params: {networks={Migration_Net={vlan=200,
ipv6autoconf=false, nic=eth0, bridged=false, dhcpv6=false, mtu=1500,
ipv6addr=2001:0db8:85a3:0000:0000:574c:14ea:0a02/64, switch=legacy}},
bondings={}, options={connectivityTimeout=120,
connectivityCheck=true}}>
and the timeout occurred at:
2017-05-14 04:10:07,535-04 DEBUG
[org.ovirt.vdsm.jsonrpc.client.internal.ResponseWorker]
(ResponseWorker) [] Message received:
{"jsonrpc":"2.0","error":{"code":"lago-basic-suite-master-host1:286640862","message":"Vds
timeout occured"},"id":null}
I see in supervdsm log:
MainProcess|jsonrpc/1::INFO::2017-05-14
04:10:05,566::netconfpersistence::52::root::(setNetwork) Adding
network Migration_Net({u'ipv6autoconf': False, 'nameservers': [],
u'nic': u'eth0', u'vlan': 200, u'mtu': 1500,
u'switch': u'legacy',
u'dhcpv6': False, u'bridged': False, u'ipv6addr':
u'2001:0db8:85a3:0000:0000:574c:14ea:0a02/64', 'defaultRoute': False,
'bootproto': 'none'})
...
MainProcess|jsonrpc/1::WARNING::2017-05-14
04:10:05,580::ifcfg::247::root::(_addSourceRoute) Invalid input for
source routing: name=eth0.200, addr=None, netmask=None, gateway=None
netlink/events::DEBUG::2017-05-14
04:10:05,581::concurrent::184::root::(run) START thread
<Thread(netlink/events, started daemon 139829765465856)> (func=<bound
method Monitor._scan of <vdsm.network.netlink.monitor.Monitor object
at 0x7f2c8c01ebd0>>, args=(), kwargs={})
MainProcess|jsonrpc/1::WARNING::2017-05-14
04:10:05,581::ifcfg::894::root::(_ignore_missing_device) eth0.200
didn't exist (yet) and so IPv6 wasn't enabled.
My question is why only 3 seconds to timeout setupNetworks.
I found one more exception not related to the above issue which we should fix:
2017-05-14 04:08:08,924-04 DEBUG
[org.ovirt.engine.core.utils.timer.SchedulerUtilQuartzImpl]
(DefaultQuartzScheduler10) [58fd90c1] Exception:
java.lang.reflect.InvocationTargetException
at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source) [:1.8.0_131]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_131]
at org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:83)
[scheduler.jar:]
at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:55)
[scheduler.jar:]
at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[rt.jar:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[rt.jar:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131]
Caused by: java.lang.NullPointerException
at
org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.lambda$processDevices$0(VmStatsRefresher.java:44)
[vdsbroker.jar:]
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:174)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
[rt.jar:1.8.0_131]
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
[rt.jar:1.8.0_131]
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
[rt.jar:1.8.0_131]
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
[rt.jar:1.8.0_131]
at
org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.processDevices(VmStatsRefresher.java:46)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.monitoring.PollVmStatsRefresher.poll(PollVmStatsRefresher.java:44)
[vdsbroker.jar:]
... 11 more
Thanks,
Piotr
On Sun, May 14, 2017 at 6:12 PM, Nir Soffer <nsoffer(a)redhat.com> wrote:
On Sun, May 14, 2017 at 5:14 PM Shlomo Ben David
<sbendavi(a)redhat.com>
wrote:
>
> Link to suspected patches: N/A
> Link to Job:
> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/
> Link to all logs:
>
http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/art...
>
> Error snippet from the log:
> Traceback (most recent call last):
>
> File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 878,
> in _run
> return fn(*args, **kargs)
> File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line 52, in
> wrapper
> res = f(*args, **kwargs)
> File "/usr/share/vdsm/storage/hsm.py", line 2132, in getAllTasksStatuses
> allTasksStatus = self._pool.getAllTasksStatuses()
> File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line
> 77, in wrapper
> raise SecureError("Secured object is not in safe state")
> SecureError: Secured object is not in safe state
This means that getAllTasksStatuses (SPM verb) was called on a host
which is not the SPM. This is an error in the caller, not in vdsm.
We already have a bug abut this:
https://bugzilla.redhat.com/1426429
However this build logs do not contain enough info. These
patches adds more info that can help to identify the caller:
https://gerrit.ovirt.org/76771
This error is not related to the real error in this build.
Nir
_______________________________________________
Devel mailing list
Devel(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel
7:31 a.m.
On Mon, May 15, 2017 at 12:40 PM, Piotr Kliczewski <
piotr.kliczewski(a)gmail.com> wrote:
I agree with Nir that the above issue is not related to the job
failure.
I see that there is a timeout for:
2017-05-14 04:10:04,215-04 DEBUG
[org.ovirt.vdsm.jsonrpc.client.reactors.stomp.StompCommonClient]
(org.ovirt.thread.pool-7-thread-12) [] Message sent: SEND
destination:jms.topic.vdsm_requests
content-length:377
reply-to:jms.topic.vdsm_responses
<JsonRpcRequest id: "846f4741-5c7d-4396-8ed7-ce995d426728", method:
Host.setupNetworks, params: {networks={Migration_Net={vlan=200,
ipv6autoconf=false, nic=eth0, bridged=false, dhcpv6=false, mtu=1500,
ipv6addr=2001:0db8:85a3:0000:0000:574c:14ea:0a02/64, switch=legacy}},
bondings={}, options={connectivityTimeout=120,
connectivityCheck=true}}>
and the timeout occurred at:
2017-05-14 04:10:07,535-04 DEBUG
[org.ovirt.vdsm.jsonrpc.client.internal.ResponseWorker]
(ResponseWorker) [] Message received:
{"jsonrpc":"2.0","error":{"code":"lago-basic-suite-
master-host1:286640862","message":"Vds
timeout occured"},"id":null}
I see in supervdsm log:
MainProcess|jsonrpc/1::INFO::2017-05-14
04:10:05,566::netconfpersistence::52::root::(setNetwork) Adding
network Migration_Net({u'ipv6autoconf': False, 'nameservers': [],
u'nic': u'eth0', u'vlan': 200, u'mtu': 1500,
u'switch': u'legacy',
u'dhcpv6': False, u'bridged': False, u'ipv6addr':
u'2001:0db8:85a3:0000:0000:574c:14ea:0a02/64', 'defaultRoute': False,
'bootproto': 'none'})
...
MainProcess|jsonrpc/1::WARNING::2017-05-14
04:10:05,580::ifcfg::247::root::(_addSourceRoute) Invalid input for
source routing: name=eth0.200, addr=None, netmask=None, gateway=None
netlink/events::DEBUG::2017-05-14
04:10:05,581::concurrent::184::root::(run) START thread
<Thread(netlink/events, started daemon 139829765465856)> (func=<bound
method Monitor._scan of <vdsm.network.netlink.monitor.Monitor object
at 0x7f2c8c01ebd0>>, args=(), kwargs={})
MainProcess|jsonrpc/1::WARNING::2017-05-14
04:10:05,581::ifcfg::894::root::(_ignore_missing_device) eth0.200
didn't exist (yet) and so IPv6 wasn't enabled.
My question is why only 3 seconds to timeout setupNetworks.
I found one more exception not related to the above issue which we should
fix:
Ack. This one is easy.
2017-05-14 04:08:08,924-04 DEBUG
[org.ovirt.engine.core.utils.timer.SchedulerUtilQuartzImpl]
(DefaultQuartzScheduler10) [58fd90c1] Exception:
java.lang.reflect.InvocationTargetException
at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
[:1.8.0_131]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_131]
at org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(
JobWrapper.java:83)
[scheduler.jar:]
at org.ovirt.engine.core.utils.timer.JobWrapper.execute(
JobWrapper.java:55)
[scheduler.jar:]
at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[rt.jar:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(
ThreadPoolExecutor.java:1142)
[rt.jar:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:617)
[rt.jar:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131]
Caused by: java.lang.NullPointerException
at org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.lambda$
processDevices$0(VmStatsRefresher.java:44)
[vdsbroker.jar:]
at java.util.stream.ReferencePipeline$2$1.accept(
ReferencePipeline.java:174)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline$3$1.accept(
ReferencePipeline.java:193)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline$2$1.accept(
ReferencePipeline.java:175)
[rt.jar:1.8.0_131]
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.
java:1374)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.wrapAndCopyInto(
AbstractPipeline.java:471)
[rt.jar:1.8.0_131]
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(
ForEachOps.java:151)
[rt.jar:1.8.0_131]
at java.util.stream.ForEachOps$ForEachOp$OfRef.
evaluateSequential(ForEachOps.java:174)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
[rt.jar:1.8.0_131]
at org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.
processDevices(VmStatsRefresher.java:46)
[vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.monitoring.PollVmStatsRefresher.poll(
PollVmStatsRefresher.java:44)
[vdsbroker.jar:]
... 11 more
Thanks,
Piotr
On Sun, May 14, 2017 at 6:12 PM, Nir Soffer <nsoffer(a)redhat.com> wrote:
> On Sun, May 14, 2017 at 5:14 PM Shlomo Ben David <sbendavi(a)redhat.com>
> wrote:
>>
>> Link to suspected patches: N/A
>> Link to Job:
>> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/
>> Link to all logs:
>> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_
master/6665/artifact/exported-artifacts/basic-suit-master-
el7/test_logs/basic-suite-master/post-006_migrations.py/
>>
>> Error snippet from the log:
>
>
>> Traceback (most recent call last):
>>
>> File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line
878,
>> in _run
>> return fn(*args, **kargs)
>> File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line 52,
in
>> wrapper
>> res = f(*args, **kwargs)
>> File "/usr/share/vdsm/storage/hsm.py", line 2132, in
getAllTasksStatuses
>> allTasksStatus = self._pool.getAllTasksStatuses()
>> File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py",
line
>> 77, in wrapper
>> raise SecureError("Secured object is not in safe state")
>> SecureError: Secured object is not in safe state
>
>
> This means that getAllTasksStatuses (SPM verb) was called on a host
> which is not the SPM. This is an error in the caller, not in vdsm.
>
> We already have a bug abut this:
> https://bugzilla.redhat.com/1426429
>
> However this build logs do not contain enough info. These
> patches adds more info that can help to identify the caller:
> https://gerrit.ovirt.org/76771
>
> This error is not related to the real error in this build.
>
> Nir
>
> _______________________________________________
> Devel mailing list
> Devel(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel
7:28 a.m.
Piotr,
How do you identify the connection between the 2 message, why do you think
that the timeout is related to the first message you've mentioned?
Regards,
Yevgeny
On Mon, May 15, 2017 at 12:40 PM, Piotr Kliczewski <
piotr.kliczewski(a)gmail.com> wrote:
I agree with Nir that the above issue is not related to the job
failure.
I see that there is a timeout for:
2017-05-14 04:10:04,215-04 DEBUG
[org.ovirt.vdsm.jsonrpc.client.reactors.stomp.StompCommonClient]
(org.ovirt.thread.pool-7-thread-12) [] Message sent: SEND
destination:jms.topic.vdsm_requests
content-length:377
reply-to:jms.topic.vdsm_responses
<JsonRpcRequest id: "846f4741-5c7d-4396-8ed7-ce995d426728", method:
Host.setupNetworks, params: {networks={Migration_Net={vlan=200,
ipv6autoconf=false, nic=eth0, bridged=false, dhcpv6=false, mtu=1500,
ipv6addr=2001:0db8:85a3:0000:0000:574c:14ea:0a02/64, switch=legacy}},
bondings={}, options={connectivityTimeout=120,
connectivityCheck=true}}>
and the timeout occurred at:
2017-05-14 04:10:07,535-04 DEBUG
[org.ovirt.vdsm.jsonrpc.client.internal.ResponseWorker]
(ResponseWorker) [] Message received:
{"jsonrpc":"2.0","error":{"code":"lago-basic-suite-
master-host1:286640862","message":"Vds
timeout occured"},"id":null}
I see in supervdsm log:
MainProcess|jsonrpc/1::INFO::2017-05-14
04:10:05,566::netconfpersistence::52::root::(setNetwork) Adding
network Migration_Net({u'ipv6autoconf': False, 'nameservers': [],
u'nic': u'eth0', u'vlan': 200, u'mtu': 1500,
u'switch': u'legacy',
u'dhcpv6': False, u'bridged': False, u'ipv6addr':
u'2001:0db8:85a3:0000:0000:574c:14ea:0a02/64', 'defaultRoute': False,
'bootproto': 'none'})
...
MainProcess|jsonrpc/1::WARNING::2017-05-14
04:10:05,580::ifcfg::247::root::(_addSourceRoute) Invalid input for
source routing: name=eth0.200, addr=None, netmask=None, gateway=None
netlink/events::DEBUG::2017-05-14
04:10:05,581::concurrent::184::root::(run) START thread
<Thread(netlink/events, started daemon 139829765465856)> (func=<bound
method Monitor._scan of <vdsm.network.netlink.monitor.Monitor object
at 0x7f2c8c01ebd0>>, args=(), kwargs={})
MainProcess|jsonrpc/1::WARNING::2017-05-14
04:10:05,581::ifcfg::894::root::(_ignore_missing_device) eth0.200
didn't exist (yet) and so IPv6 wasn't enabled.
My question is why only 3 seconds to timeout setupNetworks.
I found one more exception not related to the above issue which we should
fix:
2017-05-14 04:08:08,924-04 DEBUG
[org.ovirt.engine.core.utils.timer.SchedulerUtilQuartzImpl]
(DefaultQuartzScheduler10) [58fd90c1] Exception:
java.lang.reflect.InvocationTargetException
at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
[:1.8.0_131]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_131]
at org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(
JobWrapper.java:83)
[scheduler.jar:]
at org.ovirt.engine.core.utils.timer.JobWrapper.execute(
JobWrapper.java:55)
[scheduler.jar:]
at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[rt.jar:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(
ThreadPoolExecutor.java:1142)
[rt.jar:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:617)
[rt.jar:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131]
Caused by: java.lang.NullPointerException
at org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.lambda$
processDevices$0(VmStatsRefresher.java:44)
[vdsbroker.jar:]
at java.util.stream.ReferencePipeline$2$1.accept(
ReferencePipeline.java:174)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline$3$1.accept(
ReferencePipeline.java:193)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline$2$1.accept(
ReferencePipeline.java:175)
[rt.jar:1.8.0_131]
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.
java:1374)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.wrapAndCopyInto(
AbstractPipeline.java:471)
[rt.jar:1.8.0_131]
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(
ForEachOps.java:151)
[rt.jar:1.8.0_131]
at java.util.stream.ForEachOps$ForEachOp$OfRef.
evaluateSequential(ForEachOps.java:174)
[rt.jar:1.8.0_131]
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
[rt.jar:1.8.0_131]
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
[rt.jar:1.8.0_131]
at org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.
processDevices(VmStatsRefresher.java:46)
[vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.monitoring.PollVmStatsRefresher.poll(
PollVmStatsRefresher.java:44)
[vdsbroker.jar:]
... 11 more
Thanks,
Piotr
On Sun, May 14, 2017 at 6:12 PM, Nir Soffer <nsoffer(a)redhat.com> wrote:
> On Sun, May 14, 2017 at 5:14 PM Shlomo Ben David <sbendavi(a)redhat.com>
> wrote:
>>
>> Link to suspected patches: N/A
>> Link to Job:
>> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/
>> Link to all logs:
>> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_
master/6665/artifact/exported-artifacts/basic-suit-master-
el7/test_logs/basic-suite-master/post-006_migrations.py/
>>
>> Error snippet from the log:
>
>
>> Traceback (most recent call last):
>>
>> File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line
878,
>> in _run
>> return fn(*args, **kargs)
>> File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line 52,
in
>> wrapper
>> res = f(*args, **kwargs)
>> File "/usr/share/vdsm/storage/hsm.py", line 2132, in
getAllTasksStatuses
>> allTasksStatus = self._pool.getAllTasksStatuses()
>> File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py",
line
>> 77, in wrapper
>> raise SecureError("Secured object is not in safe state")
>> SecureError: Secured object is not in safe state
>
>
> This means that getAllTasksStatuses (SPM verb) was called on a host
> which is not the SPM. This is an error in the caller, not in vdsm.
>
> We already have a bug abut this:
> https://bugzilla.redhat.com/1426429
>
> However this build logs do not contain enough info. These
> patches adds more info that can help to identify the caller:
> https://gerrit.ovirt.org/76771
>
> This error is not related to the real error in this build.
>
> Nir
>
> _______________________________________________
> Devel mailing list
> Devel(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________
Devel mailing list
Devel(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel
10:42 a.m.
Yevgeny,
There is message id which matches request and response but in this
case I made an assumption about setupNetworks being exclusive
operation.
The following setupNetwoks was the last one which was last executed.
Thanks,
Piotr
On Thu, May 18, 2017 at 1:28 PM, Yevgeny Zaspitsky <yzaspits(a)redhat.com> wrote:
Piotr,
How do you identify the connection between the 2 message, why do you think
that the timeout is related to the first message you've mentioned?
Regards,
Yevgeny
On Mon, May 15, 2017 at 12:40 PM, Piotr Kliczewski
<piotr.kliczewski(a)gmail.com> wrote:
>
> I agree with Nir that the above issue is not related to the job failure.
>
> I see that there is a timeout for:
>
> 2017-05-14 04:10:04,215-04 DEBUG
> [org.ovirt.vdsm.jsonrpc.client.reactors.stomp.StompCommonClient]
> (org.ovirt.thread.pool-7-thread-12) [] Message sent: SEND
> destination:jms.topic.vdsm_requests
> content-length:377
> reply-to:jms.topic.vdsm_responses
>
> <JsonRpcRequest id: "846f4741-5c7d-4396-8ed7-ce995d426728", method:
> Host.setupNetworks, params: {networks={Migration_Net={vlan=200,
> ipv6autoconf=false, nic=eth0, bridged=false, dhcpv6=false, mtu=1500,
> ipv6addr=2001:0db8:85a3:0000:0000:574c:14ea:0a02/64, switch=legacy}},
> bondings={}, options={connectivityTimeout=120,
> connectivityCheck=true}}>
>
>
> and the timeout occurred at:
>
> 2017-05-14 04:10:07,535-04 DEBUG
> [org.ovirt.vdsm.jsonrpc.client.internal.ResponseWorker]
> (ResponseWorker) [] Message received:
>
>
{"jsonrpc":"2.0","error":{"code":"lago-basic-suite-master-host1:286640862","message":"Vds
> timeout occured"},"id":null}
>
> I see in supervdsm log:
>
> MainProcess|jsonrpc/1::INFO::2017-05-14
> 04:10:05,566::netconfpersistence::52::root::(setNetwork) Adding
> network Migration_Net({u'ipv6autoconf': False, 'nameservers': [],
> u'nic': u'eth0', u'vlan': 200, u'mtu': 1500,
u'switch': u'legacy',
> u'dhcpv6': False, u'bridged': False, u'ipv6addr':
> u'2001:0db8:85a3:0000:0000:574c:14ea:0a02/64', 'defaultRoute':
False,
> 'bootproto': 'none'})
> ...
> MainProcess|jsonrpc/1::WARNING::2017-05-14
> 04:10:05,580::ifcfg::247::root::(_addSourceRoute) Invalid input for
> source routing: name=eth0.200, addr=None, netmask=None, gateway=None
> netlink/events::DEBUG::2017-05-14
> 04:10:05,581::concurrent::184::root::(run) START thread
> <Thread(netlink/events, started daemon 139829765465856)> (func=<bound
> method Monitor._scan of <vdsm.network.netlink.monitor.Monitor object
> at 0x7f2c8c01ebd0>>, args=(), kwargs={})
> MainProcess|jsonrpc/1::WARNING::2017-05-14
> 04:10:05,581::ifcfg::894::root::(_ignore_missing_device) eth0.200
> didn't exist (yet) and so IPv6 wasn't enabled.
>
> My question is why only 3 seconds to timeout setupNetworks.
>
>
>
> I found one more exception not related to the above issue which we should
> fix:
>
> 2017-05-14 04:08:08,924-04 DEBUG
> [org.ovirt.engine.core.utils.timer.SchedulerUtilQuartzImpl]
> (DefaultQuartzScheduler10) [58fd90c1] Exception:
> java.lang.reflect.InvocationTargetException
> at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
> [:1.8.0_131]
> at
>
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> [rt.jar:1.8.0_131]
> at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_131]
> at
> org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:83)
> [scheduler.jar:]
> at
> org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:55)
> [scheduler.jar:]
> at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> [rt.jar:1.8.0_131]
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> [rt.jar:1.8.0_131]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> [rt.jar:1.8.0_131]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [rt.jar:1.8.0_131]
> at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131]
> Caused by: java.lang.NullPointerException
> at
>
org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.lambda$processDevices$0(VmStatsRefresher.java:44)
> [vdsbroker.jar:]
> at
> java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:174)
> [rt.jar:1.8.0_131]
> at
> java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
> [rt.jar:1.8.0_131]
> at
> java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
> [rt.jar:1.8.0_131]
> at
> java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374)
> [rt.jar:1.8.0_131]
> at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
> [rt.jar:1.8.0_131]
> at
> java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
> [rt.jar:1.8.0_131]
> at
> java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
> [rt.jar:1.8.0_131]
> at
> java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
> [rt.jar:1.8.0_131]
> at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
> [rt.jar:1.8.0_131]
> at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
> [rt.jar:1.8.0_131]
> at
>
org.ovirt.engine.core.vdsbroker.monitoring.VmStatsRefresher.processDevices(VmStatsRefresher.java:46)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.monitoring.PollVmStatsRefresher.poll(PollVmStatsRefresher.java:44)
> [vdsbroker.jar:]
> ... 11 more
>
> Thanks,
> Piotr
>
>
> On Sun, May 14, 2017 at 6:12 PM, Nir Soffer <nsoffer(a)redhat.com> wrote:
> > On Sun, May 14, 2017 at 5:14 PM Shlomo Ben David <sbendavi(a)redhat.com>
> > wrote:
> >>
> >> Link to suspected patches: N/A
> >> Link to Job:
> >> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/
> >> Link to all logs:
> >>
> >>
http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6665/art...
> >>
> >> Error snippet from the log:
> >
> >
> >> Traceback (most recent call last):
> >>
> >> File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py",
line
> >> 878,
> >> in _run
> >> return fn(*args, **kargs)
> >> File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line
52, in
> >> wrapper
> >> res = f(*args, **kwargs)
> >> File "/usr/share/vdsm/storage/hsm.py", line 2132, in
> >> getAllTasksStatuses
> >> allTasksStatus = self._pool.getAllTasksStatuses()
> >> File
"/usr/lib/python2.7/site-packages/vdsm/storage/securable.py",
> >> line
> >> 77, in wrapper
> >> raise SecureError("Secured object is not in safe state")
> >> SecureError: Secured object is not in safe state
> >
> >
> > This means that getAllTasksStatuses (SPM verb) was called on a host
> > which is not the SPM. This is an error in the caller, not in vdsm.
> >
> > We already have a bug abut this:
> > https://bugzilla.redhat.com/1426429
> >
> > However this build logs do not contain enough info. These
> > patches adds more info that can help to identify the caller:
> > https://gerrit.ovirt.org/76771
> >
> > This error is not related to the real error in this build.
> >
> > Nir
> >
> > _______________________________________________
> > Devel mailing list
> > Devel(a)ovirt.org
> > http://lists.ovirt.org/mailman/listinfo/devel
> _______________________________________________
> Devel mailing list
> Devel(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel
2778
days inactive
2782
days old
5 comments
5 participants
participants (5)
-
Arik Hadas -
Nir Soffer -
Piotr Kliczewski -
Shlomo Ben David -
Yevgeny Zaspitsky