<LAVA_DISPATCHER>2014-02-26 02:28:27 PM INFO: [ACTION-B] deploy_linaro_image is started with {u'rootfs': u'http://releases.linaro.org/14.01/openembedded/aarch64/linaro-image-minimal-genericarmv8-20140127-635.rootfs.tar.gz', u'hwpack': u'http://releases.linaro.org/14.01/openembedded/aarch64/hwpack_linaro-vexpress64-rtsm_20140126-596_arm64_supported.tar.gz', u'bootloadertype': u'uefi'}
<LAVA_DISPATCHER>2014-02-26 02:28:27 PM INFO: Downloading image: http://releases.linaro.org/14.01/openembedded/aarch64/hwpack_linaro-vexpress64-rtsm_20140126-596_arm64_supported.tar.gz
<LAVA_DISPATCHER>2014-02-26 02:28:49 PM INFO: Downloading image: http://releases.linaro.org/14.01/openembedded/aarch64/linaro-image-minimal-genericarmv8-20140127-635.rootfs.tar.gz
<LAVA_DISPATCHER>2014-02-26 02:28:55 PM INFO: Generating fastmodel image with: flock /var/lock/lava-lmc.lck sudo linaro-media-create --dev fastmodel --output-directory /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq --image-size 2000M --hwpack /srv/lava/instances/production/var/www/lava-server/images/tmpiMG4Nl/hwpack_linaro-vexpress64-rtsm_20140126-596_arm64_supported.tar.gz --binary /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/linaro-image-minimal-genericarmv8-20140127-635.rootfs.tar.gz --hwpack-force-yes --bootloader uefi
Searching correct rootfs path
------------------------------------------------------------
Installing (linaro-hwpack-install) hwpack_linaro-vexpress64-rtsm_20140126-596_arm64_supported.tar.gz in target rootfs.
Unpacking hardware pack ...Done
Extracting all kernel packages ...
Extracting package linux-headers-3.13.0-1-linaro-vexpress64_3.13.0-1.1ubuntu1~ci+140125213145_arm64.deb
Extracting package linux-image-3.13.0-1-linaro-vexpress64_3.13.0-1.1ubuntu1~ci+140125213145_arm64.deb
Extracting package fvp-pre-boot_0.2.20131029+git14+ba3155b-0linaro1_all.deb
Extracting package uefi-image-vexpress_0.1+git40+20140124+e1e57aa-0linaro1_armhf.deb
Done
Cleaning up ...Done
------------------------------------------------------------
Sleeping for 1 second(s) to wait for the partition to settle
Disk /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img: cannot get geometry

sfdisk: ERROR: sector 0 does not have an msdos signature
 /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img: unrecognized partition table type
No partitions found
Warning: /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img is not a block device
Disk /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img: cannot get geometry

sfdisk: ERROR: sector 0 does not have an msdos signature
 /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img: unrecognized partition table type
No partitions found
Warning: partition 1 does not end at a cylinder boundary
BLKRRPART: Inappropriate ioctl for device
If you created or changed a DOS partition, /dev/foo7, say, then use dd(1)
to zero the first 512 bytes:  dd if=/dev/zero of=/dev/foo7 bs=512 count=1
(See fdisk(8).)
Sleeping for 1 second(s) to wait for the partition to settle
Disk /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img: cannot get geometry
		start: (c,h,s) expected (0,1,1) found (0,1,32)
		end: (c,h,s) expected (6,160,25) found (25,127,31)
		start: (c,h,s) expected (6,160,27) found (26,0,1)
		end: (c,h,s) expected (254,245,55) found (999,127,32)
partition ends on cylinder 999, beyond the end of the disk

Formating boot partition

mkfs.vfat 3.0.12 (29 Oct 2011)
Loop device does not match a floppy size, using default hd params

Formating root partition

mke2fs 1.42 (29-Nov-2011)
Discarding device blocks:   4096/498688             done                            
Filesystem label=rootfs
OS type: Linux
Block size=4096 (log=2)
Fragment size=4096 (log=2)
Stride=0 blocks, Stripe width=0 blocks
124672 inodes, 498688 blocks
24934 blocks (5.00%) reserved for the super user
First data block=0
Maximum filesystem blocks=511705088
16 block groups
32768 blocks per group, 32768 fragments per group
7792 inodes per group
Superblock backups stored on blocks: 
	32768, 98304, 163840, 229376, 294912

