* stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
[not found] <E1a77eF-00049f-Er@osstest.test-lab.xenproject.org>
@ 2015-12-11 12:12 ` Ian Campbell
2015-12-11 14:05 ` Ian Campbell
0 siblings, 1 reply; 8+ messages in thread
From: Ian Campbell @ 2015-12-11 12:12 UTC (permalink / raw)
To: Ian Jackson, Wei Liu, Daniel De Graaf; +Cc: xen-devel
Wei did some manual investigation and found he could not reproduce this
issue on merlot1, later realising that he had XSM disabled in his build.
On that hunch I ran an adhoc flight with XSM both on and off, results
below. Public copy of the logs is at
http://logs.test-lab.xenproject.org/osstest/logs/65682/
So it appears that the issue is somehow with the XSM enabled build.
Wei observed that it looked like it was taking longer for the guest vif to
enter forwarding mode, which is rather perplexing since I don't see any
reason XSM would be involved in that, nor why it should also apparently be
machine specific (maybe it's slower everywhere but only too slow on this
host?). I've not looked into this aspect myself.
As with previous failures the issue was with "timeout 10 ssh <guest> date"
which timed out after 10s but the ssh process remained and then appears to
succeed around 5s after the timeout (so 15s in all). This is in:
http://logs.test-lab.xenproject.org/osstest/logs/65682/test-amd64-amd64-xl-
qemut-stubdom-debianhvm-amd64-xsm/13.ts-guest-localmigrate.log
In the success case
http://logs.test-lab.xenproject.org/osstest/logs/65682/test-amd64-amd64-xl-
qemut-stubdom-debianhvm-amd64/13.ts-guest-localmigrate.log
the ssh was basically instantaneous, as it was in all 10 cases in the later
repeated migration:
http://logs.test-lab.xenproject.org/osstest/logs/65682/test-amd64-amd64-xl-
qemut-stubdom-debianhvm-amd64/15.ts-guest-localmigrate.log
(actually it looks like there is some clock skew in the guest, since the
date printed is occasionally 1s before the time the controller logged the
ssh attempt. Perhaps missing NTP in the guest).
I think 10 repetitions indicates it probably wasn't a fluke, however I've
kicked off a repeat (flight 65738) of the test to increase confidence.
In the test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm case I've set
debianhvm_general_timeoutfactor to 2, which should allow the ssh to
complete inside the now 20s timeout, which will then run the 10x case so we
can see how repeated migrations occur. This is not a fix, just a
workaround/diagnostic aid.
I've left test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 alone in the
repeat since I want to check the pass wasn't a fluke.
Ian.
On Thu, 2015-12-10 at 20:17 +0000, ianc@xenbits.xen.org wrote:
> [adhoc adhoc] <testing.git production /dev/pts/5>
> harness 030b474: cr-try-bisect-adhoc: Set OSSTEST_PRIORITY=-30
> 65682: tolerable FAIL
>
> flight 65682 xen-unstable adhoc [adhoc]
> http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/
>
> Failures :-/ but no regressions.
>
> Tests which did not succeed,
> including tests which could not be run:
> test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm 13 guest-
> localmigrate fail baseline untested
>
>
> jobs:
> build-amd64-xsm pass
> build-amd64 pass
> build-amd64-pvops pass
> test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm fail
> test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 pass
>
>
> ------------------------------------------------------------
> sg-report-flight on osstest.test-lab.xenproject.org
> logs: /home/logs/logs
> images: /home/logs/images
>
> Logs, config files, etc. are available at
> http://logs.test-lab.xenproject.org/osstest/logs
>
> Explanation of these reports, and of osstest in general, is at
> http://xenbits.xen.org/gitweb/?p=osstest.git;a=blob;f=README.email;hb
> =master
> http://xenbits.xen.org/gitweb/?p=osstest.git;a=blob;f=README;hb=maste
> r
>
> Test harness code can be found at
> http://xenbits.xen.org/gitweb?p=osstest.git;a=summary
>
> ============================================================
> 2015-12-10 15:12:12 Z flight 65682 nqueued=1 nrunning=0
> 2015-12-10 15:12:12 Z flight 65682 spawning build-amd64
> 2015-12-10 15:12:12 Z flight 65682 spawned build-amd64 [2917]
> 2015-12-10 15:12:12 Z flight 65682 spawning build-amd64-pvops
> 2015-12-10 15:12:12 Z flight 65682 spawned build-amd64-pvops [2918]
> 2015-12-10 15:12:12 Z flight 65682 spawning build-amd64-xsm
> 2015-12-10 15:12:12 Z flight 65682 spawned build-amd64-xsm [2919]
> 2015-12-10 15:12:15 Z [build-amd64-pvops] starting 65682.build-amd64-
> pvops ts-build-check build-check(1)
> 2015-12-10 15:12:15 Z [build-amd64] starting 65682.build-amd64 ts-build-
> check build-check(1)
> 2015-12-10 15:12:15 Z [build-amd64-pvops] awaiting 65682.build-amd64-
> pvops ts-build-check
> 2015-12-10 15:12:15 Z [build-amd64] awaiting 65682.build-amd64 ts-build-
> check
> 2015-12-10 15:12:15 Z [build-amd64-xsm] starting 65682.build-amd64-xsm
> ts-build-check build-check(1)
> 2015-12-10 15:12:18 Z [build-amd64-xsm] awaiting 65682.build-amd64-xsm
> ts-build-check
> 2015-12-10 15:12:18 Z [build-amd64-pvops] finished 65682.build-amd64-
> pvops ts-build-check pass
> 2015-12-10 15:12:18 Z [build-amd64] finished 65682.build-amd64 ts-build-
> check pass
> 2015-12-10 15:12:19 Z [build-amd64-pvops] starting 65682.build-amd64-
> pvops ts-hosts-allocate host hosts-allocate
> 2015-12-10 15:12:19 Z [build-amd64-xsm] finished 65682.build-amd64-xsm
> ts-build-check pass
> 2015-12-10 15:12:19 Z [build-amd64] starting 65682.build-amd64 ts-hosts-
> allocate host hosts-allocate
> 2015-12-10 15:12:19 Z [build-amd64-xsm] starting 65682.build-amd64-xsm
> ts-hosts-allocate host hosts-allocate
> 2015-12-10 15:12:19 Z [build-amd64] awaiting 65682.build-amd64 ts-hosts-
> allocate host
> 2015-12-10 15:12:19 Z [build-amd64-pvops] awaiting 65682.build-amd64-
> pvops ts-hosts-allocate host
> 2015-12-10 15:12:19 Z [build-amd64-xsm] awaiting 65682.build-amd64-xsm
> ts-hosts-allocate host
> 2015-12-10 15:19:21 Z [build-amd64-pvops] finished 65682.build-amd64-
> pvops ts-hosts-allocate host pass
> 2015-12-10 15:19:22 Z [build-amd64-pvops] starting 65682.build-amd64-
> pvops ts-host-install-twice host-install(3)
> 2015-12-10 15:19:22 Z [build-amd64-pvops] awaiting 65682.build-amd64-
> pvops ts-host-install-twice
> 2015-12-10 15:30:14 Z [build-amd64-pvops] finished 65682.build-amd64-
> pvops ts-host-install-twice pass
> 2015-12-10 15:30:14 Z [build-amd64-pvops] starting 65682.build-amd64-
> pvops ts-xen-build-prep host-build-prep
> 2015-12-10 15:30:14 Z [build-amd64-pvops] awaiting 65682.build-amd64-
> pvops ts-xen-build-prep
> 2015-12-10 15:37:34 Z [build-amd64-pvops] finished 65682.build-amd64-
> pvops ts-xen-build-prep pass
> 2015-12-10 15:38:04 Z [build-amd64-pvops] starting 65682.build-amd64-
> pvops ts-kernel-build kernel-build
> 2015-12-10 15:38:12 Z [build-amd64-pvops] awaiting 65682.build-amd64-
> pvops ts-kernel-build
> 2015-12-10 15:38:51 Z [build-amd64-xsm] finished 65682.build-amd64-xsm
> ts-hosts-allocate host pass
> 2015-12-10 15:38:51 Z [build-amd64-xsm] starting 65682.build-amd64-xsm
> ts-host-install-twice host-install(3)
> 2015-12-10 15:38:52 Z [build-amd64-xsm] awaiting 65682.build-amd64-xsm
> ts-host-install-twice
> 2015-12-10 15:38:52 Z [build-amd64] finished 65682.build-amd64 ts-hosts-
> allocate host pass
> 2015-12-10 15:38:54 Z [build-amd64] starting 65682.build-amd64 ts-host-
> install-twice host-install(3)
> 2015-12-10 15:38:55 Z [build-amd64] awaiting 65682.build-amd64 ts-host-
> install-twice
> 2015-12-10 15:38:55 Z [build-amd64-xsm] finished 65682.build-amd64-xsm
> ts-host-install-twice pass
> 2015-12-10 15:38:56 Z [build-amd64-xsm] starting 65682.build-amd64-xsm
> ts-xen-build-prep host-build-prep
> 2015-12-10 15:38:57 Z [build-amd64-xsm] awaiting 65682.build-amd64-xsm
> ts-xen-build-prep
> 2015-12-10 15:38:57 Z [build-amd64] finished 65682.build-amd64 ts-host-
> install-twice pass
> 2015-12-10 15:38:59 Z [build-amd64] starting 65682.build-amd64 ts-xen-
> build-prep host-build-prep
> 2015-12-10 15:39:00 Z [build-amd64] awaiting 65682.build-amd64 ts-xen-
> build-prep
> 2015-12-10 15:39:00 Z [build-amd64-xsm] finished 65682.build-amd64-xsm
> ts-xen-build-prep pass
> 2015-12-10 15:39:03 Z [build-amd64-xsm] starting 65682.build-amd64-xsm
> ts-xen-build xen-build
> 2015-12-10 15:39:04 Z [build-amd64] finished 65682.build-amd64 ts-xen-
> build-prep pass
> 2015-12-10 15:39:06 Z [build-amd64-xsm] awaiting 65682.build-amd64-xsm
> ts-xen-build
> 2015-12-10 15:39:06 Z [build-amd64] starting 65682.build-amd64 ts-xen-
> build xen-build
> 2015-12-10 15:39:07 Z [build-amd64] awaiting 65682.build-amd64 ts-xen-
> build
> 2015-12-10 15:57:23 Z [build-amd64] finished 65682.build-amd64 ts-xen-
> build pass
> 2015-12-10 15:57:24 Z flight 65682 reaped build-amd64 [2917] EXIT 0
> 2015-12-10 15:57:25 Z flight 65682 nqueued=1 nrunning=2
> 2015-12-10 15:57:29 Z [build-amd64-xsm] finished 65682.build-amd64-xsm
> ts-xen-build pass
> 2015-12-10 15:57:29 Z flight 65682 reaped build-amd64-xsm [2919] EXIT 0
> 2015-12-10 15:57:30 Z flight 65682 nqueued=1 nrunning=1
> 2015-12-10 15:57:39 Z [build-amd64-pvops] finished 65682.build-amd64-
> pvops ts-kernel-build pass
> 2015-12-10 15:57:40 Z flight 65682 reaped build-amd64-pvops [2918] EXIT
> 0
> 2015-12-10 15:57:40 Z flight 65682 nqueued=1 nrunning=0
> 2015-12-10 15:57:40 Z flight 65682 spawning test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64
> 2015-12-10 15:57:40 Z flight 65682 spawned test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64 [27165]
> 2015-12-10 15:57:40 Z flight 65682 spawning test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64-xsm
> 2015-12-10 15:57:40 Z flight 65682 spawned test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64-xsm [27166]
> 2015-12-10 15:57:44 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> build-check build-check(1)
> 2015-12-10 15:57:44 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> build-check
> 2015-12-10 15:57:44 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-build-check build-check(1)
> 2015-12-10 15:57:45 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-build-check
> 2015-12-10 15:57:45 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> build-check pass
> 2015-12-10 15:57:46 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-build-check pass
> 2015-12-10 15:57:46 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> hosts-allocate host hosts-allocate
> 2015-12-10 15:57:47 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-hosts-allocate host hosts-allocate
> 2015-12-10 15:57:47 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> hosts-allocate host
> 2015-12-10 15:57:47 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-hosts-allocate host
> 2015-12-10 15:58:09 Z flight 65682 killing build-amd64 [2917]
> 2015-12-10 15:58:15 Z flight 65682 killing build-amd64-xsm [2919]
> 2015-12-10 15:58:25 Z flight 65682 killing build-amd64-pvops [2918]
> 2015-12-10 17:48:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> hosts-allocate host pass
> 2015-12-10 17:48:10 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> install-twice host host-install(3)
> 2015-12-10 17:48:10 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> install-twice host
> 2015-12-10 18:04:56 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> install-twice host pass
> 2015-12-10 18:04:56 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> ping-check host host-ping-check-native
> 2015-12-10 18:04:57 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> ping-check host
> 2015-12-10 18:05:34 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> ping-check host pass
> 2015-12-10 18:05:36 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-xen-
> install host xen-install
> 2015-12-10 18:05:39 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-xen-
> install host
> 2015-12-10 18:08:28 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-xen-
> install host pass
> 2015-12-10 18:08:32 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> reboot host xen-boot
> 2015-12-10 18:08:35 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> reboot host
> 2015-12-10 18:12:49 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> reboot host pass
> 2015-12-10 18:12:50 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> ping-check host host-ping-check-xen
> 2015-12-10 18:12:50 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> ping-check host
> 2015-12-10 18:13:12 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-host-
> ping-check host pass
> 2015-12-10 18:13:12 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-leak-
> check basis host leak-check/basis(8)
> 2015-12-10 18:13:13 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-leak-
> check basis host
> 2015-12-10 18:13:16 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-leak-
> check basis host pass
> 2015-12-10 18:13:16 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> debian-hvm-install debian-hvm-install
> 2015-12-10 18:13:17 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> debian-hvm-install
> 2015-12-10 18:23:04 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> debian-hvm-install pass
> 2015-12-10 18:23:04 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> migrate-support-check host debianhvm 1 migrate-support-check
> 2015-12-10 18:23:05 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> migrate-support-check host debianhvm 1
> 2015-12-10 18:23:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> migrate-support-check host debianhvm 1 pass
> 2015-12-10 18:23:08 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> saverestore-support-check host debianhvm saverestore-support-check
> 2015-12-10 18:23:09 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> saverestore-support-check host debianhvm
> 2015-12-10 18:23:10 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> saverestore-support-check host debianhvm pass
> 2015-12-10 18:23:10 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-saverestore host debianhvm guest-saverestore
> 2015-12-10 18:23:11 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-saverestore host debianhvm
> 2015-12-10 18:26:15 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-saverestore host debianhvm pass
> 2015-12-10 18:26:18 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-localmigrate host debianhvm guest-localmigrate
> 2015-12-10 18:26:20 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-localmigrate host debianhvm
> 2015-12-10 18:29:44 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-localmigrate host debianhvm pass
> 2015-12-10 18:29:45 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-saverestore host debianhvm guest-saverestore.2
> 2015-12-10 18:29:45 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-saverestore host debianhvm
> 2015-12-10 18:32:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-saverestore host debianhvm pass
> 2015-12-10 18:32:08 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-localmigrate x10 host debianhvm guest-localmigrate/x10
> 2015-12-10 18:32:08 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-localmigrate x10 host debianhvm
> 2015-12-10 19:04:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-localmigrate x10 host debianhvm pass
> 2015-12-10 19:04:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-stop host debianhvm guest-stop
> 2015-12-10 19:04:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-stop host debianhvm
> 2015-12-10 19:06:35 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-stop host debianhvm pass
> 2015-12-10 19:06:44 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> repeat-test 10 ts-guest-start host debianhvm {;} ts-guest-stop host
> debianhvm guest-start/debianhvm.repeat
> 2015-12-10 19:06:47 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> repeat-test 10 ts-guest-start host debianhvm {;} ts-guest-stop host
> debianhvm
> 2015-12-10 19:25:50 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> repeat-test 10 ts-guest-start host debianhvm {;} ts-guest-stop host
> debianhvm pass
> 2015-12-10 19:25:51 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-start host debianhvm guest-start.2
> 2015-12-10 19:25:51 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-start host debianhvm
> 2015-12-10 19:27:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-start host debianhvm pass
> 2015-12-10 19:27:07 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-destroy host debianhvm guest-destroy
> 2015-12-10 19:27:08 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-destroy host debianhvm
> 2015-12-10 19:27:31 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-
> guest-destroy host debianhvm pass
> 2015-12-10 19:27:32 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-leak-
> check check host leak-check/check
> 2015-12-10 19:27:32 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-leak-
> check check host
> 2015-12-10 19:27:35 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-leak-
> check check host pass
> 2015-12-10 19:27:35 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-logs-
> capture host capture-logs(21)
> 2015-12-10 19:27:35 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-logs-
> capture host
> 2015-12-10 19:29:12 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64]
> finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 ts-logs-
> capture host pass
> 2015-12-10 19:29:13 Z flight 65682 reaped test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64 [27165] EXIT 0
> 2015-12-10 19:29:14 Z flight 65682 nqueued=0 nrunning=1
> 2015-12-10 19:29:23 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-hosts-allocate host pass
> 2015-12-10 19:29:24 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-install-twice host host-install(3)
> 2015-12-10 19:29:24 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-install-twice host
> 2015-12-10 19:29:58 Z flight 65682 killing test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64 [27165]
> 2015-12-10 19:45:27 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-install-twice host pass
> 2015-12-10 19:45:28 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-ping-check host host-ping-check-native
> 2015-12-10 19:45:29 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-ping-check host
> 2015-12-10 19:45:50 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-ping-check host pass
> 2015-12-10 19:45:51 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-xen-install host xen-install
> 2015-12-10 19:45:51 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-xen-install host
> 2015-12-10 19:47:11 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-xen-install host pass
> 2015-12-10 19:47:11 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-reboot host xen-boot
> 2015-12-10 19:47:12 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-reboot host
> 2015-12-10 19:51:25 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-reboot host pass
> 2015-12-10 19:51:25 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-ping-check host host-ping-check-xen
> 2015-12-10 19:51:25 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-ping-check host
> 2015-12-10 19:51:46 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-host-ping-check host pass
> 2015-12-10 19:51:46 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-leak-check basis host leak-check/basis(8)
> 2015-12-10 19:51:47 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-leak-check basis host
> 2015-12-10 19:51:49 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-leak-check basis host pass
> 2015-12-10 19:51:49 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-debian-hvm-install debian-hvm-install
> 2015-12-10 19:51:50 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-debian-hvm-install
> 2015-12-10 20:06:54 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-debian-hvm-install pass
> 2015-12-10 20:07:00 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-migrate-support-check host debianhvm 1 migrate-support-check
> 2015-12-10 20:07:11 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-migrate-support-check host debianhvm 1
> 2015-12-10 20:07:19 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-migrate-support-check host debianhvm 1 pass
> 2015-12-10 20:07:41 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-saverestore-support-check host debianhvm saverestore-support-check
> 2015-12-10 20:07:48 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-saverestore-support-check host debianhvm
> 2015-12-10 20:07:59 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-saverestore-support-check host debianhvm pass
> 2015-12-10 20:07:59 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-guest-saverestore host debianhvm guest-saverestore
> 2015-12-10 20:08:00 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-guest-saverestore host debianhvm
> 2015-12-10 20:10:16 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-guest-saverestore host debianhvm pass
> 2015-12-10 20:10:16 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-guest-localmigrate host debianhvm guest-localmigrate
> 2015-12-10 20:10:16 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-guest-localmigrate host debianhvm
> 2015-12-10 20:14:01 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-guest-localmigrate host debianhvm fail child process exited abnormally
> 2015-12-10 20:14:01 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm run-
> job/test-debianhvm failed: test script failed
> 2015-12-10 20:14:08 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] starting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-logs-capture host capture-logs(14)
> 2015-12-10 20:14:09 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] awaiting 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-logs-capture host
> 2015-12-10 20:16:20 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] finished 65682.test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm
> ts-logs-capture host pass
> 2015-12-10 20:16:20 Z [test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-
> xsm] at least one test failed
> 2015-12-10 20:16:21 Z flight 65682 reaped test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64-xsm [27166] EXIT 0
> 2015-12-10 20:16:23 Z flight 65682 nqueued=0 nrunning=0
> 2015-12-10 20:16:23 Z flight 65682 ending finished.
> 2015-12-10 20:17:06 Z flight 65682 killing test-amd64-amd64-xl-qemut-
> stubdom-debianhvm-amd64-xsm [27166]
> 2015-12-10 20:17:06 Z flight 65682 ended finished.
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
2015-12-11 12:12 ` stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL]) Ian Campbell
@ 2015-12-11 14:05 ` Ian Campbell
2015-12-11 15:12 ` Ian Campbell
0 siblings, 1 reply; 8+ messages in thread
From: Ian Campbell @ 2015-12-11 14:05 UTC (permalink / raw)
To: Ian Jackson, Wei Liu, Daniel De Graaf; +Cc: xen-devel
On Fri, 2015-12-11 at 12:12 +0000, Ian Campbell wrote:
> I think 10 repetitions indicates it probably wasn't a fluke, however I've
> kicked off a repeat (flight 65738) of the test to increase confidence.
>
> In the test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm case I've set
> debianhvm_general_timeoutfactor to 2, which should allow the ssh to
> complete inside the now 20s timeout, which will then run the 10x case so we
> can see how repeated migrations occur. This is not a fix, just a
> workaround/diagnostic aid.
>
> I've left test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64 alone in the
> repeat since I want to check the pass wasn't a fluke.
That repeat has completed, results are at
http://logs.test-lab.xenproject.org/osstest/logs/65738/
(build was reused from the previous adhoc flight 65682)
Both test cases passed, remember that the -xsm one had a doubled time out.
http://logs.test-lab.xenproject.org/osstest/logs/65738/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/13.ts-guest-localmigrate.log
has (ssh debug* elided):
015-12-11 10:58:49 Z executing ssh ... -v root@172.16.145.159 date
OpenSSH_6.0p1 Debian-4+deb7u2, OpenSSL 1.0.1e 11 Feb 2013
[...]
Authenticated to 172.16.145.159 ([172.16.145.159]:22).
[...]
Fri Dec 11 10:59:04 UTC 2015
[...]
Transferred: sent 3064, received 2032 bytes, in 0.0 seconds
Bytes per second: sent 301038.8, received 199644.5
[...]
2015-12-11 10:59:05 Z execution took 15 seconds [**>20/2**]: timeout 50 ssh -[...] root@172.16.145.159 date
In the repeated case http://logs.test-lab.xenproject.org/osstest/logs/65738/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/15.ts-guest-localmigrate.log
it looks like 4 out of the 10 reps took 15-16s, the rest were below the theshold for logging.
The non-XSM case passes completely again.
Ian.
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
2015-12-11 14:05 ` Ian Campbell
@ 2015-12-11 15:12 ` Ian Campbell
2015-12-11 15:16 ` Ian Campbell
0 siblings, 1 reply; 8+ messages in thread
From: Ian Campbell @ 2015-12-11 15:12 UTC (permalink / raw)
To: Ian Jackson, Wei Liu, Daniel De Graaf; +Cc: xen-devel
On Fri, 2015-12-11 at 14:05 +0000, Ian Campbell wrote:
So returning to the logs for 65682 (the first repro, which exhibited the
fail with the usual timeout).
http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/info.html
First thing I noticed was the numa config
http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1-output-xl_vcpu-list
dom0 has 32 vcpus, allowed hard/soft on all processors.
the domU has 2 vcpus, with a soft preference for pcpu 16-23, while the stub
dom has a soft preference for 0-7. I think that's normal NUMA placement
doing what we want and while I've not thought about the wiseness (or
otherwise) of having the stubdom on another node I don't see why that
should cause a 10s+ delay to the network device forwarding.
I've confirmed in
http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1--etc-network-interfaces.new
that STP is disabled.
The hotplug log is empty.
The migration was of dom5 + stubdom6 into dom7 + stubdom8.
Time line (from 13.ts-guest-localmigrate.log):
2015-12-10 20:10:30 Z migration begins
2015-12-10 20:13:43 Z migration completes ("execution took 193 seconds[<=2x400]"
2015-12-10 20:13:43 Z ssh to guest `date` begins
2015-12-10 20:13:53 Z ssh guest timesout
2015-12-10-20:13:58 Z ssh produces: "Thu Dec 10 20:13:58 UTC 2015."
http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/serial-merlot1.log
(very abridged)
Dec 10 20:13:36.441014 (XEN) HVM5 save: CPU
[...]
Dec 10 20:13:36.641048 (XEN) HVM7 restore: CPU 0
[...]
Dec 10 20:13:36.705029 [ 1391.363224] device vif8.0 entered promiscuous mode
Dec 10 20:13:38.753001 [ 1391.369957] IPv6: ADDRCONF(NETDEV_UP): vif8.0: link is not ready
Dec 10 20:13:38.760973 (d8) Bootstrapping...
Dec 10 20:13:38.985061 (d8) backend at /local/domain/0/backend/vif/8/0
[...]
Dec 10 20:13:38.993010 (d8) mac is 5a:36:0e:92:00:02
Dec 10 20:13:38.993038 [ 1391.467483] IPv6: ADDRCONF(NETDEV_CHANGE): vif8.0: link becomes ready
Dec 10 20:13:39.001015 [ 1391.467574] xenbr0: port 4(vif8.0) entered forwarding state
Dec 10 20:13:39.009015 [ 1391.467608] xenbr0: port 4(vif8.0) entered forwarding state
[...]
Dec 10 20:13:39.273017 (d8) xs_read_watch() -> /local/domain/0/backend/vbd/8/5632/params hdc
[...]
Dec 10 20:13:39.281011 [ 1391.850153] device vif7.0 entered promiscuous mode
Dec 10 20:13:39.281047 [ 1391.856999] IPv6: ADDRCONF(NETDEV_UP): vif7.0: link is not ready
Dec 10 20:13:39.289000 (XEN) irq.c:385: Dom7 callback via changed to Direct Vector 0xf3
[...]
Dec 10 20:13:39.369050 (d8) close(3)
Dec 10 20:13:39.377010 (d8) close network: backend at /local/domain/0/backend/vif/8/0
Dec 10 20:13:39.377045 [ 1391.996438] xen_netback:set_backend_state: backend/vif/8/0: prepare for reconnect
Dec 10 20:13:39.385011 [ 1392.034769] xen-blkback:ring-ref 9, event-channel 24, protocol 1 (x86_64-abi)
Dec 10 20:13:39.424993 [ 1392.125011] xenbr0: port 2(vif6.0) entered disabled state
Dec 10 20:13:39.513026 [ 1392.125835] device vif6.0 left promiscuous mode
Dec 10 20:13:39.513062 [ 1392.125868] xenbr0: port 2(vif6.0) entered disabled state
Dec 10 20:13:39.520999 [ 1392.185454] xenbr0: port 3(vif5.0) entered disabled state
Dec 10 20:13:39.569013 [ 1392.186308] device vif5.0 left promiscuous mode
Dec 10 20:13:39.577026 [ 1392.186393] xenbr0: port 3(vif5.0) entered disabled state
Dec 10 20:13:39.584976 (XEN) avc: denied { pcilevel } for domid=8 target=7 scontext=system_u:system_r:dm_dom_t tcontext=system_u:system_r:domU_t_target tclass=hvm
Dec 10 20:13:39.793039 [ 1392.468784] xenbr0: port 4(vif8.0) entered disabled state
Dec 10 20:13:39.856990 [ 1409.562306] IPv6: ADDRCONF(NETDEV_CHANGE): vif7.0: link becomes ready
Dec 10 20:13:56.953048 [ 1409.562434] xenbr0: port 5(vif7.0) entered forwarding state
Dec 10 20:13:56.953097 [ 1409.562450] xenbr0: port 5(vif7.0) entered forwarding state
(the end, until ts-log-capture sends some keys)
I think what we can see at Dec 10 20:13:39.289000 is the PVHVM stuff
initialising direct vector injection of event channels and the stubdom8
network close at Dec 10 20:13:39.377010 is the guest unplugging the
emulated devices, then vif8.0 (the corresponding stubdom vif) goes away and
vif7.0 (the guest's vif) becomes ready.
All of that is well within the window of the "xl migrate".
However as Wei noticed there is then a 17 second delay until vif7.0 enters
the forwarding state.
The source stubdom log (which includes the kernel serial log) is
http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1---var-log-xen-qemu-dm-debianhvm.guest.osstest.log
and the destination is
http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1---var-log-xen-qemu-dm-debianhvm.guest.osstest--incoming.log
Both lack timestamps so it's not easy to discern anything.
In the non-XSM case
2015-12-11 12:58:54 Z migration finishes
2015-12-11 12:58:54 Z ssh guest `date` starts
2015-12-11 12:58:55 Z date output from guest: Fri Dec 11 12:58:55 UTC 2015
and in the host serial logs:
Dec 11 12:58:50.573034 [ 1007.966381] IPv6: ADDRCONF(NETDEV_CHANGE): vif7.0: link becomes ready
Dec 11 12:58:54.133079 [ 1007.966487] xenbr0: port 5(vif7.0) entered forwarding state
Dec 11 12:58:54.133149 [ 1007.966502] xenbr0: port 5(vif7.0) entered forwarding state
Note that there is a 4s (not 16s as with XSM) delay there.
Ian.
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
2015-12-11 15:12 ` Ian Campbell
@ 2015-12-11 15:16 ` Ian Campbell
2015-12-14 10:14 ` Ian Campbell
0 siblings, 1 reply; 8+ messages in thread
From: Ian Campbell @ 2015-12-11 15:16 UTC (permalink / raw)
To: Ian Jackson, Wei Liu, Daniel De Graaf; +Cc: xen-devel
On Fri, 2015-12-11 at 15:12 +0000, Ian Campbell wrote:
> Dec 10 20:13:39.584976 (XEN) avc: denied { pcilevel } for domid=8
> target=7 scontext=system_u:system_r:dm_dom_t
> tcontext=system_u:system_r:domU_t_target tclass=hvm
I wonder if this is an intx associated with the USB?
In the XSM case the guest serial log on restore has:
http://osstest.test-lab.xenproject.org/~osstest/pub/logs/65682/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1---var-log-xen-qemu-dm-debianhvm.guest.osstest--incoming.log
[ 373.747112] ata2.00: configured for MWDMA2
+00 [ 373.920163] usb 1-2: reset full-speed USB device number 2 using uhci_hcd
+04 [ 377.360563] PM: restore of devices complete after 3779.268 msecs
+04 [ 377.365351] usb 1-2: USB disconnect, device number 2
+04 [ 377.720174] usb 1-2: new full-speed USB device number 3 using uhci_hcd
+11 [ 384.829312] usb 1-2: New USB device found, idVendor=0627, idProduct=0001
+11 [ 384.834014] usb 1-2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
+11 [ 384.839012] usb 1-2: Product: QEMU USB Tablet
+11 [ 384.842105] usb 1-2: Manufacturer: QEMU 0.10.2
+11 [ 384.845230] usb 1-2: SerialNumber: 1
+18 [ 391.078740] input: QEMU 0.10.2 QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-2/1-2:1.0/input/input8
+18 [ 391.086474] generic-usb 0003:0627:0001.0002: input,hidraw0: USB HID v0.01 Pointer [QEMU 0.10.2 QEMU USB Tablet] on usb-0000:00:01.2-2/input0
+18 [ 391.095614] Restarting tasks ... done.
+18 [ 391.107562] Setting capacity to 20480000
+18 [ 391.124154] Setting capacity to 20480000
+18 [ 391.140135] uhci_hcd 0000:00:01.2: Unlink after no-IRQ? Controller is probably using the wrong IRQ.
(I've annotated with the time since the first line).
The corresponding log in the non-XSM case is
http://logs.test-lab.xenproject.org/osstest/logs/65738/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64/merlot1---var-log-xen-qemu-dm-debianhvm.guest.osstest--incoming.log.10
[ 338.127757] ata2.00: configured for MWDMA2
+00 [ 338.296159] usb 1-2: reset full-speed USB device number 2 using uhci_hcd
+02 [ 340.301541] usb 1-2: USB disconnect, device number 2
+02 [ 340.301655] PM: restore of devices complete after 2342.528 msecs
+02 [ 340.520096] usb 1-2: new full-speed USB device number 3 using uhci_hcd
+03 [ 341.373756] usb 1-2: New USB device found, idVendor=0627, idProduct=0001
+03 [ 341.378788] usb 1-2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
+03 [ 341.384183] usb 1-2: Product: QEMU USB Tablet
+03 [ 341.387406] usb 1-2: Manufacturer: QEMU 0.10.2
+03 [ 341.390738] usb 1-2: SerialNumber: 1
+03 [ 341.809652] input: QEMU 0.10.2 QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-2/1-2:1.0/input/input8
+03 [ 341.817873] generic-usb 0003:0627:0001.0002: input,hidraw0: USB HID v0.01 Pointer [QEMU 0.10.2 QEMU USB Tablet] on usb-0000:00:01.2-2/input0
+03 [ 341.827641] Restarting tasks ... done.
+03 [ 341.839784] Setting capacity to 20480000
+03 [ 341.846421] Setting capacity to 20480000
Which is over much quicker, and the uhci_hcd is not complaining about a
missing IRQ...
I have a new flight going on (65755) with flask=permissive instead of
flask=enforcing (assuming I didn't botch the osstest modifications to
support that setting via a runvar).
If that test passes, prints the AVC message but not the missing IRQ message
then I think that would be our smoking gun.
The new flight has dropped debianhvm_general_timeoutfactor, which has
proven its point.
Ian.
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
2015-12-11 15:16 ` Ian Campbell
@ 2015-12-14 10:14 ` Ian Campbell
2015-12-14 11:11 ` George Dunlap
2015-12-14 11:55 ` Ian Campbell
0 siblings, 2 replies; 8+ messages in thread
From: Ian Campbell @ 2015-12-14 10:14 UTC (permalink / raw)
To: Ian Jackson, Wei Liu, Daniel De Graaf; +Cc: xen-devel
On Fri, 2015-12-11 at 15:16 +0000, Ian Campbell wrote:
>
> I have a new flight going on (65755) with flask=permissive instead of
> flask=enforcing (assuming I didn't botch the osstest modifications to
> support that setting via a runvar).
I did botch the mods, but luckily permissive is the default, so I got what
I wanted ;-)
> If that test passes, prints the AVC message but not the missing IRQ message
> then I think that would be our smoking gun.
http://logs.test-lab.xenproject.org/osstest/logs/65758/
From serial-merlot1.log:
Dec 11 18:01:57.001037 (XEN) Flask: 64 avtab hash slots, 236 rules.
Dec 11 18:01:57.009023 (XEN) Flask: 64 avtab hash slots, 236 rules.
Dec 11 18:01:57.017004 (XEN) Flask: 3 users, 3 roles, 36 types, 2 bools
Dec 11 18:01:57.017038 (XEN) Flask: 12 classes, 236 rules
Dec 11 18:01:57.025015 (XEN) Flask: Starting in permissive mode.
[...]
Dec 11 18:06:01.229194 (XEN) avc: denied { pcilevel } for domid=2 target=1 scontext=system_u:system_r:dm_dom_t tcontext=system_u:system_r:domU_t_target tclass=hvm
http://logs.test-lab.xenproject.org/osstest/logs/65758/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1---var-log-xen-qemu-dm-debianhvm.guest.osstest--incoming.log.10
i.e. no "uhci_hcd 0000:00:01.2: Unlink after no-IRQ? Controller is
probably using the wrong IRQ." and the test case has passed.
I've running a test with the following patch. I'm reasonably hopeful.
Ian.
From 3f14c5afedc0df360952364b93c2f04de00f00c4 Mon Sep 17 00:00:00 2001
From: Ian Campbell <ian.campbell@citrix.com>
Date: Mon, 14 Dec 2015 08:22:41 +0000
Subject: [PATCH] flask: Allow device model to raise PCI interrupts (pcilevel
capability)
Allows:
(XEN) avc: denied { pcilevel } for domid=2 target=1 scontext=system_u:system_r:dm_dom_t tcontext=system_u:system_r:domU_t_target tclass=hvm
Which otherwise leads to the following on resume after migrate (comparing
non-XSM to XSM):
ata2.00: configured for MWDMA2
usb 1-2: reset full-speed USB device number 2 using uhci_hcd
+PM: restore of devices complete after 3779.268 msecs
usb 1-2: USB disconnect, device number 2
-PM: restore of devices complete after 2342.528 msecs
usb 1-2: new full-speed USB device number 3 using uhci_hcd
usb 1-2: New USB device found, idVendor=0627, idProduct=0001
usb 1-2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb 1-2: Product: QEMU USB Tablet
usb 1-2: Manufacturer: QEMU 0.10.2
usb 1-2: SerialNumber: 1
input: QEMU 0.10.2 QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-2/1-2:1.0/input/input8
generic-usb 0003:0627:0001.0002: input,hidraw0: USB HID v0.01 Pointer [QEMU 0.10.2 QEMU USB Tablet] on usb-0000:00:01.2-2/input0
Restarting tasks ... done.
Setting capacity to 20480000
Setting capacity to 20480000
+uhci_hcd 0000:00:01.2: Unlink after no-IRQ? Controller is probably using the wrong IRQ.
And a glitch in the domU which is sufficient to disrupt the post migration
checks done by osstest.
Signed-off-by: Ian Campbell <ian.campbell@citrix.com>
Cc: Daniel De Graaf <dgdegra@tycho.nsa.gov>
---
tools/flask/policy/policy/modules/xen/xen.if | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/tools/flask/policy/policy/modules/xen/xen.if b/tools/flask/policy/policy/modules/xen/xen.if
index 32dd7b3..00d1bbb 100644
--- a/tools/flask/policy/policy/modules/xen/xen.if
+++ b/tools/flask/policy/policy/modules/xen/xen.if
@@ -150,7 +150,7 @@ define(`device_model', `
allow $1 $2_target:domain shutdown;
allow $1 $2_target:mmu { map_read map_write adjust physmap target_hack };
- allow $1 $2_target:hvm { getparam setparam trackdirtyvram hvmctl irqlevel pciroute cacheattr send_irq };
+ allow $1 $2_target:hvm { getparam setparam trackdirtyvram hvmctl irqlevel pciroute pcilevel cacheattr send_irq };
')
# make_device_model(priv, dm_dom, hvm_dom)
--
2.6.1
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel
^ permalink raw reply related [flat|nested] 8+ messages in thread
* Re: stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
2015-12-14 10:14 ` Ian Campbell
@ 2015-12-14 11:11 ` George Dunlap
2015-12-14 11:30 ` Ian Campbell
2015-12-14 11:55 ` Ian Campbell
1 sibling, 1 reply; 8+ messages in thread
From: George Dunlap @ 2015-12-14 11:11 UTC (permalink / raw)
To: Ian Campbell; +Cc: Wei Liu, Daniel De Graaf, Ian Jackson, xen-devel
On Mon, Dec 14, 2015 at 10:14 AM, Ian Campbell <ian.campbell@citrix.com> wrote:
> On Fri, 2015-12-11 at 15:16 +0000, Ian Campbell wrote:
>>
>> I have a new flight going on (65755) with flask=permissive instead of
>> flask=enforcing (assuming I didn't botch the osstest modifications to
>> support that setting via a runvar).
>
> I did botch the mods, but luckily permissive is the default, so I got what
> I wanted ;-)
>
>> If that test passes, prints the AVC message but not the missing IRQ message
>> then I think that would be our smoking gun.
>
> http://logs.test-lab.xenproject.org/osstest/logs/65758/
>
> From serial-merlot1.log:
>
> Dec 11 18:01:57.001037 (XEN) Flask: 64 avtab hash slots, 236 rules.
> Dec 11 18:01:57.009023 (XEN) Flask: 64 avtab hash slots, 236 rules.
> Dec 11 18:01:57.017004 (XEN) Flask: 3 users, 3 roles, 36 types, 2 bools
> Dec 11 18:01:57.017038 (XEN) Flask: 12 classes, 236 rules
> Dec 11 18:01:57.025015 (XEN) Flask: Starting in permissive mode.
> [...]
> Dec 11 18:06:01.229194 (XEN) avc: denied { pcilevel } for domid=2 target=1 scontext=system_u:system_r:dm_dom_t tcontext=system_u:system_r:domU_t_target tclass=hvm
>
> http://logs.test-lab.xenproject.org/osstest/logs/65758/test-amd64-amd64-xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1---var-log-xen-qemu-dm-debianhvm.guest.osstest--incoming.log.10
So wait -- does flask not report denials when in enforcing mode?
I can see the point of not letting a rogue / misconfigured guest DoS
your logs, but it seems like some sort of rate-limiting would be a
better solution than just not printing anything.
-George
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
2015-12-14 11:11 ` George Dunlap
@ 2015-12-14 11:30 ` Ian Campbell
0 siblings, 0 replies; 8+ messages in thread
From: Ian Campbell @ 2015-12-14 11:30 UTC (permalink / raw)
To: George Dunlap; +Cc: Ian Jackson, Daniel De Graaf, Wei Liu, xen-devel
On Mon, 2015-12-14 at 11:11 +0000, George Dunlap wrote:
> On Mon, Dec 14, 2015 at 10:14 AM, Ian Campbell <ian.campbell@citrix.com>
> wrote:
> > On Fri, 2015-12-11 at 15:16 +0000, Ian Campbell wrote:
> > >
> > > I have a new flight going on (65755) with flask=permissive instead of
> > > flask=enforcing (assuming I didn't botch the osstest modifications to
> > > support that setting via a runvar).
> >
> > I did botch the mods, but luckily permissive is the default, so I got
> > what
> > I wanted ;-)
> >
> > > If that test passes, prints the AVC message but not the missing IRQ
> > > message
> > > then I think that would be our smoking gun.
> >
> > http://logs.test-lab.xenproject.org/osstest/logs/65758/
> >
> > From serial-merlot1.log:
> >
> > Dec 11 18:01:57.001037 (XEN) Flask: 64 avtab hash slots, 236 rules.
> > Dec 11 18:01:57.009023 (XEN) Flask: 64 avtab hash slots, 236 rules.
> > Dec 11 18:01:57.017004 (XEN) Flask: 3 users, 3 roles, 36 types, 2
> > bools
> > Dec 11 18:01:57.017038 (XEN) Flask: 12 classes, 236 rules
> > Dec 11 18:01:57.025015 (XEN) Flask: Starting in permissive mode.
> > [...]
> > Dec 11 18:06:01.229194 (XEN) avc: denied { pcilevel } for domid=2
> > target=1 scontext=system_u:system_r:dm_dom_t
> > tcontext=system_u:system_r:domU_t_target tclass=hvm
> >
> > http://logs.test-lab.xenproject.org/osstest/logs/65758/test-amd64-amd64
> > -xl-qemut-stubdom-debianhvm-amd64-xsm/merlot1---var-log-xen-qemu-dm-
> > debianhvm.guest.osstest--incoming.log.10
>
> So wait -- does flask not report denials when in enforcing mode?
It does, I'm not sure what made you think otherwise, earlier in the thread
I quoted such a denial and it was that which lead me down this path.
Ian.
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL])
2015-12-14 10:14 ` Ian Campbell
2015-12-14 11:11 ` George Dunlap
@ 2015-12-14 11:55 ` Ian Campbell
1 sibling, 0 replies; 8+ messages in thread
From: Ian Campbell @ 2015-12-14 11:55 UTC (permalink / raw)
To: Ian Jackson, Wei Liu, Daniel De Graaf; +Cc: xen-devel
On Mon, 2015-12-14 at 10:14 +0000, Ian Campbell wrote:
>
> I've running a test with the following patch. I'm reasonably hopeful.
and it did indeed pass:
http://logs.test-lab.xenproject.org/osstest/logs/66273/
I'll resubmit as a proper patch.
Ian.
>
> Ian.
>
> From 3f14c5afedc0df360952364b93c2f04de00f00c4 Mon Sep 17 00:00:00 2001
> From: Ian Campbell <ian.campbell@citrix.com>
> Date: Mon, 14 Dec 2015 08:22:41 +0000
> Subject: [PATCH] flask: Allow device model to raise PCI interrupts
> (pcilevel
> capability)
>
> Allows:
>
> (XEN) avc: denied { pcilevel } for domid=2 target=1
> scontext=system_u:system_r:dm_dom_t
> tcontext=system_u:system_r:domU_t_target tclass=hvm
>
> Which otherwise leads to the following on resume after migrate (comparing
> non-XSM to XSM):
>
> ata2.00: configured for MWDMA2
> usb 1-2: reset full-speed USB device number 2 using uhci_hcd
> +PM: restore of devices complete after 3779.268 msecs
> usb 1-2: USB disconnect, device number 2
> -PM: restore of devices complete after 2342.528 msecs
> usb 1-2: new full-speed USB device number 3 using uhci_hcd
> usb 1-2: New USB device found, idVendor=0627, idProduct=0001
> usb 1-2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
> usb 1-2: Product: QEMU USB Tablet
> usb 1-2: Manufacturer: QEMU 0.10.2
> usb 1-2: SerialNumber: 1
> input: QEMU 0.10.2 QEMU USB Tablet as
> /devices/pci0000:00/0000:00:01.2/usb1/1-2/1-2:1.0/input/input8
> generic-usb 0003:0627:0001.0002: input,hidraw0: USB HID v0.01 Pointer
> [QEMU 0.10.2 QEMU USB Tablet] on usb-0000:00:01.2-2/input0
> Restarting tasks ... done.
> Setting capacity to 20480000
> Setting capacity to 20480000
> +uhci_hcd 0000:00:01.2: Unlink after no-IRQ? Controller is probably
> using the wrong IRQ.
>
> And a glitch in the domU which is sufficient to disrupt the post
> migration
> checks done by osstest.
>
> Signed-off-by: Ian Campbell <ian.campbell@citrix.com>
> Cc: Daniel De Graaf <dgdegra@tycho.nsa.gov>
> ---
> tools/flask/policy/policy/modules/xen/xen.if | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/tools/flask/policy/policy/modules/xen/xen.if
> b/tools/flask/policy/policy/modules/xen/xen.if
> index 32dd7b3..00d1bbb 100644
> --- a/tools/flask/policy/policy/modules/xen/xen.if
> +++ b/tools/flask/policy/policy/modules/xen/xen.if
> @@ -150,7 +150,7 @@ define(`device_model', `
>
> allow $1 $2_target:domain shutdown;
> allow $1 $2_target:mmu { map_read map_write adjust physmap
> target_hack };
> - allow $1 $2_target:hvm { getparam setparam trackdirtyvram hvmctl
> irqlevel pciroute cacheattr send_irq };
> + allow $1 $2_target:hvm { getparam setparam trackdirtyvram hvmctl
> irqlevel pciroute pcilevel cacheattr send_irq };
> ')
>
> # make_device_model(priv, dm_dom, hvm_dom)
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2015-12-14 11:55 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <E1a77eF-00049f-Er@osstest.test-lab.xenproject.org>
2015-12-11 12:12 ` stubdom migration failure on merlot* XSM related (Was: [adhoc test] 65682: tolerable FAIL]) Ian Campbell
2015-12-11 14:05 ` Ian Campbell
2015-12-11 15:12 ` Ian Campbell
2015-12-11 15:16 ` Ian Campbell
2015-12-14 10:14 ` Ian Campbell
2015-12-14 11:11 ` George Dunlap
2015-12-14 11:30 ` Ian Campbell
2015-12-14 11:55 ` Ian Campbell
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.