Added Bruce.
Joshua to see if it's reproducible on autobuilder.

Test build on opensuse423 started:
https://autobuilder.yocto.io/builders/nightly-ppc/builds/528

Test build succeeded, changing status to have priority re-assessed during triage.

think this failed again.

nightly 590 - ross/rocko d9f4b79ec76b4e798b381c9546a93b8219638ab0
https://autobuilder.yocto.io/builders/nightly-ppc/builds/537/steps/Running%20Sanity%20Tests/logs/stdio

IT: version 2.88 booting

[    6.008438] usb 1-1: new full-speed USB device number 2 using ohci-pci
[    6.259718] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:0d.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input2
[    6.300951] hid-generic 0003:0627:0001.0001: input: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:0d.0-1/input0
Starting udev
[    6.483591] udevd[102]: starting version 3.2.2
[    6.557724] udevd[103]: starting eudev-3.2.2
[    7.289049] EXT4-fs (vda): re-mounted. Opts: data=ordered
hwclock: can't open '/dev/misc/rtc': No such file or directory


INIT: Entering runlevel: 5


Configuring network interfaces... ip: RTNETLINK answers: File exists

hwclock: can't open '/dev/misc/rtc': No such file or directory

Starting syslogd/klogd: done

NOTE: core-image-minimal-1.0-r0 do_testimage: Check full boot log: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc/build/build/tmp/work/qemuppc-poky-linux/core-image-minimal/1.0-r0/testimage/qemu_boot_log.20171013141438
WARNING: core-image-minimal-1.0-r0 do_testimage: Qemu ended unexpectedly, dump data from host is in /tmp/oe-saved-tests/201710131439_qemu
NOTE: core-image-minimal-1.0-r0 do_testimage: Stopping logging thread
NOTE: core-image-minimal-1.0-r0 do_testimage: Stop event received
NOTE: core-image-minimal-1.0-r0 do_testimage: Tearing down logging thread
NOTE: core-image-minimal-1.0-r0 do_testimage: Sending SIGTERM to runqemu
ERROR: core-image-minimal-1.0-r0 do_testimage: testimage received SIGTERM, shutting down...
ERROR: core-image-minimal-1.0-r0 do_testimage: core-image-minimal - FAILED - tests were interrupted during execution
ERROR: core-image-minimal-1.0-r0 do_testimage: Function failed: do_testimage
ERROR: Logfile of failure stored in: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc/build/build/tmp/work/qemuppc-poky-linux/core-image-minimal/1.0-r0/temp/log.do_testimage.48002
NOTE: recipe core-image-minimal-1.0-r0: task do_testimage: Failed
ERROR: Task (/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc/build/meta/recipes-core/images/core-image-minimal.bb:do_testimage) failed with exit code '1'
NOTE: core-image-sato-sdk-1.0-r0 do_testimage:  ... OK (15549.088s)

ppc-lsb which should be the LTSI kernel (4.9)

nightly 590 - ross/rocko d9f4b79ec76b4e798b381c9546a93b8219638ab0

https://autobuilder.yocto.io/builders/nightly-ppc-lsb/builds/525/steps/Running%20Sanity%20Tests/logs/stdio


NOTE: recipe core-image-lsb-1.0-r0: task do_testimage: Succeeded
NOTE: core-image-lsb-sdk-1.0-r0 do_testimage: Target didn't reached login boot in 1500 seconds
NOTE: core-image-lsb-sdk-1.0-r0 do_testimage: Last 25 lines of text:
starting 8 nfsd kernel threads: [   27.773471] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
[   27.774542] NFSD: starting 90-second grace period (net c0ac4728)
done

starting mountd: done

Starting system log daemon...0

Starting kernel log daemon...0

Starting internet superserver: xinetd.

 * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon

Starting Telephony daemon

Starting random number generator daemon.

No makedumpfile found.

Starting Lighttpd Web Server: lighttpd.

Starting crond: OK