Allocating group tables:  0/16 1/16 2/16 3/16 4/16 5/16 6/16 7/16 8/16 9/1610/1611/1612/1613/1614/1615/16     done                            
Writing inode tables:  0/16 1/16 2/16 3/16 4/16 5/16 6/16 7/16 8/16 9/1610/1611/1612/1613/1614/1615/16     done                            
Creating journal (8192 blocks): done
Writing superblocks and filesystem accounting information:  0/16 1/16 2/16 3/16 4/16 5/16 6/16 7/16 8/16 9/1610/1611/1612/1613/1614/1615/16     done

Copying dtb files
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid dtb file, skipping it.
Could not find a valid initrd, skipping uInitrd.
Could not find a valid dtb file, skipping it.
Will use kernel=/tmp/tmpg2gpw0/rootfs/boot/Image-3.13.0-1-linaro-vexpress64, initrd=None, dtb=None.
`/tmp/tmpg2gpw0/rootfs//boot/img.axf' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/img.axf'
`/tmp/tmpg2gpw0/rootfs//boot/img.axf' -> `/tmp/tmpg2gpw0/boot-disc/img.axf'
`/tmp/tmpg2gpw0/rootfs//boot/img-foundation.axf' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/img-foundation.axf'
`/tmp/tmpg2gpw0/rootfs//boot/img-foundation.axf' -> `/tmp/tmpg2gpw0/boot-disc/img-foundation.axf'
`/tmp/tmpg2gpw0/rootfs/boot/Image-3.13.0-1-linaro-vexpress64' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/Image-3.13.0-1-linaro-vexpress64'
`/tmp/tmpg2gpw0/rootfs/boot/Image-3.13.0-1-linaro-vexpress64' -> `/tmp/tmpg2gpw0/boot-disc/Image-3.13.0-1-linaro-vexpress64'
`/tmp/tmpg2gpw0/boot-disc/fvp/bl1.bin' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/bl1.bin'
`/tmp/tmpg2gpw0/boot-disc/fvp/bl1.bin' -> `/tmp/tmpg2gpw0/boot-disc/bl1.bin'
`/tmp/tmpg2gpw0/boot-disc/fvp/bl2.bin' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/bl2.bin'
`/tmp/tmpg2gpw0/boot-disc/fvp/bl2.bin' -> `/tmp/tmpg2gpw0/boot-disc/bl2.bin'
`/tmp/tmpg2gpw0/boot-disc/fvp/bl31.bin' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/bl31.bin'
`/tmp/tmpg2gpw0/boot-disc/fvp/bl31.bin' -> `/tmp/tmpg2gpw0/boot-disc/bl31.bin'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-base-gicv2-psci.dtb' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/fvp-base-gicv2-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-base-gicv2-psci.dtb' -> `/tmp/tmpg2gpw0/boot-disc/fvp-base-gicv2-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-base-gicv2legacy-psci.dtb' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/fvp-base-gicv2legacy-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-base-gicv2legacy-psci.dtb' -> `/tmp/tmpg2gpw0/boot-disc/fvp-base-gicv2legacy-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-base-gicv3-psci.dtb' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/fvp-base-gicv3-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-base-gicv3-psci.dtb' -> `/tmp/tmpg2gpw0/boot-disc/fvp-base-gicv3-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-foundation-gicv2-psci.dtb' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/fvp-foundation-gicv2-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-foundation-gicv2-psci.dtb' -> `/tmp/tmpg2gpw0/boot-disc/fvp-foundation-gicv2-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-foundation-gicv3-psci.dtb' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/fvp-foundation-gicv3-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-foundation-gicv3-psci.dtb' -> `/tmp/tmpg2gpw0/boot-disc/fvp-foundation-gicv3-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-foundation-gicv2legacy-psci.dtb' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/fvp-foundation-gicv2legacy-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/fvp-foundation-gicv2legacy-psci.dtb' -> `/tmp/tmpg2gpw0/boot-disc/fvp-foundation-gicv2legacy-psci.dtb'
`/tmp/tmpg2gpw0/boot-disc/fvp/uefi_fvp-base.bin' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/uefi_fvp-base.bin'
`/tmp/tmpg2gpw0/boot-disc/fvp/uefi_fvp-base.bin' -> `/tmp/tmpg2gpw0/boot-disc/uefi_fvp-base.bin'
`/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/Image-3.13.0-1-linaro-vexpress64' -> `/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/Image'
`/tmp/tmpg2gpw0/boot-disc/Image-3.13.0-1-linaro-vexpress64' -> `/tmp/tmpg2gpw0/boot-disc/Image'

