Re: [ovirt-devel] System tests failure (wrong test code?)

[Arik Hadas]

On Sun, Mar 19, 2017 at 2:09 PM, Yaniv Kaul  wrote:

>
>
> On Sun, Mar 19, 2017 at 12:14 PM, Arik Hadas  wrote:
>
>>
>>
>> On Sat, Mar 18, 2017 at 12:57 PM, Yaniv Kaul  wrote:
>>
>>>
>>>
>>> On Sat, Mar 18, 2017 at 12:05 AM, Michal Skrivanek 
>>> wrote:
>>>

 On 17 Mar 2017, at 20:49, Yaniv Kaul  wrote:



 On Thu, Mar 16, 2017 at 8:16 PM, Michal Skrivanek 
 wrote:

>
> On 16 Mar 2017, at 15:18, Yaniv Kaul  wrote:
>
>
>
> On Thu, Mar 16, 2017 at 10:46 AM, Nir Soffer  wr
> ote:
>
>> If found this error in system tests - looks like wrong assert - code
>> should check
>> if disk is not None before checking state.
>>
>> I'm not sure who is the owner of this test, so posting here.
>>
>
> Theoretically, perhaps.
> Practically, it worked (until yesterday?) and now I'm also seeing this
> failure - it's not a coincidence.
>
> However, looking at my failure[1], I'm seeing other nasty stuff, which
> may explain the later on failures
>
> For example, new NPE I have not seen in the past:
> 2017-03-16 09:57:57,581-04 INFO  
> [org.ovirt.engine.core.bll.AddVmTemplateCommand]
> (DefaultQuartzScheduler1) [5d94233] Ending command
> 'org.ovirt.engine.core.bll.AddVmTemplateCommand' successfully.
>
>
> Is this IST or which TZ?
>

 Interesting question - I guess that's why we need the offset from UTC
 or use UTC in the logs.


> Likely https://gerrit.ovirt.org/#/c/69323 merged 10:33:20 CET today
>

 That's the cause or the fix?


 oh, sorry, the cause.
 we were not able to find anyone to confirm and resolve it today
 unfortunately

>>>
>> A fix is posted: https://gerrit.ovirt.org/#/c/74276/
>> The cause is explained in the commit message.
>>
>
Merged.


>
> Thanks.
>
>
>> In our defense I'll say that somehow the system tests passed when we ran
>> them ([1]) and that the command for adding a template became way too
>> complicated than it is supposed to be with the introduction of import from
>> glance and instance-types.
>>
>
> Do we have intentions to simplify it?
>

Well, we had such intentions but these things are always the first
candidates to postpone. We should.


>
>
>>
>> [1] http://jenkins.ovirt.org/job/ovirt-system-tests_manual/129/
>>
>>
>>>
>>> A secondary bug is that it fails every 10 seconds or so, continuously.
>>> Y.
>>>
>>
>> Right, because it fails in the end-action phase of the command and we
>> have a retry mechanism that attempts to end the command (unless stated
>> otherwise) periodically.
>>
>
> But the end user experience is an event every few seconds (10?) that we
> fail an operation.
> When does it give up?
>

For the most part, chances are extremely low for a command to fail in its
end-action phase. Generally, commands either fail in their validation phase
or execution phase or when their async tasks/jobs fail. In those case, we
don't have/need a mechanism for periodic retry. On the other hand, the
end-action phase is relatively short and simple and is really not expected
to fail (unless there is a bug, like in this case), but if it does fail -
we have to retry and the user will probably experience more acute issues
than a flood of audit messages (e.g., inability to connect to the
database). AFAIK there is no limit to the number of retry attempts in this
case.


> Y.
>
>
>>
>>
>>>
>>>
>>>

 Y.


>
> 2017-03-16 09:57:57,591-04 INFO  
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] START, SetVmStatusVDSCommand(
> SetVmStatusVDSCommandParameters:{runAsync='true',
> vmId='----', status='Down',
> exitStatus='Normal'}), log id: 30ee3299
> 2017-03-16 09:57:57,593-04 DEBUG [org.ovirt.engine.core.dal.dbb
> roker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
> (DefaultQuartzScheduler1) [5d94233] Compiled stored procedure. Call string
> is [{call getvmdynamicbyvmguid(?)}]
> 2017-03-16 09:57:57,594-04 DEBUG [org.ovirt.engine.core.dal.dbb
> roker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
> (DefaultQuartzScheduler1) [5d94233] SqlCall for procedure
> [GetVmDynamicByVmGuid] compiled
> 2017-03-16 09:57:57,595-04 ERROR 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] Command 'SetVmStatusVDSCommand(
> SetVmStatusVDSCommandParameters:{runAsync='true',
> vmId='----', status='Down',
> exitStatus='Normal'})' execution failed: null
> 2017-03-16 09:57:57,595-04 DEBUG 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] Exception:
> 

