Bug 5131 - Slow/hung boot failure for qemumips/qemuppc image test
Summary: Slow/hung boot failure for qemumips/qemuppc image test
Status: RESOLVED FIXED
Alias: None
Product: Runtime Testing
Classification: QA/Testing
Component: general (show other bugs)
Version: 1.5
Hardware: x86 Multiple
: Medium+ normal
Target Milestone: 1.5 M5
Assignee: Ross Burton
QA Contact:
URL:
Whiteboard:
Depends on:
Blocks:
 
Reported: 2013-09-06 00:22 UTC by Beth Flanagan
Modified: 2013-09-25 09:19 UTC (History)
6 users (show)

See Also:
OS type for building Yocto: ---
Type of Regression: ---
Verified:
Documentation change: No (bug/feature does not impact docs)


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Beth Flanagan 2013-09-06 00:22:48 UTC
http://autobuilder.yoctoproject.org:8011/builders/nightly-mips/builds/284/steps/Running%20Sanity%20Tests/logs/stdio

and

http://autobuilder.yoctoproject.org:8011/builders/nightly-ppc/builds/281/steps/Running%20Sanity%20Tests/logs/stdio

Both seem to fail out the same way

Log data follows:
| DEBUG: Executing python function do_testimage
| NOTE: Created listening socket for qemu serial console on: 127.0.0.1:52692
| NOTE: DISPLAY value: :1
| NOTE: rootfs file: /srv/home/pokybuild/yocto-autobuilder-new/yocto-slave/nightly-ppc/build/build/tmp/work/qemuppc-poky-linux/core-image-sato-sdk/1.0-r0/testimage/core-image-sato-sdk-qemuppc-testimage.ext3
| NOTE: Qemu log file: /srv/home/pokybuild/yocto-autobuilder-new/yocto-slave/nightly-ppc/build/build/tmp/work/qemuppc-poky-linux/core-image-sato-sdk/1.0-r0/testimage/qemu_boot_log.20130905191450
| NOTE: SSH log file: /srv/home/pokybuild/yocto-autobuilder-new/yocto-slave/nightly-ppc/build/build/tmp/work/qemuppc-poky-linux/core-image-sato-sdk/1.0-r0/testimage/ssh_target_log.20130905191450
| NOTE: runqemu started, pid is 12663
| NOTE: waiting at most 60 seconds for qemu pid
| NOTE: qemu started - qemu procces pid is 12722
| NOTE: IP found: 192.168.7.6
| NOTE: Waiting at most 1500 seconds for login banner
| NOTE: Connection from 127.0.0.1:56930
| NOTE: Target didn't reached login boot in 1500 seconds
| NOTE: Last 5 lines of text:
| usb 1-1: new full-speed USB device number 2 using ohci_hcd
| 
| INIT: version 2.88 booting
| 
| input: Wacom Penpartner as /devices/pci0000:00/0000:00:0f.0/usb1/1-1/1-1:1.0/input/input2
| NOTE: Check full boot log: /srv/home/pokybuild/yocto-autobuilder-new/yocto-slave/nightly-ppc/build/build/tmp/work/qemuppc-poky-linux/core-image-sato-sdk/1.0-r0/testimage/qemu_boot_log.20130905191450
| NOTE: Sending SIGTERM to runqemu
| DEBUG: Python function do_testimage finished
| ERROR: Function failed: Failed to start qemu. You should check the task log and the qemu boot log (qemu log is /srv/home/pokybuild/yocto-autobuilder-new/yocto-slave/nightly-ppc/build/build/tmp/work/qemuppc-poky-linux/core-image-sato-sdk/1.0-r0/testimage/qemu_boot_log.20130905191450)
Comment 1 Stefan Stanacar 2013-09-06 07:10:48 UTC
These are the same boot fails we've seen before and tried to solve by bumping the timeout from 500 to 1000 and then 1500 (on the AB). That seemed to help a bit, making them more rare. Also the problem isn't related to qemumips or ppc or the image (minimal, sato, sato-sdk). 

I've tried _many_ times to reproduce this on my local AB and I finally I got lucky. What I know so far:
 - it has nothing to do with machine type
 - it took me something like 3 targets running in parallel (so a high load on the machine) - but now I'm not so sure that load is so important
 - I think I got lucky and two of the targets ran the sanity tests at the same time (so that means 6 images booting in parallel)
 - the images themselves are fine, they boot just fine if I run the testimage task by hand