Starting tcf-agent: OK
NOTE: core-image-lsb-sdk-1.0-r0 do_testimage: Check full boot log: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/build/tmp/work/qemuppc-poky-linux/core-image-lsb-sdk/1.0-r0/testimage/qemu_boot_log.20171013143811
WARNING: core-image-lsb-sdk-1.0-r0 do_testimage: Qemu ended unexpectedly, dump data from host is in /tmp/oe-saved-tests/201710131503_qemu
NOTE: core-image-lsb-sdk-1.0-r0 do_testimage: Stopping logging thread
NOTE: core-image-lsb-sdk-1.0-r0 do_testimage: Stop event received
NOTE: core-image-lsb-sdk-1.0-r0 do_testimage: Tearing down logging thread
NOTE: core-image-lsb-sdk-1.0-r0 do_testimage: Sending SIGTERM to runqemu
ERROR: core-image-lsb-sdk-1.0-r0 do_testimage: testimage received SIGTERM, shutting down...
ERROR: core-image-lsb-sdk-1.0-r0 do_testimage: core-image-lsb-sdk - FAILED - tests were interrupted during execution
ERROR: core-image-lsb-sdk-1.0-r0 do_testimage: Function failed: do_testimage
ERROR: Logfile of failure stored in: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/build/tmp/work/qemuppc-poky-linux/core-image-lsb-sdk/1.0-r0/temp/log.do_testimage.49217
NOTE: recipe core-image-lsb-sdk-1.0-r0: task do_testimage: Failed
ERROR: Task (/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/meta/recipes-extended/images/core-image-lsb-sdk.bb:do_testimage) failed with exit code '1'
NOTE: Tasks Summary: Attempted 564 tasks of which 562 didn't need to be rerun and 1 failed.

now failed on x86

nightly 588 - master da05a01423a60a23cd1073eb0ad3776e5bf4f2a8
https://autobuilder.yocto.io/builders/nightly-x86-64/builds/538/steps/Running%20Sanity%20Tests/logs/stdio