Re: [ovirt-devel] System tests failure (wrong test code?)

[Yaniv Kaul]

On Sun, Mar 19, 2017 at 12:14 PM, Arik Hadas  wrote:

>
>
> On Sat, Mar 18, 2017 at 12:57 PM, Yaniv Kaul  wrote:
>
>>
>>
>> On Sat, Mar 18, 2017 at 12:05 AM, Michal Skrivanek 
>> wrote:
>>
>>>
>>> On 17 Mar 2017, at 20:49, Yaniv Kaul  wrote:
>>>
>>>
>>>
>>> On Thu, Mar 16, 2017 at 8:16 PM, Michal Skrivanek 
>>> wrote:
>>>

 On 16 Mar 2017, at 15:18, Yaniv Kaul  wrote:



 On Thu, Mar 16, 2017 at 10:46 AM, Nir Soffer  wr
 ote:

> If found this error in system tests - looks like wrong assert - code
> should check
> if disk is not None before checking state.
>
> I'm not sure who is the owner of this test, so posting here.
>

 Theoretically, perhaps.
 Practically, it worked (until yesterday?) and now I'm also seeing this
 failure - it's not a coincidence.

 However, looking at my failure[1], I'm seeing other nasty stuff, which
 may explain the later on failures

 For example, new NPE I have not seen in the past:
 2017-03-16 09:57:57,581-04 INFO  
 [org.ovirt.engine.core.bll.AddVmTemplateCommand]
 (DefaultQuartzScheduler1) [5d94233] Ending command
 'org.ovirt.engine.core.bll.AddVmTemplateCommand' successfully.


 Is this IST or which TZ?

>>>
>>> Interesting question - I guess that's why we need the offset from UTC or
>>> use UTC in the logs.
>>>
>>>
 Likely https://gerrit.ovirt.org/#/c/69323 merged 10:33:20 CET today

>>>
>>> That's the cause or the fix?
>>>
>>>
>>> oh, sorry, the cause.
>>> we were not able to find anyone to confirm and resolve it today
>>> unfortunately
>>>
>>
> A fix is posted: https://gerrit.ovirt.org/#/c/74276/
> The cause is explained in the commit message.
>

Thanks.


> In our defense I'll say that somehow the system tests passed when we ran
> them ([1]) and that the command for adding a template became way too
> complicated than it is supposed to be with the introduction of import from
> glance and instance-types.
>

Do we have intentions to simplify it?


>
> [1] http://jenkins.ovirt.org/job/ovirt-system-tests_manual/129/
>
>
>>
>> A secondary bug is that it fails every 10 seconds or so, continuously.
>> Y.
>>
>
> Right, because it fails in the end-action phase of the command and we have
> a retry mechanism that attempts to end the command (unless stated
> otherwise) periodically.
>

But the end user experience is an event every few seconds (10?) that we
fail an operation.
When does it give up?
Y.