Populating rootfs partition
Be patient, this may take a few minutes


Creating /etc/flash-kernel.conf


Updating /etc/network/interfaces

Done creating Linaro image on /srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img
<LAVA_DISPATCHER>2014-02-26 02:29:18 PM INFO: [ACTION-E] deploy_linaro_image is finished successfully.
<LAVA_DISPATCHER>2014-02-26 02:29:18 PM INFO: [ACTION-B] boot_linaro_image is started with {u'options': [u'cache_state_modelled=1', u'bp.secureflashloader.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/bl1.bin', u'cluster0.cpu0.semihosting-cwd=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/', u'bp.flashloader0.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/fip.bin.test_scn28']}
<LAVA_DISPATCHER>2014-02-26 02:29:18 PM INFO: Boot the test image
<LAVA_DISPATCHER>2014-02-26 02:29:18 PM INFO: Booting the test image. Attempt: 1
<LAVA_DISPATCHER>2014-02-26 02:29:18 PM INFO: No INITRD found, [u'uInitrd', u'ramdisk.img', u'initrd.*']
<LAVA_DISPATCHER>2014-02-26 02:29:18 PM INFO: launching fastmodel with command u'sudo -u www-data ARMLMD_LICENSE_FILE="7010@euhpc-lic03.euhpc.arm.com:7010@euhpc-lic04.euhpc.arm.com:7010@euhpc-lic05.euhpc.arm.com:7010@euhpc-lic07.euhpc.arm.com" /fastmodels/future/FVP_Base_Cortex-A57x4-A53x4  -C bp.virtioblockdevice.image_path=/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img -C cluster0.cpu0.semihosting-cwd=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/ -C bp.secure_memory=0 -C bp.smsc_91c111.mac_address="02:90:00:03:00:09" -C pctl.startup=0.0.0.0 -C bp.pl011_uart0.untimed_fifos=1 -C bp.flashloader0.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/fip.bin.test_scn28 -C bp.secureflashloader.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/bl1.bin -C bp.smsc_91c111.enabled=true -C bp.hostbridge.interfaceName="armv8_06" -C cache_state_modelled=1'
terminal_0: Listening for serial connection on port 5004
<LAVA_DISPATCHER>2014-02-26 02:29:20 PM INFO: serial console port on: 5004
terminal_1: Listening for serial connection on port 5005
terminal_2: Listening for serial connection on port 5006
terminal_3: Listening for serial connection on port 5007
WARNING: bp.mmc: MMC backing store file mmc.dat could not be used
INFO: bp.mmc backing store: no image file connected
INFO: bp.flashloader0: FlashLoader: Loaded 2670 kB from file '/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/fip.bin.test_scn28'
INFO: bp.secureflashloader: FlashLoader: Loaded 21 kB from file '/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/bl1.bin'
Simulation is started
<LAVA_DISPATCHER>2014-02-26 02:29:20 PM INFO: simulator is started connecting to serial port
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
Booting tsh: 1: xterm: not found
rusted firmware boot loader stage 1
Built : 19:37:13, Feb 25 2014
Booting trusted firmware boot loader stage 2
BL2 Built : 19:37:30, Feb 25 2014
INFO: Loading BL31
INFO: FIP header looks OK.
INFO: Using FIP
INFO: Loading BL32
INFO: FIP header looks OK.
INFO: Using FIP
INFO: Loading BL33 (Normal world firmware)
INFO: FIP header looks OK.
INFO: Using FIP
Booting trusted firmware boot loader stage 3
BL31 Built : 19:37:32, Feb 25 2014
sh: 1: xterm: not found
TEST_SCN28 Built : 12:05:32, Feb 26 2014
Configure GIC 
Configure interrupt handling 
[0] main_cluster=0, other_cluster=1
[1] Cold boot status 0x1
[1] Cluster Powerdown requested: core=1 (clus_id=0, cpu_id=1)
[2] Cold boot status 0x2
[2] Cluster Powerdown requested: core=2 (clus_id=0, cpu_id=2)
[3] Cold boot status 0x3
[3] Cluster Powerdown requested: core=3 (clus_id=0, cpu_id=3)
[4] Cold boot status 0x4
[4] Cluster Powerdown requested: core=4 (clus_id=1, cpu_id=0)
[5] Cold boot status 0x5
[5] Cluster Powerdown requested: core=5 (clus_id=1, cpu_id=1)
[6] Cold boot status 0x6
[6] Cluster Powerdown requested: core=6 (clus_id=1, cpu_id=2)
[0] Waiting for the Other cluster to report Off
[7] Cold boot status 0x7
[7] Cluster Powerdown requested: core=7 (clus_id=1, cpu_id=3)
[0] MPIDR: 0x0 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0<LAVA_DISPATCHER>2014-02-26 02:49:20 PM INFO: Boot linaro image failed: Timeout exceeded in read_nonblocking().
<lava_dispatcher.utils.logging_spawn object at 0x4815d90>
version: 2.4 ($Revision: 516 $)
command: /usr/bin/telnet
args: ['/usr/bin/telnet', 'localhost', '5004']
searcher: searcher_re:
    0: re.compile("The default boot selection will start in")