The thing that caught my attention when watching the AB log and waiting for output was this:
NOTE: recipe core-image-sato-sdk-1.0-r0: task do_testimage: Started
NOTE: recipe core-image-sato-1.0-r0: task do_testimage: Started
NOTE: recipe core-image-minimal-1.0-r0: task do_testimage: Started
NOTE: recipe core-image-sato-1.0-r0: task do_testimage: Succeeded

 - The task for sato succeeded before minimal? That's impossible, minimal only boots, sato runs a lot of tests. 
 - So I started looking at all possible logs (testimage task log, qemu boot log, ssh log) everything looked just as I expected, with the boot log being stuck somewhere similar as here (around INIT).
 - And then I did: vncviewer :1 (to connect to the vncserver RunSanity starts) and suddenly the boot log started to fill again I could see the progress bar for the splash moving again.
 - strange enough it seemed that other qemu windows (remember there were two targets running sanity tests, each with 3 images) that were running in parallel appeared just fine (they weren't frozen, I could see the sato desktops)
 - the gnome session in that vncserver was crashed ("Oh no! Something has gone wrong. A problem has occurred and the system can't revover. All extensions have been disabled as a precaution.") and I clicked the Log out button and the desktop reappeared. The qemu windows were overlapped over the message. Now I'm not sure if this was the moment when my image started booting again (I was tailing the log in the background) or if that happened right when I connected to the vncserver.

I have no idea were to go from here and what the problem might be:
 - is it something wrong with vncserver (I'm using tigervnc-server-1.2.80) 
 - something wrong with the gnome session? (I never had a problem with gnome on that machine on the primary server, I'm using it as a desktop too)
 - the vncserver log didn't revealed anything (sure there were a lot of messages from gnome-settings-daemon and some js errors there, but...)
 - or is it the way we start the images, something wrong with serial options? But if I can't reproduce this by hand (me running the task locally, no vncserver) I can't tell (we did had a similar bug a while ago but that was something I could trigger myself too).
 - why does the qemu windows/process appear to be hung/paused when ran from the AB? I can start on my desktop 10 tasks and they all boot just fine.

The timeout increase we used helped by hiding the problem (we've seen it less often). I believe that when an image got "paused" others images running in parallel finished the tests before the timeout and then the "paused" one starts working, just like here:
NOTE: recipe core-image-sato-1.0-r0: task do_testimage: Started
NOTE: recipe core-image-sato-sdk-1.0-r0: task do_testimage: Started
NOTE: recipe core-image-minimal-1.0-r0: task do_testimage: Started
NOTE: recipe core-image-sato-1.0-r0: task do_testimage: Succeeded
NOTE: recipe core-image-minimal-1.0-r0: task do_testimage: Succeeded
NOTE: recipe core-image-sato-sdk-1.0-r0: task do_testimage: Succeeded

Ideas? Help?
Comment 2 Saul Wold 2013-09-09 16:42:58 UTC
I think this is addressed by RP's change to select
Comment 3 Stefan Stanacar 2013-09-11 18:38:50 UTC
Just an update: 
I've managed to replicate this outside of AB, doing it all manually. The trick was to use a vncserver (just as the AB) not the local display and run something like 6 images in parallel and use the (a similar) command the AB is using:

echo > /dev/tcp/localhost/5901) 2> /dev/null;if [ $? -ne 0 ]; then echo "Starting a VNC server on :1"; vncserver :1; else echo "Will use a VNC server already running on :1"; fi;DISPLAY=:1 bitbake core-image-minimal core-image-sato core-image-sato-sdk -c testimage; 


vncserver blacklists unauthentificated connections from a host after a certain number, and that echo is counted as an unauthenticated connection, and those add up from each target. That's why when I connected with vncviewer the image resumed (see my earlier comment).

Michael increased the blacklist threshold for the vncserver, let's see if that helps.
Comment 4 Stefan Stanacar 2013-09-12 14:41:28 UTC
Okay so I was able to reproduce this without bitbake or AB, just by running runqemu on the vncserver (on local desktop I don't see this)

[stefans@thunderbird build]$ vncserver :1

New 'thunderbird:1 (stefans)' desktop is thunderbird:1

Starting applications specified in /home/stefans/.vnc/xstartup
Log file is /home/stefans/.vnc/thunderbird:1.log


[stefans@thunderbird build]$ netstat -an | grep 5901
tcp        0      0 0.0.0.0:5901            0.0.0.0:*               LISTEN   



[stefans@thunderbird ~]$ for i in {1..6}; do gnome-terminal -e "sh -c 'cd /home/stefans/yocto/poky; source ./oe-init-build-env; DISPLAY=:1 runqemu qemumips core-image-sato serial qemuparams=\"-snapshot\"'"; sleep 10; echo "Started $i"; done 
Started 1
Started 2
Started 3
Started 4
Started 5
Started 6

At this point at least one terminal shows the log getting stuck somewhere around
INIT: version 2.88 booting 

Some images reach login:, some not (at least 1 reaches). If I'm closing the terminal with the image which reached login other start to boot or if from another terminal I'm doing vncviewer :1 again they all start to boot.

Results are not always the same (I had to use more than 6, it seems to have something to do with since Xvnc was started, when I did an authentificated connection. etc.)
Log show absolutely nothing (only accepted authenticated session).
Comment 5 Paul Eggleton 2013-09-13 17:08:34 UTC
This is not reaching some kind of memory or other resource limit, is it? 

FWIW, I've not had any luck reproducing this. My system is somewhat different though; I'm using KDE and on a 32-bit system rather than 64-bit.
Comment 6 Stefan Stanacar 2013-09-13 17:37:51 UTC
I don't think that matters but I don't have 32 bit system to test with. The only thing probably that matters is the vncserver (i'm using tigervnc iirc). Oh, and after you've started you shouldn't login into it as I've seen that it takes much more tries and a longer time until I hit this. (consider it a fresh reboot of AB and the server just started on boot or it's started by the RunSanityTest).
Comment 7 Richard Purdie 2013-09-16 16:25:08 UTC
To add some extra data points, I was unable to reproduce this locally with sleep 2 and 12 instances. I did need to change sh -> bash since I have dash by default which doesn't have source. I tried with xvnc4 and tightvnc locally. I also downloaded tigervnc versions 1.2.0 and 1.3.0 and tried these and was also not able to reproduce the issue with those either. These are standalone and can be run from:

http://sourceforge.net/projects/tigervnc/files/tigervnc/1.2.0/tigervnc-Linux-x86_64-1.2.0.tar.gz/download

http://sourceforge.net/projects/tigervnc/files/tigervnc/1.3.0/tigervnc-Linux-x86_64-1.3.0.tar.gz/download

I did find I could crash tightvnc with 12 instances (segfault) but 11 was fine. Stefan was able to get a backtrace from a stuck session http://pastebin.com/raX88UMZ

Stefan's test case was not able to reduce with the two tarball vnc's mentioned above. It was noted that Fedora does have patches to SDL in the area of the segfault:

http://pkgs.fedoraproject.org/cgit/SDL.git/tree/SDL-1.2.10-GrabNotViewable.patch?h=f18

Fedora also patches tightvnc: http://pkgs.fedoraproject.org/cgit/tigervnc.git/tree/?h=f19 (http://koji.fedoraproject.org/koji/rpminfo?rpmID=4193974)
Comment 8 Michael Halstead 2013-09-16 21:38:45 UTC
ab04, ab06, and ab10 are now all running tigervnc version 1.3.0. On these buiders vncserver is now running with LD_LIBRARY_PATH pointing at a locally compiled SDL-1.2.15.

Should the Fedora patch you referenced be included or removed? It is currently included.
Comment 9 Richard Purdie 2013-09-17 08:44:56 UTC
Michael, we have seen further failures so I checked what was running. On AB06 in proc, I see:

lrwxrwxrwx.   1 pokybuild users 0 Sep 17 08:30 exe -> /usr/bin/Xvnc (deleted)

the Xvnc binary on disk matches the one I linked to which doesn't have the redhat patches.

On AB10 the vnc binary in memory matches the one on disk and it says its 1.3.0 but it doesn't match the one I linked to. Is that 1.3.0 with redhat's patches applied or not?
Comment 10 Stefan Stanacar 2013-09-17 13:43:11 UTC
So I've rebuilt on a Fedora 18 machine the src.rpm from http://kojipkgs.fedoraproject.org//packages/tigervnc/1.3.0/3.fc19/src/tigervnc-1.3.0-3.fc19.src.rpm

I did 2 builds, then installed the rpms generated, started vncserver :1 and manually started 3-4 runqemu qemumips - it hanged. The upstream binaries don't seem to hit this (http://sourceforge.net/projects/tigervnc/files/tigervnc/1.3.0/tigervnc-Linux-x86_64-1.3.0.tar.gz/download)


- first build was from the original spec file
- then I removed the patches applied by fedora - no change (so basically I had an upstream build).
- then I did two builds by hand (upstreams has two methods of building)


Building the TigerVNC Server on Modern Unix/Linux Systems
---------------------------------------------------------

Building the TigerVNC Server (Xvnc) is a bit trickier.  On newer systems
containing Xorg 7.4 or later (such as Fedora), Xvnc is typically built to use
the X11 shared libraries provided with the system.  The procedure for this is
system-specific, since it requires specifying such things as font directories,
but the general outline is as follows (this procedure assumes that the viewer
has already been built, per above.)
   If performing an out-of-tree build:
  > mkdir unix
  > cp -R {source_directory}/unix/xserver unix/

  > cp -R {xorg_source}/* unix/xserver/
    (NOTE: {xorg_source} is the directory containing the Xorg source for the
    machine on which you are building TigerVNC.  The most recent versions of
    Red Hat/CentOS/Fedora, for instance, provide an RPM called
    "xorg-x11-server-source", which installs the Xorg source under
    /usr/share/xorg-x11-server-source.)

  > cd unix/xserver/
  > patch -p1 < {source_directory}/unix/xserver{version}.patch
    (where {version} matches the X server version you are building, such as
    "17" for version 1.7.x.)
  > autoreconf -fiv

  > ./configure --with-pic --without-dtrace --disable-static --disable-dri \
      --disable-xinerama --disable-xvfb --disable-xnest --disable-xorg \
      --disable-dmx --disable-xwin --disable-xephyr --disable-kdrive \
      --disable-config-dbus --disable-config-hal --disable-config-udev \
      --disable-dri2 --enable-install-libxf86config --enable-glx \
      --with-default-font-path="catalogue:/etc/X11/fontpath.d,built-ins" \
      --with-fontdir=/usr/share/X11/fonts \
      --with-xkb-path=/usr/share/X11/xkb \
      --with-xkb-output=/var/lib/xkb \
      --with-xkb-bin-directory=/usr/bin \
      --with-serverconfig-path=/usr/lib[64]/xorg \
      --with-dri-driver-path=/usr/lib[64]/dri \
      {additional configure options}
    (NOTE: This is merely an example that works with Red Hat Enterprise/CentOS
    6 and recent Fedora releases.  You should customize it for your particular
    system.  In particular, it will be necessary to customize the font, XKB,
    and DRI directories.)

  > make TIGERVNC_SRCDIR={source_directory}


This is almost identical to what the spec file does.

Second version is:

Building the TigerVNC Server on Legacy Unix/Linux Systems
---------------------------------------------------------

Those using systems with older versions of Xorg must build a "legacy-friendly"
version of the TigerVNC Server.  This is accomplished by downloading and
building the more recent Xorg modules in a local directory and then building
Xvnc such that it links against the local build of these libraries, not the X11
libraries installed on the system.  The "build-xorg" script in the TigerVNC
source distribution (located under unix/) automates this process.

The following procedure will build both the TigerVNC Viewer and a
"legacy-friendly" version of the TigerVNC Server:

  cd {build_directory}
  sh {source_directory}/unix/build-xorg init
  sh {source_directory}/unix/build-xorg build [additional CMake flags]

build-xorg generates a version of Xvnc that has no external dependencies on the
X11 shared libraries or any other distribution-specific shared libraries.  This
version of Xvnc should be transportable across multiple O/S distributions.
build-xorg should work on Red Hat Enterprise 4, its contemporaries, and later
systems.  It probably will not work on older systems.  It has not been tested
on non-Linux systems (yet).


This is how I assume upstream builds the binaries - and I'm trying to get them to build just to see if the hang reproduces anymore. I assume not...
Comment 11 Michael Halstead 2013-09-17 15:28:52 UTC
(In reply to comment #9)
> Michael, we have seen further failures so I checked what was running. On
> AB06 in proc, I see:
> 
> lrwxrwxrwx.   1 pokybuild users 0 Sep 17 08:30 exe -> /usr/bin/Xvnc (deleted)
> 
> the Xvnc binary on disk matches the one I linked to which doesn't have the
> redhat patches.
> 
> On AB10 the vnc binary in memory matches the one on disk and it says its
> 1.3.0 but it doesn't match the one I linked to. Is that 1.3.0 with redhat's
> patches applied or not?

I made a mistake yesterday. I've gone back over ab04, ab06, and ab10 and carefully:

stopped the vnc servers
removed all packaged versions of tigervnc-server
installed the statically linked version from the link above
restarted the vnc servers with "-BlacklistThreshold 10 -BlacklistTimeout 1"
Comment 12 Richard Purdie 2013-09-17 19:26:29 UTC
I think we now have a better understanding of the problem. The problem is the qemu's can stave of input events. To work around this periodically people need to log into the vncserver session on each autobuilder and move the pointer around to ensure there is sufficient data in the pool. 

Short term the SWAT team should be able to cover this, longer term we can look at writing a module which connects to the VNC server and generates pointer data to keep the qemu's from locking up.
Comment 13 Richard Purdie 2013-09-17 19:30:54 UTC
Ok, seriously, it appears the screensaver timeout is causing problems. Fedora has the best integrated VNC server and runs a full desktop session in the VNC server, complete with the sceensaver. It would seem running the static binary also reconfigures the session environment which means the screensaver isn't present hence the issue is removed. The qemu's hang at the time the wacom device is initialized which is around when they do take a grab of the pointer.

One slightly bizarre behaviour noted is that if you have a hung qemu, and your screensaver kicks in on the desktop showing the terminals, when you clear that screensaver, the qemu also resumes, despite it being on a different desktop/session. To quote ross:

(19:48:03) ross: the cursor just happens to be over the window that freezes
(19:48:07) ross: the screensaver kicks in
(19:48:11) ross: does a full grab
(19:48:22) ross: qemu polls input, sees the pointer is "over" its window
(19:48:23) ross: tries to grab
(19:48:30) ross: and waits for the grab
(19:48:32) ross: and waits

So possible workarounds are:
a) disable the screensaver
b) stop running full sessions

however we should round out the issue and figure out why it hangs as it really shouldn't.
Comment 14 Stefan Stanacar 2013-09-18 08:28:34 UTC
Yup, it's the screensaver/lockscreen and where the cursor lands.
I did this:
 - Machine A - Fedora 18, my user logged in, Gnome3 shell session, no other windows open, no vnc running
             - lock the screen, and leave the mouse cursor somewhere I predicted the window manager will open a new window (usually it starts somewere in the right top corner)
 - On Machine B: 
         ssh user@machineA
         export DISPLAY=:0
         cd /home/stefans/yocto/poky
         source ./oe-init-build-env
         runqemu qemumips core-image-sato serial 
  - boot hangs: 
Freeing unused kernel memory: 248K (80852000 - 80890000)
INIT: version 2.88 booting
input: Wacom Penpartner as /devices/pci0000:00/0000:00:0a.2/usb1/1-1/1-1:1.0/input/input0

If I unlock the screen on Machine A, it resumes booting. Also if the cursor didn't land over the qemu window it boots normally even with the lockscreen.
Comment 15 Richard Purdie 2013-09-18 13:00:21 UTC
Michael: We now have a good handle on what the problem is. Can you:

a) Remove any of the other workarounds we've tried
b) Disable the lockscreen/screensaver on the vncserver desktops on ab04,6,10

The issue is that those ABs have the complete desktop environment on the X session complete with that lockscreen/screensaver and its this that causes us problems.

We're trying to look at ways of stopping qemu or more specifically sdl waiting on the screen grab but in the meantime we need to have successful builds on the autobuilder. Sorry for the runaround in trying to figure this out, its one rather crazy bug!

In case anyone wonders, when we tried the static tigervnc binaries, they worked as they broke the user session and there was no lockscreen/screensaver. When Michael installed them properly on the AB, he correctly configured them and has the full user session so the bug remained! :)
Comment 16 Michael Halstead 2013-09-18 18:01:20 UTC
I will attempt to disable the screen blank by adding

            exec -l $SHELL -c "xset s off"
            exec -l $SHELL -c "setterm -blank 0"

to the xstartup file.

I can also run "setterm -blank poke" every minute to keep the screen active in case any other systems are monitoring.

I'm unsure about methods of completely disabling everything that is causing the issue.
Comment 17 Ross Burton 2013-09-18 18:48:48 UTC
xset is going to be flaky as many desktops (at least GNOME) just turn off the legacy screensaver support.  To be fair, it's not fit for purpose.

Don't bother poking the X server - I've just sent patches that should stop the grabs happening.  Optimistically setting the state to REVIEW.
Comment 18 Michael Halstead 2013-09-18 19:33:41 UTC
Okay. Standard packaged versions of tigervnc are back in place. I've restarted all the sessions and "setterm -blank 0" is set. I've not bothered with xset or poking.
Comment 19 Ross Burton 2013-09-18 21:55:11 UTC
As of oe-core 9934141d5df9d334f7f7f76e1990234af8a25a63 my qemu patch is integrated.  I'm not optimistic enough to close this bug though!
Comment 20 Stefan Stanacar 2013-09-25 09:19:56 UTC
But I am optimistic :) Since the patch got merged I haven't seen any boot timeout fail on the AB so I'm just gonna go ahead and close it :).