<div dir="ltr"><div><div>Heartbeat issue caused channel being closed and set to null which caused a surprise for a reactor.<br></div>It seems that we may want to schedule closure of channel in this situation instead of calling it explicitly.<br><br></div>What was the cause of the heartbeat issues?<br></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Oct 27, 2016 at 4:12 AM, Allon Mureinik <span dir="ltr"><<a href="mailto:amureini@redhat.com" target="_blank">amureini@redhat.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div class="gmail_default" style="font-family:monospace,monospace">Seems like we cleared up the engine issues related to the recent injection changes.</div><div class="gmail_default" style="font-family:monospace,monospace"><br></div><div class="gmail_default" style="font-family:monospace,monospace">I am now seeing stop errors, e.g.:</div><div class="gmail_default" style="font-family:monospace,monospace"><br></div><div class="gmail_default" style="font-family:monospace,monospace"><pre style="color:rgb(0,0,0)">{"jsonrpc": "2.0", "id": "ea0c564f-bc17-4fc2-8f1b-<wbr>67c4d28257c6", "result": {"cpuStatistics": {"1": {"cpuUser": "3.07", "nodeIndex": 0, "cpuSys": "3.00", "cpuIdle": "93.93"}, "0": {"cpuUser": "1.67", "nodeIndex": 0, "cpuSys": "2.07", "cpuIdle": "96.26"}}, "numaNodeMemFree": {"0": {"memPercent": 83, "memFree": "359"}}, "memShared": 0, "thpState": "always", "ksmMergeAcrossNodes": true, "vmCount": 0, "memUsed": "20", "storageDomains": {"b2bb3220-1eb3-426a-90c2-<wbr>5e236aefbe1a": {"code": 0, "actual": true, "version": 0, "acquired": true, "delay": "0.000840117", "lastCheck": "7.1", "valid": true}, "3130195a-73f9-4490-b554-<wbr>98a9205cead6": {"code": 0, "actual": true, "version": 4, "acquired": true, "delay": "0.00150771", "lastCheck": "7.5", "valid": true}, "1a9e202b-83b7-4bdc-9b0c-<wbr>e76b83676068": {"code": 0, "actual": true, "version": 4, "acquired": true, "delay": "0.000590956",
2016-10-26 21:51:09,878 DEBUG [org.ovirt.engine.core.utils.<wbr>timer.FixedDelayJobListener] (DefaultQuartzScheduler7) [6d206bd1] Rescheduling DEFAULT.org.ovirt.engine.core.<wbr>bll.tasks.<wbr>CommandCallbacksPoller.<wbr>invokeCallbackMethods#-<wbr>9223372036854775783 as there is no unfired trigger.
2016-10-26 21:51:28,705 DEBUG [org.ovirt.vdsm.jsonrpc.<wbr>client.reactors.ReactorClient] (SSL Stomp Reactor) [383dd6a0] Heartbeat exceeded. Closing channel
2016-10-26 21:51:28,708 DEBUG [org.ovirt.vdsm.jsonrpc.<wbr>client.reactors.Reactor] (SSL Stomp Reactor) [383dd6a0] Internal server error: null: java.lang.NullPointerException
at org.ovirt.vdsm.jsonrpc.client.<wbr>reactors.SSLClient.write(<wbr>SSLClient.java:102) [vdsm-jsonrpc-java-client.jar:<wbr>]
at org.ovirt.vdsm.jsonrpc.client.<wbr>reactors.ReactorClient.<wbr>processOutgoing(ReactorClient.<wbr>java:245) [vdsm-jsonrpc-java-client.jar:<wbr>]
at org.ovirt.vdsm.jsonrpc.client.<wbr>reactors.ReactorClient.<wbr>process(ReactorClient.java:<wbr>208) [vdsm-jsonrpc-java-client.jar:<wbr>]
at org.ovirt.vdsm.jsonrpc.client.<wbr>reactors.SSLClient.process(<wbr>SSLClient.java:125) [vdsm-jsonrpc-java-client.jar:<wbr>]
at org.ovirt.vdsm.jsonrpc.client.<wbr>reactors.Reactor.<wbr>processChannels(Reactor.java:<wbr>89) [vdsm-jsonrpc-java-client.jar:<wbr>]
at org.ovirt.vdsm.jsonrpc.client.<wbr>reactors.Reactor.run(Reactor.<wbr>java:65) [vdsm-jsonrpc-java-client.jar:<wbr>]</pre><pre style="color:rgb(0,0,0)"><br></pre><pre style="color:rgb(0,0,0)">Piotr - any idea?</pre></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Oct 26, 2016 at 9:34 PM, Nadav Goldin <span dir="ltr"><<a href="mailto:ngoldin@redhat.com" target="_blank">ngoldin@redhat.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Its running now:<br>
<a href="http://jenkins.ovirt.org/job/ovirt-engine_master_build-artifacts-fc24-x86_64/1037/" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/o<wbr>virt-engine_master_build-artif<wbr>acts-fc24-x86_64/1037/</a>,<br>
when it finishes it will trigger the deploy job which will trigger the<br>
experimental job. The build_artifacts job is triggered approximately<br>
every 2 hours(depends on the load).<br>
Inside the build-artifacts job you can see the last<br>
commit(<a href="https://gerrit.ovirt.org/65776" rel="noreferrer" target="_blank">https://gerrit.ovirt.or<wbr>g/65776</a>, which is already after your<br>
commit)<br>
<div class="m_4750592846160278338HOEnZb"><div class="m_4750592846160278338h5"><br>
<br>
On Wed, Oct 26, 2016 at 9:26 PM, Allon Mureinik <<a href="mailto:amureini@redhat.com" target="_blank">amureini@redhat.com</a>> wrote:<br>
> @Infra - the last experimental job I saw was from ~17:30 local Israel time.<br>
> Any idea why another one isn't being triggered (or am I just being daft)?<br>
><br>
> On Wed, Oct 26, 2016 at 6:27 PM, Allon Mureinik <<a href="mailto:amureini@redhat.com" target="_blank">amureini@redhat.com</a>> wrote:<br>
>><br>
>> Yipes.<br>
>> [1] should fix that, waiting for the CI to run to merge.<br>
>><br>
>> [1] <a href="https://gerrit.ovirt.org/#/c/65768/" rel="noreferrer" target="_blank">https://gerrit.ovirt.org/#/c/6<wbr>5768/</a><br>
>><br>
>> On Wed, Oct 26, 2016 at 3:42 PM, Nadav Goldin <<a href="mailto:ngoldin@redhat.com" target="_blank">ngoldin@redhat.com</a>> wrote:<br>
>>><br>
>>> Unfortunately it is still failing, see[1], the repository used was<br>
>>> built from commit [2]. If you want to check the logs same links<br>
>>> apply(just replace build number 2759->2782)<br>
>>><br>
>>><br>
>>><br>
>>> [1] <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/2782" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/t<wbr>est-repo_ovirt_experimental_ma<wbr>ster/2782</a><br>
>>> [2] <a href="https://gerrit.ovirt.org/#/c/65740/" rel="noreferrer" target="_blank">https://gerrit.ovirt.org/#/c/6<wbr>5740/</a><br>
>>><br>
>>> On Wed, Oct 26, 2016 at 11:33 AM, Tal Nisan <<a href="mailto:tnisan@redhat.com" target="_blank">tnisan@redhat.com</a>> wrote:<br>
>>> > Should be fixed now on master as those patches were just merged:<br>
>>> ><br>
>>> > <a href="https://gerrit.ovirt.org/#/c/65738/" rel="noreferrer" target="_blank">https://gerrit.ovirt.org/#/c/6<wbr>5738/</a> - "Move InjectorRule to VdsBroker":<br>
>>> > aligns the InjectorRule's package with the Injector so it can<br>
>>> > essentially be<br>
>>> > used wherever the Injector is used [+12, -4]<br>
>>> > <a href="https://gerrit.ovirt.org/#/c/65739" rel="noreferrer" target="_blank">https://gerrit.ovirt.org/#/c/6<wbr>5739</a> - "InjectorRule: override injector<br>
>>> > anyway": Fixes a bug in InjectorRule where the Injector is only mocked<br>
>>> > if<br>
>>> > you call InjectorRule.bind [+6, -1]<br>
>>> > <a href="https://gerrit.ovirt.org/#/c/65740" rel="noreferrer" target="_blank">https://gerrit.ovirt.org/#/c/6<wbr>5740</a> - "core: InjectorRule for injecting<br>
>>> > members": Fixes a bug in InjectorRule to allow using<br>
>>> > Injector.injectMembers<br>
>>> > when using it [+18, -5]<br>
>>> > <a href="https://gerrit.ovirt.org/#/c/65725" rel="noreferrer" target="_blank">https://gerrit.ovirt.org/#/c/6<wbr>5725</a> - "core: Fix AuditLogging": The<br>
>>> > actual<br>
>>> > fix. Basically, goes over all the places that create an<br>
>>> > AuditLoggableBase<br>
>>> > that needs injecting and take care of it [+155, -160]<br>
>>> ><br>
>>> ><br>
>>> > On Wed, Oct 26, 2016 at 10:04 AM, Nadav Goldin <<a href="mailto:ngoldin@redhat.com" target="_blank">ngoldin@redhat.com</a>><br>
>>> > wrote:<br>
>>> >><br>
>>> >> Hi,<br>
>>> >> We have new failure on OST from patches merged to master yesterday,<br>
>>> >> the failure started after the merge of [1], but as there were quite a<br>
>>> >> few patches merged quickly I can't make sure it is the one causing<br>
>>> >> it(OST aren't ran per-patch).<br>
>>> >> The test that fails is [2] when attempting to start the VM.<br>
>>> >><br>
>>> >> The error from the API side:<br>
>>> >><br>
>>> >> RequestError:<br>
>>> >> status: 500<br>
>>> >> reason: Internal Server Error<br>
>>> >> detail: javax.ejb.EJBException: java.lang.NullPointerException<br>
>>> >> at<br>
>>> >><br>
>>> >> org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.handleExceptionInNoTx(<wbr>CMTTxInterceptor.java:213)<br>
>>> >> at<br>
>>> >><br>
>>> >> org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.invokeInNoTx(CMTTxInte<wbr>rceptor.java:265)<br>
>>> >> at<br>
>>> >><br>
>>> >> org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.supports(CMTTxIntercep<wbr>tor.java:374)<br>
>>> >> at<br>
>>> >><br>
>>> >> org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.processInvocation(CMTT<wbr>xInterceptor.java:243)<br>
>>> >> at<br>
>>> >><br>
>>> >> org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:340)<br>
>>> >> ....<br>
>>> >><br>
>>> >> In the engine logs there are a few 'java.lang.NullPointerExceptio<wbr>n'<br>
>>> >> errors:<br>
>>> >><br>
>>> >> 2016-10-25 11:53:52,845 INFO<br>
>>> >> [org.ovirt.engine.core.dal.dbb<wbr>roker.auditloghandling.AuditLo<wbr>gableBase]<br>
>>> >> (org.ovirt.thread.pool-6-threa<wbr>d-2) [5e6a88be] Failed to get vds<br>
>>> >> 'd60db21f-95f0-487b-9f17-44861<wbr>e2610a7', error: null<br>
>>> >> 2016-10-25 11:53:52,864 DEBUG<br>
>>> >> [org.ovirt.engine.core.utils.t<wbr>imer.FixedDelayJobListener]<br>
>>> >> (DefaultQuartzScheduler5) [] Rescheduling<br>
>>> >><br>
>>> >><br>
>>> >> DEFAULT.org.ovirt.engine.core.<wbr>bll.tasks.AsyncTaskManager.tim<wbr>erElapsed#-9223372036854775787<br>
>>> >> as there is no unfired trigger.<br>
>>> >> ...<br>
>>> >> 2016-10-25 11:53:52,845 DEBUG<br>
>>> >> [org.ovirt.engine.core.dal.dbb<wbr>roker.auditloghandling.AuditLo<wbr>gableBase]<br>
>>> >> (org.ovirt.thread.pool-6-threa<wbr>d-2) [5e6a88be] Exception:<br>
>>> >> java.lang.NullPointerException<br>
>>> >> at<br>
>>> >><br>
>>> >> org.ovirt.engine.core.dal.dbbr<wbr>oker.auditloghandling.AuditLog<wbr>ableBase.getVdsStatic(AuditLog<wbr>ableBase.java:633)<br>
>>> >> [dal.jar:]<br>
>>> >> at<br>
>>> >><br>
>>> >> org.ovirt.engine.core.dal.dbbr<wbr>oker.auditloghandling.AuditLog<wbr>ableBase.getVdsName(AuditLogab<wbr>leBase.java:504)<br>
>>> >> [dal.jar:]<br>
>>> >> ...<br>
>>> >> 2016-10-25 11:53:52,837 INFO<br>
>>> >> [org.ovirt.engine.core.dal.dbb<wbr>roker.auditloghandling.AuditLo<wbr>gableBase]<br>
>>> >> (org.ovirt.thread.pool-6-threa<wbr>d-2) [5e6a88be] Failed to get vds<br>
>>> >> 'd60db21f-95f0-487b-9f17-44861<wbr>e2610a7', error: null<br>
>>> >> 2016-10-25 11:53:52,837 DEBUG<br>
>>> >> [org.ovirt.engine.core.dal.dbb<wbr>roker.auditloghandling.AuditLo<wbr>gableBase]<br>
>>> >> (org.ovirt.thread.pool-6-threa<wbr>d-2) [5e6a88be] Exception:<br>
>>> >> java.lang.NullPointerException<br>
>>> >> at<br>
>>> >><br>
>>> >> org.ovirt.engine.core.dal.dbbr<wbr>oker.auditloghandling.AuditLog<wbr>ableBase.getVdsStatic(AuditLog<wbr>ableBase.java:633)<br>
>>> >> [dal.jar:]<br>
>>> >> at<br>
>>> >><br>
>>> >> org.ovirt.engine.core.dal.dbbr<wbr>oker.auditloghandling.AuditLog<wbr>ableBase.getVdsName(AuditLogab<wbr>leBase.java:504)<br>
>>> >> [dal.jar:]<br>
>>> >> ...<br>
>>> >><br>
>>> >> The full engine logs can be found here[3] and the entire test suite<br>
>>> >> logs here[4].<br>
>>> >><br>
>>> >> Can anyone have a look?<br>
>>> >><br>
>>> >> Thanks,<br>
>>> >> Nadav.<br>
>>> >><br>
>>> >><br>
>>> >> [1] <a href="https://gerrit.ovirt.org/#/c/65198/" rel="noreferrer" target="_blank">https://gerrit.ovirt.org/#/c/6<wbr>5198/</a><br>
>>> >> [2]<br>
>>> >><br>
>>> >> <a href="https://github.com/oVirt/ovirt-system-tests/blob/master/basic_suite_master/test-scenarios/004_basic_sanity.py#L322" rel="noreferrer" target="_blank">https://github.com/oVirt/ovirt<wbr>-system-tests/blob/master/<wbr>basic_suite_master/test-<wbr>scenarios/004_basic_sanity.py#<wbr>L322</a><br>
>>> >> [3]<br>
>>> >><br>
>>> >> <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/2759/artifact/exported-artifacts/basic_suite_master.sh-fc24/exported-artifacts/test_logs/basic_suite_master/post-004_basic_sanity.py/*zip*/post-004_basic_sanity.py.zip" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/t<wbr>est-repo_ovirt_experimental_ma<wbr>ster/2759/artifact/exported-ar<wbr>tifacts/basic_suite_master.sh-<wbr>fc24/exported-artifacts/test_<wbr>logs/basic_suite_master/post-<wbr>004_basic_sanity.py/*zip*/<wbr>post-004_basic_sanity.py.zip</a><br>
>>> >> [4]<br>
>>> >><br>
>>> >> <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/2759/artifact/exported-artifacts/basic_suite_master.sh-fc24/exported-artifacts/" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/t<wbr>est-repo_ovirt_experimental_ma<wbr>ster/2759/artifact/exported-ar<wbr>tifacts/basic_suite_master.sh-<wbr>fc24/exported-artifacts/</a><br>
>>> >> ______________________________<wbr>_________________<br>
>>> >> Devel mailing list<br>
>>> >> <a href="mailto:Devel@ovirt.org" target="_blank">Devel@ovirt.org</a><br>
>>> >> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank">http://lists.ovirt.org/mailman<wbr>/listinfo/devel</a><br>
>>> ><br>
>>> ><br>
>><br>
>><br>
><br>
</div></div></blockquote></div><br></div>
</blockquote></div><br></div>