buffer (last 100 chars): F_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0
before (last 100 chars): F_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0
after: <class 'pexpect.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 19869
child_fd: 6
closed: False
timeout: 1200
delimiter: <class 'pexpect.EOF'>
logfile: None
logfile_read: <lava_dispatcher.context.Flusher object at 0x3b49990>
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: None
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1
<LAVA_DISPATCHER>2014-02-26 02:49:20 PM INFO: Booting the test image. Attempt: 2
<LAVA_DISPATCHER>2014-02-26 02:49:20 PM WARNING: device already powered on, powering off first
<LAVA_DISPATCHER>2014-02-26 02:49:20 PM INFO: No INITRD found, [u'uInitrd', u'ramdisk.img', u'initrd.*']
<LAVA_DISPATCHER>2014-02-26 02:49:20 PM INFO: launching fastmodel with command u'sudo -u www-data ARMLMD_LICENSE_FILE="7010@euhpc-lic03.euhpc.arm.com:7010@euhpc-lic04.euhpc.arm.com:7010@euhpc-lic05.euhpc.arm.com:7010@euhpc-lic07.euhpc.arm.com" /fastmodels/future/FVP_Base_Cortex-A57x4-A53x4  -C bp.virtioblockdevice.image_path=/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img -C cluster0.cpu0.semihosting-cwd=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/ -C bp.secure_memory=0 -C bp.smsc_91c111.mac_address="02:90:00:03:00:09" -C pctl.startup=0.0.0.0 -C bp.pl011_uart0.untimed_fifos=1 -C bp.flashloader0.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/fip.bin.test_scn28 -C bp.secureflashloader.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/bl1.bin -C bp.smsc_91c111.enabled=true -C bp.hostbridge.interfaceName="armv8_06" -C cache_state_modelled=1'
terminal_0: Listening for serial connection on port 5004
<LAVA_DISPATCHER>2014-02-26 02:49:22 PM INFO: serial console port on: 5004
terminal_1: Listening for serial connection on port 5005
terminal_2: Listening for serial connection on port 5006
terminal_3: Listening for serial connection on port 5007
WARNING: bp.mmc: MMC backing store file mmc.dat could not be used
INFO: bp.mmc backing store: no image file connected
INFO: bp.flashloader0: FlashLoader: Loaded 2670 kB from file '/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/fip.bin.test_scn28'
INFO: bp.secureflashloader: FlashLoader: Loaded 21 kB from file '/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/bl1.bin'
Simulation is started
<LAVA_DISPATCHER>2014-02-26 02:49:22 PM INFO: simulator is started connecting to serial port
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
Booting trusted firmware boot loader stage 1
sh: 1: xterm: not found
Built : 19:37:13, Feb 25 2014
Booting trusted firmware boot loader stage 2
BL2 Built : 19:37:30, Feb 25 2014
INFO: Loading BL31
INFO: FIP header looks OK.
INFO: Using FIP
INFO: Loading BL32
INFO: FIP header looks OK.
INFO: Using FIP
INFO: Loading BL33 (Normal world firmware)
INFO: FIP header looks OK.
INFO: Using FIP
Booting trusted firmware boot loader stage 3
BL31 Built : 19:37:32, Feb 25 2014
sh: 1: xterm: not found
TEST_SCN28 Built : 12:05:32, Feb 26 2014
Configure GIC 
Configure interrupt handling 
[0] main_cluster=0, other_cluster=1
[1] Cold boot status 0x1
[1] Cluster Powerdown requested: core=1 (clus_id=0, cpu_id=1)
[2] Cold boot status 0x2
[2] Cluster Powerdown requested: core=2 (clus_id=0, cpu_id=2)
[3] Cold boot status 0x3
[3] Cluster Powerdown requested: core=3 (clus_id=0, cpu_id=3)
[4] Cold boot status 0x4
[4] Cluster Powerdown requested: core=4 (clus_id=1, cpu_id=0)
[5] Cold boot status 0x5
[5] Cluster Powerdown requested: core=5 (clus_id=1, cpu_id=1)
[6] Cold boot status 0x6
[6] Cluster Powerdown requested: core=6 (clus_id=1, cpu_id=2)
[0] Waiting for the Other cluster to report Off
[7] Cold boot status 0x7
[7] Cluster Powerdown requested: core=7 (clus_id=1, cpu_id=3)
[0] MPIDR: 0x0 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0<LAVA_DISPATCHER>2014-02-26 03:09:22 PM INFO: Boot linaro image failed: Timeout exceeded in read_nonblocking().
<lava_dispatcher.utils.logging_spawn object at 0x7f525c009e90>
version: 2.4 ($Revision: 516 $)
command: /usr/bin/telnet
args: ['/usr/bin/telnet', 'localhost', '5004']
searcher: searcher_re:
    0: re.compile("The default boot selection will start in")