[    0.000000] Memory: 239224K/261608K available (9365K kernel code, 1201K rwdata, 2872K rodata, 1440K init, 480K bss, 22384K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] ftrace: allocating 37136 entries in 146 pages
[    0.001000] Preemptible hierarchical RCU implementation.
[    0.001000] 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=1.
[    0.001000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[    0.001000] NR_IRQS:4352 nr_irqs:256 16
[    0.001000] Console: colour VGA+ 80x25
[    0.001000] console [tty1] enabled
[    0.001000] console [ttyS0] enabled
[    0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    0.001009] tsc: Detected 2599.996 MHz processor
[    0.001679] Calibrating delay loop (skipped) preset value.. 5199.99 BogoMIPS (lpj=2599996)
[    0.002004] pid_max: default: 32768 minimum: 301
[    0.003015] ACPI: Core revision 20170303
[    0.004853] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.005039] Security Framework initialized
[    0.006014] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
[    0.007005] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
[    0.008261] mce: CPU supports 10 MCE banks
[    0.009037] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.009730] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    0.026860] Freeing SMP alternatives memory: 36K
[    0.028450] smpboot: Max logical packages: 1
[    0.029669] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
NOTE: core-image-sato-sdk-1.0-r0 do_testimage: Check full boot log: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64/build/build/tmp/work/qemux86_64-poky-linux/core-image-sato-sdk/1.0-r0/testimage/qemu_boot_log.20171009100532
WARNING: core-image-sato-sdk-1.0-r0 do_testimage: Qemu ended unexpectedly, dump data from host is in /tmp/oe-saved-tests/201710091030_qemu
NOTE: core-image-sato-1.0-r0 do_testimage: Target didn't reached login boot in 1500 seconds
NOTE: core-image-sato-1.0-r0 do_testimage: Last 25 lines of text:
[    0.000000] Memory: 239224K/261608K available (9365K kernel code, 1201K rwdata, 2872K rodata, 1440K init, 480K bss, 22384K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] ftrace: allocating 37136 entries in 146 pages
[    0.001000] Preemptible hierarchical RCU implementation.
[    0.001000] 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=1.
[    0.001000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[    0.001000] NR_IRQS:4352 nr_irqs:256 16
[    0.001000] Console: colour VGA+ 80x25
[    0.001000] console [tty1] enabled
[    0.001000] console [ttyS0] enabled
[    0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    0.001004] tsc: Detected 2599.996 MHz processor
[    0.001454] Calibrating delay loop (skipped) preset value.. 5199.99 BogoMIPS (lpj=2599996)
[    0.002003] pid_max: default: 32768 minimum: 301
[    0.002443] ACPI: Core revision 20170303
[    0.003601] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.004027] Security Framework initialized
[    0.004460] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
[    0.005003] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
[    0.006151] mce: CPU supports 10 MCE banks
[    0.006615] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.007003] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    0.020769] Freeing SMP alternatives memory: 36K
[    0.021657] smpboot: Max logical packages: 1
[    0.022531] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
NOTE: core-image-sato-1.0-r0 do_testimage: Check full boot log: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64/build/build/tmp/work/qemux86_64-poky-linux/core-image-sato/1.0-r0/testimage/qemu_boot_log.20171009100532
WARNING: core-image-sato-1.0-r0 do_testimage: Qemu ended unexpectedly, dump data from host is in /tmp/oe-saved-tests/201710091030_qemu
NOTE: core-image-sato-sdk-1.0-r0 do_testimage: Stopping logging thread
NOTE: core-image-sato-sdk-1.0-r0 do_testimage: Stop event received
NOTE: core-image-sato-sdk-1.0-r0 do_testimage: Tearing down logging thread
NOTE: core-image-sato-sdk-1.0-r0 do_testimage: Sending SIGTERM to runqemu
NOTE: core-image-sato-1.0-r0 do_testimage: Stopping logging thread
NOTE: core-image-sato-1.0-r0 do_testimage: Stop event received
NOTE: core-image-sato-1.0-r0 do_testimage: Tearing down logging thread
NOTE: core-image-sato-1.0-r0 do_testimage: Sending SIGTERM to runqemu
ERROR: core-image-sato-sdk-1.0-r0 do_testimage: testimage received SIGTERM, shutting down...
ERROR: core-image-sato-sdk-1.0-r0 do_testimage: core-image-sato-sdk - FAILED - tests were interrupted during execution
ERROR: core-image-sato-sdk-1.0-r0 do_testimage: Function failed: do_testimage
ERROR: Logfile of failure stored in: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64/build/build/tmp/work/qemux86_64-poky-linux/core-image-sato-sdk/1.0-r0/temp/log.do_testimage.9385
NOTE: recipe core-image-sato-sdk-1.0-r0: task do_testimage: Failed
ERROR: Task (/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64/build/meta/recipes-sato/images/core-image-sato-sdk.bb:do_testimage) failed with exit code '1'
ERROR: core-image-sato-1.0-r0 do_testimage: testimage received SIGTERM, shutting down...
ERROR: core-image-sato-1.0-r0 do_testimage: core-image-sato - FAILED - tests were interrupted during execution
ERROR: core-image-sato-1.0-r0 do_testimage: Function failed: do_testimage
ERROR: Logfile of failure stored in: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64/build/build/tmp/work/qemux86_64-poky-linux/core-image-sato/1.0-r0/temp/log.do_testimage.9386
NOTE: recipe core-image-sato-1.0-r0: task do_testimage: Failed
ERROR: Task (/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64/build/meta/recipes-sato/images/core-image-sato.bb:do_testimage) failed with exit code '1'
NOTE: Tasks Summary: Attempted 565 tasks of which 562 didn't need to be rerun and 2 failed.

Comment 6 is the tumbleweed builder issue, the others look ppc related.

*** Bug 12306 has been marked as a duplicate of this bug. ***

I was asked to take a look at this and having been burnt frequently enough with test harnesses I think there is some data we need to collect before continuing. The code has two escape routes "while time.time() < endtime and not stopread:", yet the error msg is only for one of these (ie. the failure will always appear as a timeout issue in the logs). The log is also pretty sparse as far as timestamps so I will add some to validate that we are getting what we expect. Once we get these changes merged I think we will be in a better position to diagnose the issue.

*** Bug 12350 has been marked as a duplicate of this bug. ***

I've been putting info into https://wiki.yoctoproject.org/wiki/Qemuppc_Boot_Hangs

http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=2713f71a2611c13e801c7077e2803096ee23237d