>
>
>>
>>
>>
>>>
>>> Y.
>>>
>>>

 2017-03-16 09:57:57,591-04 INFO  
 [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
 (DefaultQuartzScheduler1) [5d94233] START, SetVmStatusVDSCommand(
 SetVmStatusVDSCommandParameters:{runAsync='true',
 vmId='----', status='Down',
 exitStatus='Normal'}), log id: 30ee3299
 2017-03-16 09:57:57,593-04 DEBUG [org.ovirt.engine.core.dal.dbb
 roker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
 (DefaultQuartzScheduler1) [5d94233] Compiled stored procedure. Call string
 is [{call getvmdynamicbyvmguid(?)}]
 2017-03-16 09:57:57,594-04 DEBUG [org.ovirt.engine.core.dal.dbb
 roker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
 (DefaultQuartzScheduler1) [5d94233] SqlCall for procedure
 [GetVmDynamicByVmGuid] compiled
 2017-03-16 09:57:57,595-04 ERROR 
 [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
 (DefaultQuartzScheduler1) [5d94233] Command 'SetVmStatusVDSCommand(
 SetVmStatusVDSCommandParameters:{runAsync='true',
 vmId='----', status='Down',
 exitStatus='Normal'})' execution failed: null
 2017-03-16 09:57:57,595-04 DEBUG 
 [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
 (DefaultQuartzScheduler1) [5d94233] Exception:
 java.lang.NullPointerException
 at org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand.execut
 eVDSCommand(SetVmStatusVDSCommand.java:33) [vdsbroker.jar:]
 at 
 org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
 [vdsbroker.jar:]
 at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
 [dal.jar:]
 at org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandE
 xecutor.execute(DefaultVdsCommandExecutor.java:14) [vdsbroker.jar:]
 at 
 org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:404)
 [vdsbroker.jar:]
 at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsComman
 d(VDSBrokerFrontendImpl.java:33) [bll.jar:]
 at org.ovirt.engine.core.bll.VmHandler.unLockVm(VmHandler.java:377)
 [bll.jar:]



 Y.

 [1]  http://jenkins.ovirt.org/job/ovirt-system-tests_master_chec
 

Re: [ovirt-devel] System tests failure (wrong test code?)

[Arik Hadas]

On Sat, Mar 18, 2017 at 12:57 PM, Yaniv Kaul  wrote:

>
>
> On Sat, Mar 18, 2017 at 12:05 AM, Michal Skrivanek 
> wrote:
>
>>
>> On 17 Mar 2017, at 20:49, Yaniv Kaul  wrote:
>>
>>
>>
>> On Thu, Mar 16, 2017 at 8:16 PM, Michal Skrivanek 
>> wrote:
>>
>>>
>>> On 16 Mar 2017, at 15:18, Yaniv Kaul  wrote:
>>>
>>>
>>>
>>> On Thu, Mar 16, 2017 at 10:46 AM, Nir Soffer  wrote:
>>>
 If found this error in system tests - looks like wrong assert - code
 should check
 if disk is not None before checking state.

 I'm not sure who is the owner of this test, so posting here.

>>>
>>> Theoretically, perhaps.
>>> Practically, it worked (until yesterday?) and now I'm also seeing this
>>> failure - it's not a coincidence.
>>>
>>> However, looking at my failure[1], I'm seeing other nasty stuff, which
>>> may explain the later on failures
>>>
>>> For example, new NPE I have not seen in the past:
>>> 2017-03-16 09:57:57,581-04 INFO  
>>> [org.ovirt.engine.core.bll.AddVmTemplateCommand]
>>> (DefaultQuartzScheduler1) [5d94233] Ending command
>>> 'org.ovirt.engine.core.bll.AddVmTemplateCommand' successfully.
>>>
>>>
>>> Is this IST or which TZ?
>>>
>>
>> Interesting question - I guess that's why we need the offset from UTC or
>> use UTC in the logs.
>>
>>
>>> Likely https://gerrit.ovirt.org/#/c/69323 merged 10:33:20 CET today
>>>
>>
>> That's the cause or the fix?
>>
>>
>> oh, sorry, the cause.
>> we were not able to find anyone to confirm and resolve it today
>> unfortunately
>>
>
A fix is posted: https://gerrit.ovirt.org/#/c/74276/
The cause is explained in the commit message.
In our defense I'll say that somehow the system tests passed when we ran
them ([1]) and that the command for adding a template became way too
complicated than it is supposed to be with the introduction of import from
glance and instance-types.

[1] http://jenkins.ovirt.org/job/ovirt-system-tests_manual/129/


>
> A secondary bug is that it fails every 10 seconds or so, continuously.
> Y.
>

Right, because it fails in the end-action phase of the command and we have
a retry mechanism that attempts to end the command (unless stated
otherwise) periodically.


>
>
>
>>
>> Y.
>>
>>
>>>
>>> 2017-03-16 09:57:57,591-04 INFO  
>>> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
>>> (DefaultQuartzScheduler1) [5d94233] START, SetVmStatusVDSCommand(
>>> SetVmStatusVDSCommandParameters:{runAsync='true',
>>> vmId='----', status='Down',
>>> exitStatus='Normal'}), log id: 30ee3299
>>> 2017-03-16 09:57:57,593-04 DEBUG [org.ovirt.engine.core.dal.dbb
>>> roker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
>>> (DefaultQuartzScheduler1) [5d94233] Compiled stored procedure. Call string
>>> is [{call getvmdynamicbyvmguid(?)}]
>>> 2017-03-16 09:57:57,594-04 DEBUG [org.ovirt.engine.core.dal.dbb
>>> roker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
>>> (DefaultQuartzScheduler1) [5d94233] SqlCall for procedure
>>> [GetVmDynamicByVmGuid] compiled
>>> 2017-03-16 09:57:57,595-04 ERROR 
>>> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
>>> (DefaultQuartzScheduler1) [5d94233] Command 'SetVmStatusVDSCommand(
>>> SetVmStatusVDSCommandParameters:{runAsync='true',
>>> vmId='----', status='Down',
>>> exitStatus='Normal'})' execution failed: null
>>> 2017-03-16 09:57:57,595-04 DEBUG 
>>> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
>>> (DefaultQuartzScheduler1) [5d94233] Exception:
>>> java.lang.NullPointerException
>>> at org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand.execut
>>> eVDSCommand(SetVmStatusVDSCommand.java:33) [vdsbroker.jar:]
>>> at 
>>> org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
>>> [vdsbroker.jar:]
>>> at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
>>> [dal.jar:]
>>> at org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandE
>>> xecutor.execute(DefaultVdsCommandExecutor.java:14) [vdsbroker.jar:]
>>> at 
>>> org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:404)
>>> [vdsbroker.jar:]
>>> at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsComman
>>> d(VDSBrokerFrontendImpl.java:33) [bll.jar:]
>>> at org.ovirt.engine.core.bll.VmHandler.unLockVm(VmHandler.java:377)
>>> [bll.jar:]
>>>
>>>
>>>
>>> Y.
>>>
>>> [1]  http://jenkins.ovirt.org/job/ovirt-system-tests_master_chec
>>> k-patch-el7-x86_64/326/artifact/exported-artifacts/basic_sui
>>> te_master__logs/test_logs/basic-suite-master/post-004_basic_
>>> sanity.py/lago-basic-suite-master-engine/_var_log/ovirt-
>>> engine/engine.log
>>>
>>>
 *08:28:05*   # snapshots_merge: *08:28:31* Unhandled exception in 
  at 0x276a5f0>*08:28:31* Traceback (most recent call 
 last):*08:28:31*   File 
 "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 217, in 
 

Re: [ovirt-devel] System tests failure (wrong test code?)

[Nir Soffer]

On Fri, Mar 17, 2017 at 9:49 PM Yaniv Kaul  wrote:

> On Thu, Mar 16, 2017 at 8:16 PM, Michal Skrivanek 
> wrote:
>
>
> On 16 Mar 2017, at 15:18, Yaniv Kaul  wrote:
>
>
>
> On Thu, Mar 16, 2017 at 10:46 AM, Nir Soffer  wrote:
>
> If found this error in system tests - looks like wrong assert - code
> should check
> if disk is not None before checking state.
>
> I'm not sure who is the owner of this test, so posting here.
>
>
> Theoretically, perhaps.
> Practically, it worked (until yesterday?) and now I'm also seeing this
> failure - it's not a coincidence.
>
> However, looking at my failure[1], I'm seeing other nasty stuff, which may
> explain the later on failures
>
> For example, new NPE I have not seen in the past:
> 2017-03-16 09:57:57,581-04 INFO
>  [org.ovirt.engine.core.bll.AddVmTemplateCommand] (DefaultQuartzScheduler1)
> [5d94233] Ending command 'org.ovirt.engine.core.bll.AddVmTemplateCommand'
> successfully.
>
>
> Is this IST or which TZ?
>
>
> Interesting question - I guess that's why we need the offset from UTC or
> use UTC in the logs.
>

We have offset from UTC - "-04"

Do we have slaves here?
https://time.is/map/UTC-4

Probably machine with incorrect timezone?


>
>
> Likely https://gerrit.ovirt.org/#/c/69323 merged 10:33:20 CET today
>
>
> That's the cause or the fix?
> Y.
>
>
>
> 2017-03-16 09:57:57,591-04 INFO
>  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] START, SetVmStatusVDSCommand(
> SetVmStatusVDSCommandParameters:{runAsync='true',
> vmId='----', status='Down',
> exitStatus='Normal'}), log id: 30ee3299
> 2017-03-16 09:57:57,593-04 DEBUG
> [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
> (DefaultQuartzScheduler1) [5d94233] Compiled stored procedure. Call string
> is [{call getvmdynamicbyvmguid(?)}]
> 2017-03-16 09:57:57,594-04 DEBUG
> [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
> (DefaultQuartzScheduler1) [5d94233] SqlCall for procedure
> [GetVmDynamicByVmGuid] compiled
> 2017-03-16 09:57:57,595-04 ERROR
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] Command 'SetVmStatusVDSCommand(
> SetVmStatusVDSCommandParameters:{runAsync='true',
> vmId='----', status='Down',
> exitStatus='Normal'})' execution failed: null
> 2017-03-16 09:57:57,595-04 DEBUG
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] Exception:
> java.lang.NullPointerException
> at
> org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand.executeVDSCommand(SetVmStatusVDSCommand.java:33)
> [vdsbroker.jar:]
> at
> org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
> [vdsbroker.jar:]
> at
> org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
> [dal.jar:]
> at
> org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
> [vdsbroker.jar:]
> at
> org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:404)
> [vdsbroker.jar:]
> at
> org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33)
> [bll.jar:]
> at org.ovirt.engine.core.bll.VmHandler.unLockVm(VmHandler.java:377)
> [bll.jar:]
>
>
>
> Y.
>
> [1]
> http://jenkins.ovirt.org/job/ovirt-system-tests_master_check-patch-el7-x86_64/326/artifact/exported-artifacts/basic_suite_master__logs/test_logs/basic-suite-master/post-004_basic_sanity.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/engine.log
>
>
> *08:28:05*   # snapshots_merge: *08:28:31* Unhandled exception in   at 0x276a5f0>*08:28:31* Traceback (most recent call last):*08:28:31* 
>   File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 217, in 
> assert_equals_within*08:28:31* res = func()*08:28:31*   File 
> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>  line 466, in *08:28:31* 
> api.vms.get(VM0_NAME).disks.get(disk_name).status.state == 'ok'*08:28:31* 
> AttributeError: 'NoneType' object has no attribute 'state'*08:28:31* Error 
> while running thread*08:28:31* Traceback (most recent call last):*08:28:31*   
> File "/usr/lib/python2.7/site-packages/lago/utils.py", line 57, in 
> _ret_via_queue*08:28:31* queue.put({'return': func()})*08:28:31*   File 
> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>  line 465, in snapshot_live_merge*08:28:31* lambda:*08:28:31*   File 
> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 264, in 
> assert_true_within_long*08:28:31* assert_equals_within_long(func, True, 
> allowed_exceptions)*08:28:31*   File 
> 