buffer (last 100 chars): F_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0
before (last 100 chars): F_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0
after: <class 'pexpect.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 20738
child_fd: 7
closed: False
timeout: 1200
delimiter: <class 'pexpect.EOF'>
logfile: None
logfile_read: <lava_dispatcher.context.Flusher object at 0x3b49990>
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: None
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1
<LAVA_DISPATCHER>2014-02-26 03:09:22 PM INFO: Booting the test image. Attempt: 3
<LAVA_DISPATCHER>2014-02-26 03:09:22 PM WARNING: device already powered on, powering off first
<LAVA_DISPATCHER>2014-02-26 03:09:22 PM INFO: No INITRD found, [u'uInitrd', u'ramdisk.img', u'initrd.*']
<LAVA_DISPATCHER>2014-02-26 03:09:22 PM INFO: launching fastmodel with command u'sudo -u www-data ARMLMD_LICENSE_FILE="7010@euhpc-lic03.euhpc.arm.com:7010@euhpc-lic04.euhpc.arm.com:7010@euhpc-lic05.euhpc.arm.com:7010@euhpc-lic07.euhpc.arm.com" /fastmodels/future/FVP_Base_Cortex-A57x4-A53x4  -C bp.virtioblockdevice.image_path=/srv/lava/instances/production/var/www/lava-server/images/tmpPlIsMq/sd.img -C cluster0.cpu0.semihosting-cwd=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/ -C bp.secure_memory=0 -C bp.smsc_91c111.mac_address="02:90:00:03:00:09" -C pctl.startup=0.0.0.0 -C bp.pl011_uart0.untimed_fifos=1 -C bp.flashloader0.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/fip.bin.test_scn28 -C bp.secureflashloader.fname=/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/bl1.bin -C bp.smsc_91c111.enabled=true -C bp.hostbridge.interfaceName="armv8_06" -C cache_state_modelled=1'
terminal_0: Listening for serial connection on port 5004
<LAVA_DISPATCHER>2014-02-26 03:09:24 PM INFO: serial console port on: 5004
terminal_1: Listening for serial connection on port 5005
terminal_2: Listening for serial connection on port 5006
terminal_3: Listening for serial connection on port 5007
WARNING: bp.mmc: MMC backing store file mmc.dat could not be used
INFO: bp.mmc backing store: no image file connected
INFO: bp.flashloader0: FlashLoader: Loaded 2670 kB from file '/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/fip.bin.test_scn28'
INFO: bp.secureflashloader: FlashLoader: Loaded 21 kB from file '/test-binaries/manual-job-binaries-cortex4x4/without_tsp_and_tspd/release/bl1.bin'
Simulation is started
<LAVA_DISPATCHER>2014-02-26 03:09:24 PM INFO: simulator is started connecting to serial port
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
Booting trusted firmware boot loader stage 1
sh: 1: xterm: not found
Built : 19:37:13, Feb 25 2014
Booting trusted firmware boot loader stage 2
BL2 Built : 19:37:30, Feb 25 2014
INFO: Loading BL31
INFO: FIP header looks OK.
INFO: Using FIP
INFO: Loading BL32
INFO: FIP header looks OK.
INFO: Using FIP
INFO: Loading BL33 (Normal world firmware)
INFO: FIP header looks OK.
INFO: Using FIP
Booting trusted firmware boot loader stage 3
BL31 Built : 19:37:32, Feb 25 2014
TEST_SCN28 Built : 12:05:32, Feb 26 2014
Configure GIC 
sh: 1: xterm: not found
Configure interrupt handling 
[0] main_cluster=0, other_cluster=1
[1] Cold boot status 0x1
[1] Cluster Powerdown requested: core=1 (clus_id=0, cpu_id=1)
[2] Cold boot status 0x2
[2] Cluster Powerdown requested: core=2 (clus_id=0, cpu_id=2)
[3] Cold boot status 0x3
[3] Cluster Powerdown requested: core=3 (clus_id=0, cpu_id=3)
[4] Cold boot status 0x4
[4] Cluster Powerdown requested: core=4 (clus_id=1, cpu_id=0)
[5] Cold boot status 0x5
[5] Cluster Powerdown requested: core=5 (clus_id=1, cpu_id=1)
[6] Cold boot status 0x6
[6] Cluster Powerdown requested: core=6 (clus_id=1, cpu_id=2)
[0] Waiting for the Other cluster to report Off
[7] Cold boot status 0x7
[7] Cluster Powerdown requested: core=7 (clus_id=1, cpu_id=3)
[0] MPIDR: 0x0 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0<LAVA_DISPATCHER>2014-02-26 03:29:24 PM INFO: Boot linaro image failed: Timeout exceeded in read_nonblocking().
<lava_dispatcher.utils.logging_spawn object at 0x4815cd0>
version: 2.4 ($Revision: 516 $)
command: /usr/bin/telnet
args: ['/usr/bin/telnet', 'localhost', '5004']
searcher: searcher_re:
    0: re.compile("The default boot selection will start in")
