2013-07-29 21:45:53 +00:00
# Copyright (C) 2013 Intel Corporation
#
# Released under the MIT license (see COPYING.MIT)
# This module provides a class for starting qemu images using runqemu.
# It's used by testimage.bbclass.
2013-06-28 08:27:56 +00:00
import subprocess
import os
import time
import signal
import re
2013-08-13 14:47:12 +00:00
import socket
import select
2015-07-27 13:04:00 +00:00
import errno
2015-08-20 20:01:25 +00:00
import threading
2015-09-01 07:36:29 +00:00
from oeqa . utils . dump import HostDumper
2015-07-22 14:20:48 +00:00
import logging
2015-07-27 13:03:58 +00:00
logger = logging . getLogger ( " BitBake.QemuRunner " )
2013-06-28 08:27:56 +00:00
class QemuRunner :
2015-09-01 07:36:29 +00:00
def __init__ ( self , machine , rootfs , display , tmpdir , deploy_dir_image , logfile , boottime , dump_dir , dump_host_cmds ) :
2013-06-28 08:27:56 +00:00
2013-11-26 09:18:22 +00:00
# Popen object for runqemu
self . runqemu = None
# pid of the qemu process that runqemu will start
2013-06-28 08:27:56 +00:00
self . qemupid = None
2013-11-26 09:18:22 +00:00
# target ip - from the command line
2013-06-28 08:27:56 +00:00
self . ip = None
2013-11-26 09:18:22 +00:00
# host ip - where qemu is running
self . server_ip = None
2013-06-28 08:27:56 +00:00
2013-11-26 09:18:22 +00:00
self . machine = machine
self . rootfs = rootfs
2013-06-28 08:27:56 +00:00
self . display = display
self . tmpdir = tmpdir
2013-09-12 11:04:52 +00:00
self . deploy_dir_image = deploy_dir_image
2013-06-28 08:27:56 +00:00
self . logfile = logfile
2013-07-10 11:33:32 +00:00
self . boottime = boottime
2015-08-11 13:41:04 +00:00
self . logged = False
2015-08-20 20:01:25 +00:00
self . thread = None
2013-11-26 09:18:22 +00:00
self . runqemutime = 60
2015-09-01 07:36:29 +00:00
self . host_dumper = HostDumper ( dump_host_cmds , dump_dir )
2013-08-13 14:47:12 +00:00
2013-08-22 11:47:21 +00:00
def create_socket ( self ) :
2013-08-13 14:47:12 +00:00
try :
2015-08-20 17:55:17 +00:00
sock = socket . socket ( socket . AF_INET , socket . SOCK_STREAM )
sock . setblocking ( 0 )
sock . bind ( ( " 127.0.0.1 " , 0 ) )
sock . listen ( 2 )
port = sock . getsockname ( ) [ 1 ]
logger . info ( " Created listening socket for qemu serial console on: 127.0.0.1: %s " % port )
return ( sock , port )
2013-08-13 14:47:12 +00:00
2015-08-20 17:55:17 +00:00
except socket . error :
sock . close ( )
raise
2013-08-13 14:47:12 +00:00
def log ( self , msg ) :
if self . logfile :
with open ( self . logfile , " a " ) as f :
f . write ( " %s " % msg )
2013-06-28 08:27:56 +00:00
2013-11-26 09:18:22 +00:00
def start ( self , qemuparams = None ) :
2013-06-28 08:27:56 +00:00
if self . display :
os . environ [ " DISPLAY " ] = self . display
else :
2015-07-27 13:03:58 +00:00
logger . error ( " To start qemu I need a X desktop, please set DISPLAY correctly (e.g. DISPLAY=:1) " )
2013-06-28 08:27:56 +00:00
return False
if not os . path . exists ( self . rootfs ) :
2015-07-27 13:03:58 +00:00
logger . error ( " Invalid rootfs %s " % self . rootfs )
2013-06-28 08:27:56 +00:00
return False
if not os . path . exists ( self . tmpdir ) :
2015-07-27 13:03:58 +00:00
logger . error ( " Invalid TMPDIR path %s " % self . tmpdir )
2013-06-28 08:27:56 +00:00
return False
else :
os . environ [ " OE_TMPDIR " ] = self . tmpdir
2013-09-12 11:04:52 +00:00
if not os . path . exists ( self . deploy_dir_image ) :
2015-07-27 13:03:58 +00:00
logger . error ( " Invalid DEPLOY_DIR_IMAGE path %s " % self . deploy_dir_image )
2013-09-12 11:04:52 +00:00
return False
else :
os . environ [ " DEPLOY_DIR_IMAGE " ] = self . deploy_dir_image
2013-06-28 08:27:56 +00:00
2015-08-20 17:55:17 +00:00
try :
2015-08-20 20:01:25 +00:00
threadsock , threadport = self . create_socket ( )
2015-08-20 17:55:17 +00:00
self . server_socket , self . serverport = self . create_socket ( )
except socket . error , msg :
logger . error ( " Failed to create listening socket: %s " % msg [ 1 ] )
2015-07-22 14:20:48 +00:00
return False
2013-09-18 16:48:46 +00:00
# Set this flag so that Qemu doesn't do any grabs as SDL grabs interact
# badly with screensavers.
os . environ [ " QEMU_DONT_GRAB " ] = " 1 "
2015-08-24 07:25:03 +00:00
self . qemuparams = ' bootparams= " console=tty1 console=ttyS0,115200n8 " qemuparams= " -serial tcp:127.0.0.1: {} " ' . format ( threadport )
2013-08-13 14:47:12 +00:00
if qemuparams :
self . qemuparams = self . qemuparams [ : - 1 ] + " " + qemuparams + " " + ' \" '
2015-08-09 07:07:05 +00:00
def getOutput ( o ) :
import fcntl
fl = fcntl . fcntl ( o , fcntl . F_GETFL )
fcntl . fcntl ( o , fcntl . F_SETFL , fl | os . O_NONBLOCK )
return os . read ( o . fileno ( ) , 1000000 )
2015-08-24 07:25:03 +00:00
launch_cmd = ' runqemu tcpserial= %s %s %s %s ' % ( self . serverport , self . machine , self . rootfs , self . qemuparams )
2015-07-27 13:03:59 +00:00
# FIXME: We pass in stdin=subprocess.PIPE here to work around stty
# blocking at the end of the runqemu script when using this within
# oe-selftest (this makes stty error out immediately). There ought
# to be a proper fix but this will suffice for now.
self . runqemu = subprocess . Popen ( launch_cmd , shell = True , stdout = subprocess . PIPE , stderr = subprocess . STDOUT , stdin = subprocess . PIPE , preexec_fn = os . setpgrp )
2015-08-09 07:07:05 +00:00
output = self . runqemu . stdout
2013-06-28 08:27:56 +00:00
2015-07-27 13:03:58 +00:00
logger . info ( " runqemu started, pid is %s " % self . runqemu . pid )
logger . info ( " waiting at most %s seconds for qemu pid " % self . runqemutime )
2013-08-13 14:47:12 +00:00
endtime = time . time ( ) + self . runqemutime
2013-06-28 08:27:56 +00:00
while not self . is_alive ( ) and time . time ( ) < endtime :
2015-07-27 13:04:00 +00:00
if self . runqemu . poll ( ) :
if self . runqemu . returncode :
# No point waiting any longer
logger . info ( ' runqemu exited with code %d ' % self . runqemu . returncode )
2015-09-01 07:36:29 +00:00
self . _dump_host ( )
2015-07-27 13:04:00 +00:00
self . stop ( )
2015-08-09 07:07:05 +00:00
logger . info ( " Output from runqemu: \n %s " % getOutput ( output ) )
2015-07-27 13:04:00 +00:00
return False
2013-06-28 08:27:56 +00:00
time . sleep ( 1 )
if self . is_alive ( ) :
2015-07-27 13:03:58 +00:00
logger . info ( " qemu started - qemu procces pid is %s " % self . qemupid )
2013-11-26 09:18:22 +00:00
cmdline = ' '
with open ( ' /proc/ %s /cmdline ' % self . qemupid ) as p :
cmdline = p . read ( )
2015-08-06 18:44:22 +00:00
try :
ips = re . findall ( " ((?:[0-9] { 1,3} \ .) {3} [0-9] { 1,3}) " , cmdline . split ( " ip= " ) [ 1 ] )
if not ips or len ( ips ) != 3 :
raise ValueError
else :
self . ip = ips [ 0 ]
self . server_ip = ips [ 1 ]
except IndexError , ValueError :
2015-08-09 07:07:05 +00:00
logger . info ( " Couldn ' t get ip from qemu process arguments! Here is the qemu command line used: \n %s \n and output from runqemu: \n %s " % ( cmdline , getOutput ( output ) ) )
2015-09-01 07:36:29 +00:00
self . _dump_host ( )
2013-11-26 09:18:22 +00:00
self . stop ( )
2013-08-13 14:47:12 +00:00
return False
2015-08-27 09:04:10 +00:00
logger . info ( " qemu cmdline used: \n {} " . format ( cmdline ) )
2015-07-27 13:03:58 +00:00
logger . info ( " Target IP: %s " % self . ip )
logger . info ( " Server IP: %s " % self . server_ip )
2015-08-20 20:01:25 +00:00
logger . info ( " Starting logging thread " )
self . thread = LoggingThread ( self . log , threadsock , logger )
self . thread . start ( )
if not self . thread . connection_established . wait ( self . boottime ) :
logger . error ( " Didn ' t receive a console connection from qemu. "
" Here is the qemu command line used: \n %s \n and "
" output from runqemu: \n %s " % ( cmdline ,
getOutput ( output ) ) )
self . stop_thread ( )
return False
2015-07-27 13:03:58 +00:00
logger . info ( " Waiting at most %d seconds for login banner " % self . boottime )
2013-08-13 14:47:12 +00:00
endtime = time . time ( ) + self . boottime
socklist = [ self . server_socket ]
reachedlogin = False
stopread = False
2015-08-18 23:44:25 +00:00
qemusock = None
bootlog = ' '
2013-08-13 14:47:12 +00:00
while time . time ( ) < endtime and not stopread :
2013-09-06 14:14:34 +00:00
sread , swrite , serror = select . select ( socklist , [ ] , [ ] , 5 )
2013-08-13 14:47:12 +00:00
for sock in sread :
if sock is self . server_socket :
2015-08-18 23:44:25 +00:00
qemusock , addr = self . server_socket . accept ( )
qemusock . setblocking ( 0 )
socklist . append ( qemusock )
2013-08-13 14:47:12 +00:00
socklist . remove ( self . server_socket )
2015-07-27 13:03:58 +00:00
logger . info ( " Connection from %s : %s " % addr )
2013-08-13 14:47:12 +00:00
else :
data = sock . recv ( 1024 )
if data :
2015-08-18 23:44:25 +00:00
bootlog + = data
if re . search ( " .* login: " , bootlog ) :
self . server_socket = qemusock
2013-08-13 14:47:12 +00:00
stopread = True
reachedlogin = True
2015-07-27 13:03:58 +00:00
logger . info ( " Reached login banner " )
2013-08-13 14:47:12 +00:00
else :
socklist . remove ( sock )
sock . close ( )
stopread = True
if not reachedlogin :
2015-07-27 13:03:58 +00:00
logger . info ( " Target didn ' t reached login boot in %d seconds " % self . boottime )
2015-08-18 23:44:25 +00:00
lines = " \n " . join ( bootlog . splitlines ( ) [ - 25 : ] )
2015-07-27 13:28:24 +00:00
logger . info ( " Last 25 lines of text: \n %s " % lines )
2015-07-27 13:03:58 +00:00
logger . info ( " Check full boot log: %s " % self . logfile )
2015-09-01 07:36:29 +00:00
self . _dump_host ( )
2013-11-26 09:18:22 +00:00
self . stop ( )
2013-06-28 08:27:56 +00:00
return False
2015-08-11 13:41:04 +00:00
2015-09-02 13:44:42 +00:00
# If we are not able to login the tests can continue
try :
( status , output ) = self . run_serial ( " root \n " , raw = True )
if re . search ( " root@[a-zA-Z0-9 \ -]+:~# " , output ) :
self . logged = True
logger . info ( " Logged as root in serial console " )
else :
logger . info ( " Couldn ' t login into serial console "
" as root using blank password " )
except :
logger . info ( " Serial console failed while trying to login " )
2015-08-11 13:41:04 +00:00
2013-06-28 08:27:56 +00:00
else :
2015-07-27 13:03:58 +00:00
logger . info ( " Qemu pid didn ' t appeared in %s seconds " % self . runqemutime )
2015-09-01 07:36:29 +00:00
self . _dump_host ( )
2013-11-26 09:18:22 +00:00
self . stop ( )
2015-08-09 07:07:05 +00:00
logger . info ( " Output from runqemu: \n %s " % getOutput ( output ) )
2013-06-28 08:27:56 +00:00
return False
return self . is_alive ( )
2013-11-26 09:18:22 +00:00
def stop ( self ) :
2013-08-22 11:47:21 +00:00
2015-08-25 20:58:47 +00:00
self . stop_thread ( )
2013-08-22 11:47:21 +00:00
if self . runqemu :
2015-07-27 13:03:58 +00:00
logger . info ( " Sending SIGTERM to runqemu " )
2015-07-27 13:04:00 +00:00
try :
os . killpg ( self . runqemu . pid , signal . SIGTERM )
except OSError as e :
if e . errno != errno . ESRCH :
raise
2013-08-22 11:47:21 +00:00
endtime = time . time ( ) + self . runqemutime
while self . runqemu . poll ( ) is None and time . time ( ) < endtime :
time . sleep ( 1 )
if self . runqemu . poll ( ) is None :
2015-07-27 13:03:58 +00:00
logger . info ( " Sending SIGKILL to runqemu " )
2014-03-11 12:11:08 +00:00
os . killpg ( self . runqemu . pid , signal . SIGKILL )
2013-08-22 11:47:21 +00:00
self . runqemu = None
2015-07-27 21:15:57 +00:00
if hasattr ( self , ' server_socket ' ) and self . server_socket :
2013-08-13 14:47:12 +00:00
self . server_socket . close ( )
self . server_socket = None
2013-06-28 08:27:56 +00:00
self . qemupid = None
self . ip = None
2015-08-20 20:01:25 +00:00
def stop_thread ( self ) :
if self . thread and self . thread . is_alive ( ) :
self . thread . stop ( )
self . thread . join ( )
2013-06-28 08:27:56 +00:00
def restart ( self , qemuparams = None ) :
2015-07-27 13:03:58 +00:00
logger . info ( " Restarting qemu process " )
2013-08-22 11:47:21 +00:00
if self . runqemu . poll ( ) is None :
2013-11-26 09:18:22 +00:00
self . stop ( )
if self . start ( qemuparams ) :
2013-08-22 11:47:21 +00:00
return True
return False
2013-06-28 08:27:56 +00:00
def is_alive ( self ) :
qemu_child = self . find_child ( str ( self . runqemu . pid ) )
if qemu_child :
self . qemupid = qemu_child [ 0 ]
2013-08-13 14:47:12 +00:00
if os . path . exists ( " /proc/ " + str ( self . qemupid ) ) :
2013-06-28 08:27:56 +00:00
return True
return False
def find_child ( self , parent_pid ) :
#
# Walk the process tree from the process specified looking for a qemu-system. Return its [pid'cmd]
#
ps = subprocess . Popen ( [ ' ps ' , ' axww ' , ' -o ' , ' pid,ppid,command ' ] , stdout = subprocess . PIPE ) . communicate ( ) [ 0 ]
processes = ps . split ( ' \n ' )
nfields = len ( processes [ 0 ] . split ( ) ) - 1
pids = { }
commands = { }
for row in processes [ 1 : ] :
data = row . split ( None , nfields )
if len ( data ) != 3 :
continue
if data [ 1 ] not in pids :
pids [ data [ 1 ] ] = [ ]
pids [ data [ 1 ] ] . append ( data [ 0 ] )
commands [ data [ 0 ] ] = data [ 2 ]
if parent_pid not in pids :
return [ ]
parents = [ ]
newparents = pids [ parent_pid ]
while newparents :
next = [ ]
for p in newparents :
if p in pids :
for n in pids [ p ] :
if n not in parents and n not in next :
next . append ( n )
if p not in parents :
parents . append ( p )
newparents = next
#print "Children matching %s:" % str(parents)
for p in parents :
# Need to be careful here since runqemu-internal runs "ldd qemu-system-xxxx"
# Also, old versions of ldd (2.11) run "LD_XXXX qemu-system-xxxx"
basecmd = commands [ p ] . split ( ) [ 0 ]
basecmd = os . path . basename ( basecmd )
2013-08-13 14:47:12 +00:00
if " qemu-system " in basecmd and " -serial tcp " in commands [ p ] :
2013-06-28 08:27:56 +00:00
return [ int ( p ) , commands [ p ] ]
2015-08-11 13:24:44 +00:00
2015-08-12 07:02:21 +00:00
def run_serial ( self , command , raw = False ) :
2015-08-11 13:24:44 +00:00
# We assume target system have echo to get command status
2015-08-12 07:02:21 +00:00
if not raw :
command = " %s ; echo $? \n " % command
self . server_socket . sendall ( command )
2015-08-11 13:24:44 +00:00
data = ' '
status = 0
stopread = False
endtime = time . time ( ) + 5
while time . time ( ) < endtime and not stopread :
2015-08-12 08:37:28 +00:00
sread , _ , _ = select . select ( [ self . server_socket ] , [ ] , [ ] , 5 )
for sock in sread :
answer = sock . recv ( 1024 )
if answer :
data + = answer
# Search the prompt to stop
if re . search ( " [a-zA-Z0-9]+@[a-zA-Z0-9 \ -]+:~# " , data ) :
stopread = True
break
else :
2015-09-02 13:44:42 +00:00
raise Exception ( " No data on serial console socket " )
2015-08-11 13:24:44 +00:00
if data :
2015-08-12 07:02:21 +00:00
if raw :
2015-08-11 13:24:44 +00:00
status = 1
2015-08-12 07:02:21 +00:00
else :
# Remove first line (command line) and last line (prompt)
data = data [ data . find ( ' $? \r \n ' ) + 4 : data . rfind ( ' \r \n ' ) ]
index = data . rfind ( ' \r \n ' )
if index == - 1 :
status_cmd = data
data = " "
else :
status_cmd = data [ index + 2 : ]
data = data [ : index ]
if ( status_cmd == " 0 " ) :
status = 1
2015-08-11 13:24:44 +00:00
return ( status , str ( data ) )
2015-08-20 20:01:25 +00:00
2015-09-01 07:36:29 +00:00
def _dump_host ( self ) :
self . host_dumper . create_dir ( " qemu " )
logger . error ( " Qemu ended unexpectedly, dump data from host "
" is in %s " % self . host_dumper . dump_dir )
self . host_dumper . dump_host ( )
2015-08-20 20:01:25 +00:00
# This class is for reading data from a socket and passing it to logfunc
# to be processed. It's completely event driven and has a straightforward
# event loop. The mechanism for stopping the thread is a simple pipe which
# will wake up the poll and allow for tearing everything down.
class LoggingThread ( threading . Thread ) :
def __init__ ( self , logfunc , sock , logger ) :
self . connection_established = threading . Event ( )
self . serversock = sock
self . logfunc = logfunc
self . logger = logger
self . readsock = None
self . running = False
self . errorevents = select . POLLERR | select . POLLHUP | select . POLLNVAL
self . readevents = select . POLLIN | select . POLLPRI
threading . Thread . __init__ ( self , target = self . threadtarget )
def threadtarget ( self ) :
try :
self . eventloop ( )
finally :
self . teardown ( )
def run ( self ) :
self . logger . info ( " Starting logging thread " )
self . readpipe , self . writepipe = os . pipe ( )
threading . Thread . run ( self )
def stop ( self ) :
self . logger . info ( " Stopping logging thread " )
if self . running :
os . write ( self . writepipe , " stop " )
def teardown ( self ) :
2015-08-27 09:04:10 +00:00
self . logger . info ( " Tearing down logging thread " )
2015-08-20 20:01:25 +00:00
self . close_socket ( self . serversock )
if self . readsock is not None :
self . close_socket ( self . readsock )
self . close_ignore_error ( self . readpipe )
self . close_ignore_error ( self . writepipe )
self . running = False
def eventloop ( self ) :
poll = select . poll ( )
eventmask = self . errorevents | self . readevents
poll . register ( self . serversock . fileno ( ) )
poll . register ( self . readpipe , eventmask )
breakout = False
self . running = True
self . logger . info ( " Starting thread event loop " )
while not breakout :
events = poll . poll ( )
for event in events :
# An error occurred, bail out
if event [ 1 ] & self . errorevents :
raise Exception ( self . stringify_event ( event [ 1 ] ) )
# Event to stop the thread
if self . readpipe == event [ 0 ] :
self . logger . info ( " Stop event received " )
breakout = True
break
# A connection request was received
elif self . serversock . fileno ( ) == event [ 0 ] :
self . logger . info ( " Connection request received " )
self . readsock , _ = self . serversock . accept ( )
2015-08-25 20:58:47 +00:00
self . readsock . setblocking ( 0 )
2015-08-20 20:01:25 +00:00
poll . unregister ( self . serversock . fileno ( ) )
poll . register ( self . readsock . fileno ( ) )
self . logger . info ( " Setting connection established event " )
self . connection_established . set ( )
# Actual data to be logged
elif self . readsock . fileno ( ) == event [ 0 ] :
2015-08-27 09:04:10 +00:00
data = self . recv ( 1024 )
2015-08-20 20:01:25 +00:00
self . logfunc ( data )
2015-08-26 07:15:15 +00:00
# Since the socket is non-blocking make sure to honor EAGAIN
2015-08-27 09:04:10 +00:00
# and EWOULDBLOCK.
def recv ( self , count ) :
try :
data = self . readsock . recv ( count )
except socket . error as e :
if e . errno == errno . EAGAIN or e . errno == errno . EWOULDBLOCK :
return ' '
else :
raise
2015-08-26 07:15:15 +00:00
2015-08-27 09:04:10 +00:00
if data is None :
2015-08-26 07:15:15 +00:00
raise Exception ( " No data on read ready socket " )
2015-08-27 09:04:10 +00:00
elif not data :
2015-08-26 07:15:15 +00:00
# This actually means an orderly shutdown
# happened. But for this code it counts as an
# error since the connection shouldn't go away
# until qemu exits.
raise Exception ( " Console connection closed unexpectedly " )
return data
2015-08-20 20:01:25 +00:00
def stringify_event ( self , event ) :
val = ' '
if select . POLLERR == event :
val = ' POLLER '
elif select . POLLHUP == event :
val = ' POLLHUP '
elif select . POLLNVAL == event :
val = ' POLLNVAL '
return val
def close_socket ( self , sock ) :
sock . shutdown ( socket . SHUT_RDWR )
sock . close ( )
def close_ignore_error ( self , fd ) :
try :
os . close ( fd )
except OSError :
pass