Re: [ovirt-devel] System tests failure (wrong test code?)

[Yaniv Kaul]

On Thu, Mar 16, 2017 at 8:16 PM, Michal Skrivanek 
wrote:

>
> On 16 Mar 2017, at 15:18, Yaniv Kaul  wrote:
>
>
>
> On Thu, Mar 16, 2017 at 10:46 AM, Nir Soffer  wrote:
>
>> If found this error in system tests - looks like wrong assert - code
>> should check
>> if disk is not None before checking state.
>>
>> I'm not sure who is the owner of this test, so posting here.
>>
>
> Theoretically, perhaps.
> Practically, it worked (until yesterday?) and now I'm also seeing this
> failure - it's not a coincidence.
>
> However, looking at my failure[1], I'm seeing other nasty stuff, which may
> explain the later on failures
>
> For example, new NPE I have not seen in the past:
> 2017-03-16 09:57:57,581-04 INFO  
> [org.ovirt.engine.core.bll.AddVmTemplateCommand]
> (DefaultQuartzScheduler1) [5d94233] Ending command
> 'org.ovirt.engine.core.bll.AddVmTemplateCommand' successfully.
>
>
> Is this IST or which TZ?
>

Interesting question - I guess that's why we need the offset from UTC or
use UTC in the logs.