buffer (last 100 chars): F_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0
before (last 100 chars): F_LEVEL_ON
[0] MPIDR: 0x100 = PSCI_AFF_LEVEL_OFF
[0] PASS
[0] END
[0] CPU Powerdown requested: 0
after: <class 'pexpect.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 21606
child_fd: 6
closed: False
timeout: 1200
delimiter: <class 'pexpect.EOF'>
logfile: None
logfile_read: <lava_dispatcher.context.Flusher object at 0x3b49990>
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: None
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1
<LAVA_DISPATCHER>2014-02-26 03:29:24 PM CRITICAL: Could not get the test image booted properly
<LAVA_DISPATCHER>2014-02-26 03:29:24 PM ERROR: boot_linaro_image failed
Traceback (most recent call last):
  File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013.12.5/lava_dispatcher/actions/boot_control.py", line 105, in run
    client.boot_linaro_image()
  File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013.12.5/lava_dispatcher/client/base.py", line 530, in boot_linaro_image
    raise CriticalError(msg)
CriticalError: Could not get the test image booted properly
<LAVA_DISPATCHER>2014-02-26 03:29:24 PM INFO: CriticalError
<LAVA_DISPATCHER>2014-02-26 03:29:24 PM WARNING: [ACTION-E] boot_linaro_image is finished with error (Failed to boot test image.).
ErrorMessage: Failed to boot test image.
Lava failed at action boot_linaro_image with error:Failed to boot test image.
Traceback (most recent call last):
  File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013.12.5/lava_dispatcher/job.py", line 270, in run
    action.run(**params)
  File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013.12.5/lava_dispatcher/actions/boot_control.py", line 109, in run
    raise CriticalError("Failed to boot test image.")
CriticalError: Failed to boot test image.
<LAVA_DISPATCHER>2014-02-26 03:29:25 PM INFO: Submitting the test result with parameters = {u'token': '<HIDDEN>', u'stream': u'/public/personal/pdcs-platforms/genfw/', u'server': u'http://pdcs-platforms@pdsw-lava.cambridge.arm.com/RPC2/'}
<LAVA_DISPATCHER>2014-02-26 03:29:25 PM INFO: Dashboard : http://pdsw-lava.cambridge.arm.com/dashboard/permalink/bundle/8a0ccf3c7588561fdc24b92456bd5989432e4a02/