> Likely https://gerrit.ovirt.org/#/c/69323 merged 10:33:20 CET today
>

That's the cause or the fix?
Y.


>
> 2017-03-16 09:57:57,591-04 INFO  
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] START, SetVmStatusVDSCommand(
> SetVmStatusVDSCommandParameters:{runAsync='true',
> vmId='----', status='Down',
> exitStatus='Normal'}), log id: 30ee3299
> 2017-03-16 09:57:57,593-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.
> PostgresDbEngineDialect$PostgresSimpleJdbcCall] (DefaultQuartzScheduler1)
> [5d94233] Compiled stored procedure. Call string is [{call
> getvmdynamicbyvmguid(?)}]
> 2017-03-16 09:57:57,594-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.
> PostgresDbEngineDialect$PostgresSimpleJdbcCall] (DefaultQuartzScheduler1)
> [5d94233] SqlCall for procedure [GetVmDynamicByVmGuid] compiled
> 2017-03-16 09:57:57,595-04 ERROR 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] Command 'SetVmStatusVDSCommand(
> SetVmStatusVDSCommandParameters:{runAsync='true',
> vmId='----', status='Down',
> exitStatus='Normal'})' execution failed: null
> 2017-03-16 09:57:57,595-04 DEBUG 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
> (DefaultQuartzScheduler1) [5d94233] Exception:
> java.lang.NullPointerException
> at org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand.
> executeVDSCommand(SetVmStatusVDSCommand.java:33) [vdsbroker.jar:]
> at org.ovirt.engine.core.vdsbroker.VDSCommandBase.
> executeCommand(VDSCommandBase.java:73) [vdsbroker.jar:]
> at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
> [dal.jar:]
> at org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.
> execute(DefaultVdsCommandExecutor.java:14) [vdsbroker.jar:]
> at org.ovirt.engine.core.vdsbroker.ResourceManager.
> runVdsCommand(ResourceManager.java:404) [vdsbroker.jar:]
> at 
> org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33)
> [bll.jar:]
> at org.ovirt.engine.core.bll.VmHandler.unLockVm(VmHandler.java:377)
> [bll.jar:]
>
>
>
> Y.
>
> [1]  http://jenkins.ovirt.org/job/ovirt-system-tests_master_
> check-patch-el7-x86_64/326/artifact/exported-artifacts/
> basic_suite_master__logs/test_logs/basic-suite-master/post-
> 004_basic_sanity.py/lago-basic-suite-master-engine/_
> var_log/ovirt-engine/engine.log
>
>
>> *08:28:05*   # snapshots_merge: *08:28:31* Unhandled exception in >  at 0x276a5f0>*08:28:31* Traceback (most recent call 
>> last):*08:28:31*   File 
>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 217, in 
>> assert_equals_within*08:28:31* res = func()*08:28:31*   File 
>> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>>  line 466, in *08:28:31* 
>> api.vms.get(VM0_NAME).disks.get(disk_name).status.state == 'ok'*08:28:31* 
>> AttributeError: 'NoneType' object has no attribute 'state'*08:28:31* Error 
>> while running thread*08:28:31* Traceback (most recent call last):*08:28:31*  
>>  File "/usr/lib/python2.7/site-packages/lago/utils.py", line 57, in 
>> _ret_via_queue*08:28:31* queue.put({'return': func()})*08:28:31*   File 
>> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>>  line 465, in snapshot_live_merge*08:28:31* lambda:*08:28:31*   File 
>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 264, in 
>> assert_true_within_long*08:28:31* assert_equals_within_long(func, True, 
>> allowed_exceptions)*08:28:31*   File 
>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 251, in 
>> assert_equals_within_long*08:28:31* func, value, LONG_TIMEOUT, 
>> allowed_exceptions=allowed_exceptions*08:28:31*   File 
>> 

Re: [ovirt-devel] System tests failure (wrong test code?)

[Michal Skrivanek]

> On 16 Mar 2017, at 15:18, Yaniv Kaul  wrote:
> 
> 
> 
> On Thu, Mar 16, 2017 at 10:46 AM, Nir Soffer  > wrote:
> If found this error in system tests - looks like wrong assert - code should 
> check
> if disk is not None before checking state.
> 
> I'm not sure who is the owner of this test, so posting here.
> 
> Theoretically, perhaps. 
> Practically, it worked (until yesterday?) and now I'm also seeing this 
> failure - it's not a coincidence.
> However, looking at my failure[1], I'm seeing other nasty stuff, which may 
> explain the later on failures
> 
> For example, new NPE I have not seen in the past:
> 2017-03-16 09:57:57,581-04 INFO  
> [org.ovirt.engine.core.bll.AddVmTemplateCommand] (DefaultQuartzScheduler1) 
> [5d94233] Ending command 'org.ovirt.engine.core.bll.AddVmTemplateCommand' 
> successfully.

Is this IST or which TZ?
Likely https://gerrit.ovirt.org/#/c/69323  
merged 10:33:20 CET today 

> 2017-03-16 09:57:57,591-04 INFO  
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] 
> (DefaultQuartzScheduler1) [5d94233] START, SetVmStatusVDSCommand( 
> SetVmStatusVDSCommandParameters:{runAsync='true', 
> vmId='----', status='Down', 
> exitStatus='Normal'}), log id: 30ee3299
> 2017-03-16 09:57:57,593-04 DEBUG 
> [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
>  (DefaultQuartzScheduler1) [5d94233] Compiled stored procedure. Call string 
> is [{call getvmdynamicbyvmguid(?)}]
> 2017-03-16 09:57:57,594-04 DEBUG 
> [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
>  (DefaultQuartzScheduler1) [5d94233] SqlCall for procedure 
> [GetVmDynamicByVmGuid] compiled
> 2017-03-16 09:57:57,595-04 ERROR 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] 
> (DefaultQuartzScheduler1) [5d94233] Command 'SetVmStatusVDSCommand( 
> SetVmStatusVDSCommandParameters:{runAsync='true', 
> vmId='----', status='Down', 
> exitStatus='Normal'})' execution failed: null
> 2017-03-16 09:57:57,595-04 DEBUG 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] 
> (DefaultQuartzScheduler1) [5d94233] Exception: java.lang.NullPointerException
>   at 
> org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand.executeVDSCommand(SetVmStatusVDSCommand.java:33)
>  [vdsbroker.jar:]
>   at 
> org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
>  [vdsbroker.jar:]
>   at 
> org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33) 
> [dal.jar:]
>   at 
> org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
>  [vdsbroker.jar:]
>   at 
> org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:404)
>  [vdsbroker.jar:]
>   at 
> org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33)
>  [bll.jar:]
>   at org.ovirt.engine.core.bll.VmHandler.unLockVm(VmHandler.java:377) 
> [bll.jar:]
> 
> 
> 
> Y.
> 
> [1]  
> http://jenkins.ovirt.org/job/ovirt-system-tests_master_check-patch-el7-x86_64/326/artifact/exported-artifacts/basic_suite_master__logs/test_logs/basic-suite-master/post-004_basic_sanity.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/engine.log
>  
> 
> 
> 
> 08:28:05   # snapshots_merge: 
> 08:28:31 Unhandled exception in  at 0x276a5f0>
> 08:28:31 Traceback (most recent call last):
> 08:28:31   File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 
> 217, in assert_equals_within
> 08:28:31 res = func()
> 08:28:31   File 
> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>  line 466, in 
> 08:28:31 api.vms.get(VM0_NAME).disks.get(disk_name).status.state == 'ok'
> 08:28:31 AttributeError: 'NoneType' object has no attribute 'state'
> 08:28:31 Error while running thread
> 08:28:31 Traceback (most recent call last):
> 08:28:31   File "/usr/lib/python2.7/site-packages/lago/utils.py", line 57, in 
> _ret_via_queue
> 08:28:31 queue.put({'return': func()})
> 08:28:31   File 
> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>  line 465, in snapshot_live_merge
> 08:28:31 lambda:
> 08:28:31   File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 
> 264, in assert_true_within_long
> 08:28:31 assert_equals_within_long(func, True, allowed_exceptions)
> 08:28:31   File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 
> 251, in 

Re: [ovirt-devel] System tests failure (wrong test code?)

[Yaniv Kaul]

On Thu, Mar 16, 2017 at 10:46 AM, Nir Soffer  wrote:

> If found this error in system tests - looks like wrong assert - code
> should check
> if disk is not None before checking state.
>
> I'm not sure who is the owner of this test, so posting here.
>

Theoretically, perhaps.
Practically, it worked (until yesterday?) and now I'm also seeing this
failure - it's not a coincidence.
However, looking at my failure[1], I'm seeing other nasty stuff, which may
explain the later on failures

For example, new NPE I have not seen in the past:
2017-03-16 09:57:57,581-04 INFO
 [org.ovirt.engine.core.bll.AddVmTemplateCommand] (DefaultQuartzScheduler1)
[5d94233] Ending command 'org.ovirt.engine.core.bll.AddVmTemplateCommand'
successfully.
2017-03-16 09:57:57,591-04 INFO
 [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
(DefaultQuartzScheduler1) [5d94233] START, SetVmStatusVDSCommand(
SetVmStatusVDSCommandParameters:{runAsync='true',
vmId='----', status='Down',
exitStatus='Normal'}), log id: 30ee3299
2017-03-16 09:57:57,593-04 DEBUG
[org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
(DefaultQuartzScheduler1) [5d94233] Compiled stored procedure. Call string
is [{call getvmdynamicbyvmguid(?)}]
2017-03-16 09:57:57,594-04 DEBUG
[org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall]
(DefaultQuartzScheduler1) [5d94233] SqlCall for procedure
[GetVmDynamicByVmGuid] compiled
2017-03-16 09:57:57,595-04 ERROR
[org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
(DefaultQuartzScheduler1) [5d94233] Command 'SetVmStatusVDSCommand(
SetVmStatusVDSCommandParameters:{runAsync='true',
vmId='----', status='Down',
exitStatus='Normal'})' execution failed: null
2017-03-16 09:57:57,595-04 DEBUG
[org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
(DefaultQuartzScheduler1) [5d94233] Exception:
java.lang.NullPointerException
at
org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand.executeVDSCommand(SetVmStatusVDSCommand.java:33)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
[vdsbroker.jar:]
at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
[dal.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:404)
[vdsbroker.jar:]
at
org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33)
[bll.jar:]
at org.ovirt.engine.core.bll.VmHandler.unLockVm(VmHandler.java:377)
[bll.jar:]



Y.

[1]
http://jenkins.ovirt.org/job/ovirt-system-tests_master_check-patch-el7-x86_64/326/artifact/exported-artifacts/basic_suite_master__logs/test_logs/basic-suite-master/post-004_basic_sanity.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/engine.log


> *08:28:05*   # snapshots_merge: *08:28:31* Unhandled exception in   at 0x276a5f0>*08:28:31* Traceback (most recent call last):*08:28:31* 
>   File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 217, in 
> assert_equals_within*08:28:31* res = func()*08:28:31*   File 
> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>  line 466, in *08:28:31* 
> api.vms.get(VM0_NAME).disks.get(disk_name).status.state == 'ok'*08:28:31* 
> AttributeError: 'NoneType' object has no attribute 'state'*08:28:31* Error 
> while running thread*08:28:31* Traceback (most recent call last):*08:28:31*   
> File "/usr/lib/python2.7/site-packages/lago/utils.py", line 57, in 
> _ret_via_queue*08:28:31* queue.put({'return': func()})*08:28:31*   File 
> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>  line 465, in snapshot_live_merge*08:28:31* lambda:*08:28:31*   File 
> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 264, in 
> assert_true_within_long*08:28:31* assert_equals_within_long(func, True, 
> allowed_exceptions)*08:28:31*   File 
> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 251, in 
> assert_equals_within_long*08:28:31* func, value, LONG_TIMEOUT, 
> allowed_exceptions=allowed_exceptions*08:28:31*   File 
> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 217, in 
> assert_equals_within*08:28:31* res = func()*08:28:31*   File 
> "/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
>  line 466, in *08:28:31* 
> api.vms.get(VM0_NAME).disks.get(disk_name).status.state == 'ok'*08:28:31* 
> AttributeError: 'NoneType' object has no attribute 'state'
>
>
>
> ___
> Devel mailing list
> Devel@ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel
>

[ovirt-devel] System tests failure (wrong test code?)

[Nir Soffer]

If found this error in system tests - looks like wrong assert - code should
check
if disk is not None before checking state.

I'm not sure who is the owner of this test, so posting here.

*08:28:05*   # snapshots_merge: *08:28:31* Unhandled exception in
 at 0x276a5f0>*08:28:31* Traceback (most recent call
last):*08:28:31*   File
"/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 217, in
assert_equals_within*08:28:31* res = func()*08:28:31*   File
"/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
line 466, in *08:28:31*
api.vms.get(VM0_NAME).disks.get(disk_name).status.state ==
'ok'*08:28:31* AttributeError: 'NoneType' object has no attribute
'state'*08:28:31* Error while running thread*08:28:31* Traceback (most
recent call last):*08:28:31*   File
"/usr/lib/python2.7/site-packages/lago/utils.py", line 57, in
_ret_via_queue*08:28:31* queue.put({'return': func()})*08:28:31*
File 
"/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
line 465, in snapshot_live_merge*08:28:31* lambda:*08:28:31*
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line
264, in assert_true_within_long*08:28:31*
assert_equals_within_long(func, True, allowed_exceptions)*08:28:31*
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line
251, in assert_equals_within_long*08:28:31* func, value,
LONG_TIMEOUT, allowed_exceptions=allowed_exceptions*08:28:31*   File
"/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 217, in
assert_equals_within*08:28:31* res = func()*08:28:31*   File
"/home/jenkins/workspace/ovirt-system-tests_manual/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py",
line 466, in *08:28:31*
api.vms.get(VM0_NAME).disks.get(disk_name).status.state ==
'ok'*08:28:31* AttributeError: 'NoneType' object has no attribute
'state'
___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel