qemurunner.py 35 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830
  1. #
  2. # Copyright (C) 2013 Intel Corporation
  3. #
  4. # SPDX-License-Identifier: MIT
  5. #
  6. # This module provides a class for starting qemu images using runqemu.
  7. # It's used by testimage.bbclass.
  8. import subprocess
  9. import os
  10. import sys
  11. import time
  12. import signal
  13. import re
  14. import socket
  15. import select
  16. import errno
  17. import string
  18. import threading
  19. import codecs
  20. import logging
  21. import tempfile
  22. from collections import defaultdict
  23. import importlib
  24. # Get Unicode non printable control chars
  25. control_range = list(range(0,32))+list(range(127,160))
  26. control_chars = [chr(x) for x in control_range
  27. if chr(x) not in string.printable]
  28. re_control_char = re.compile('[%s]' % re.escape("".join(control_chars)))
  29. class QemuRunner:
  30. def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, use_kvm, logger, use_slirp=False,
  31. serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None, tmpfsdir=None):
  32. # Popen object for runqemu
  33. self.runqemu = None
  34. self.runqemu_exited = False
  35. # pid of the qemu process that runqemu will start
  36. self.qemupid = None
  37. # target ip - from the command line or runqemu output
  38. self.ip = None
  39. # host ip - where qemu is running
  40. self.server_ip = None
  41. # target ip netmask
  42. self.netmask = None
  43. self.machine = machine
  44. self.rootfs = rootfs
  45. self.display = display
  46. self.tmpdir = tmpdir
  47. self.deploy_dir_image = deploy_dir_image
  48. self.logfile = logfile
  49. self.boottime = boottime
  50. self.logged = False
  51. self.thread = None
  52. self.use_kvm = use_kvm
  53. self.use_ovmf = use_ovmf
  54. self.use_slirp = use_slirp
  55. self.serial_ports = serial_ports
  56. self.msg = ''
  57. self.boot_patterns = boot_patterns
  58. self.tmpfsdir = tmpfsdir
  59. self.runqemutime = 300
  60. if not workdir:
  61. workdir = os.getcwd()
  62. self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid())
  63. self.monitorpipe = None
  64. self.logger = logger
  65. # Whether we're expecting an exit and should show related errors
  66. self.canexit = False
  67. # Enable testing other OS's
  68. # Set commands for target communication, and default to Linux ALWAYS
  69. # Other OS's or baremetal applications need to provide their
  70. # own implementation passing it through QemuRunner's constructor
  71. # or by passing them through TESTIMAGE_BOOT_PATTERNS[flag]
  72. # provided variables, where <flag> is one of the mentioned below.
  73. accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished']
  74. default_boot_patterns = defaultdict(str)
  75. # Default to the usual paterns used to communicate with the target
  76. default_boot_patterns['search_reached_prompt'] = ' login:'
  77. default_boot_patterns['send_login_user'] = 'root\n'
  78. default_boot_patterns['search_login_succeeded'] = r"root@[a-zA-Z0-9\-]+:~#"
  79. default_boot_patterns['search_cmd_finished'] = r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#"
  80. # Only override patterns that were set e.g. login user TESTIMAGE_BOOT_PATTERNS[send_login_user] = "webserver\n"
  81. for pattern in accepted_patterns:
  82. if not self.boot_patterns[pattern]:
  83. self.boot_patterns[pattern] = default_boot_patterns[pattern]
  84. def create_socket(self):
  85. try:
  86. sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
  87. sock.setblocking(0)
  88. sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
  89. sock.bind(("127.0.0.1",0))
  90. sock.listen(2)
  91. port = sock.getsockname()[1]
  92. self.logger.debug("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port)
  93. return (sock, port)
  94. except socket.error:
  95. sock.close()
  96. raise
  97. def decode_qemulog(self, todecode):
  98. # Sanitize the data received from qemu as it may contain control characters
  99. msg = todecode.decode("utf-8", errors='backslashreplace')
  100. msg = re_control_char.sub('', msg)
  101. return msg
  102. def log(self, msg, extension=""):
  103. if self.logfile:
  104. with codecs.open(self.logfile + extension, "ab") as f:
  105. f.write(msg)
  106. self.msg += self.decode_qemulog(msg)
  107. def getOutput(self, o):
  108. import fcntl
  109. fl = fcntl.fcntl(o, fcntl.F_GETFL)
  110. fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK)
  111. try:
  112. return os.read(o.fileno(), 1000000).decode("utf-8")
  113. except BlockingIOError:
  114. return ""
  115. def handleSIGCHLD(self, signum, frame):
  116. if self.runqemu and self.runqemu.poll():
  117. if self.runqemu.returncode:
  118. self.logger.error('runqemu exited with code %d' % self.runqemu.returncode)
  119. self.logger.error('Output from runqemu:\n%s' % self.getOutput(self.runqemu.stdout))
  120. self.stop()
  121. def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True):
  122. env = os.environ.copy()
  123. if self.display:
  124. env["DISPLAY"] = self.display
  125. # Set this flag so that Qemu doesn't do any grabs as SDL grabs
  126. # interact badly with screensavers.
  127. env["QEMU_DONT_GRAB"] = "1"
  128. if not os.path.exists(self.rootfs):
  129. self.logger.error("Invalid rootfs %s" % self.rootfs)
  130. return False
  131. if not os.path.exists(self.tmpdir):
  132. self.logger.error("Invalid TMPDIR path %s" % self.tmpdir)
  133. return False
  134. else:
  135. env["OE_TMPDIR"] = self.tmpdir
  136. if not os.path.exists(self.deploy_dir_image):
  137. self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image)
  138. return False
  139. else:
  140. env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image
  141. if self.tmpfsdir:
  142. env["RUNQEMU_TMPFS_DIR"] = self.tmpfsdir
  143. if not launch_cmd:
  144. launch_cmd = 'runqemu %s' % ('snapshot' if discard_writes else '')
  145. if self.use_kvm:
  146. self.logger.debug('Using kvm for runqemu')
  147. launch_cmd += ' kvm'
  148. else:
  149. self.logger.debug('Not using kvm for runqemu')
  150. if not self.display:
  151. launch_cmd += ' nographic'
  152. if self.use_slirp:
  153. launch_cmd += ' slirp'
  154. if self.use_ovmf:
  155. launch_cmd += ' ovmf'
  156. launch_cmd += ' %s %s' % (runqemuparams, self.machine)
  157. if self.rootfs.endswith('.vmdk'):
  158. self.logger.debug('Bypassing VMDK rootfs for runqemu')
  159. else:
  160. launch_cmd += ' %s' % (self.rootfs)
  161. return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env)
  162. def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None):
  163. # use logfile to determine the recipe-sysroot-native path and
  164. # then add in the site-packages path components and add that
  165. # to the python sys.path so the qmp module can be found.
  166. python_path = os.path.dirname(os.path.dirname(self.logfile))
  167. python_path += "/recipe-sysroot-native/usr/lib/qemu-python"
  168. sys.path.append(python_path)
  169. importlib.invalidate_caches()
  170. try:
  171. qmp = importlib.import_module("qmp")
  172. except Exception as e:
  173. self.logger.error("qemurunner: qmp module missing, please ensure it's installed in %s (%s)" % (python_path, str(e)))
  174. return False
  175. # Path relative to tmpdir used as cwd for qemu below to avoid unix socket path length issues
  176. qmp_file = "." + next(tempfile._get_candidate_names())
  177. qmp_param = ' -S -qmp unix:./%s,server,wait' % (qmp_file)
  178. qmp_port = self.tmpdir + "/" + qmp_file
  179. # Create a second socket connection for debugging use,
  180. # note this will NOT cause qemu to block waiting for the connection
  181. qmp_file2 = "." + next(tempfile._get_candidate_names())
  182. qmp_param += ' -qmp unix:./%s,server,nowait' % (qmp_file2)
  183. qmp_port2 = self.tmpdir + "/" + qmp_file2
  184. self.logger.info("QMP Available for connection at %s" % (qmp_port2))
  185. try:
  186. if self.serial_ports >= 2:
  187. self.threadsock, threadport = self.create_socket()
  188. self.server_socket, self.serverport = self.create_socket()
  189. except socket.error as msg:
  190. self.logger.error("Failed to create listening socket: %s" % msg[1])
  191. return False
  192. bootparams = ' printk.time=1'
  193. if extra_bootparams:
  194. bootparams = bootparams + ' ' + extra_bootparams
  195. # Ask QEMU to store the QEMU process PID in file, this way we don't have to parse running processes
  196. # and analyze descendents in order to determine it.
  197. if os.path.exists(self.qemu_pidfile):
  198. os.remove(self.qemu_pidfile)
  199. self.qemuparams = 'bootparams="{0}" qemuparams="-pidfile {1} {2}"'.format(bootparams, self.qemu_pidfile, qmp_param)
  200. if qemuparams:
  201. self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"'
  202. if self.serial_ports >= 2:
  203. launch_cmd += ' tcpserial=%s:%s %s' % (threadport, self.serverport, self.qemuparams)
  204. else:
  205. launch_cmd += ' tcpserial=%s %s' % (self.serverport, self.qemuparams)
  206. self.origchldhandler = signal.getsignal(signal.SIGCHLD)
  207. signal.signal(signal.SIGCHLD, self.handleSIGCHLD)
  208. self.logger.debug('launchcmd=%s' % (launch_cmd))
  209. # FIXME: We pass in stdin=subprocess.PIPE here to work around stty
  210. # blocking at the end of the runqemu script when using this within
  211. # oe-selftest (this makes stty error out immediately). There ought
  212. # to be a proper fix but this will suffice for now.
  213. self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
  214. output = self.runqemu.stdout
  215. launch_time = time.time()
  216. #
  217. # We need the preexec_fn above so that all runqemu processes can easily be killed
  218. # (by killing their process group). This presents a problem if this controlling
  219. # process itself is killed however since those processes don't notice the death
  220. # of the parent and merrily continue on.
  221. #
  222. # Rather than hack runqemu to deal with this, we add something here instead.
  223. # Basically we fork off another process which holds an open pipe to the parent
  224. # and also is setpgrp. If/when the pipe sees EOF from the parent dieing, it kills
  225. # the process group. This is like pctrl's PDEATHSIG but for a process group
  226. # rather than a single process.
  227. #
  228. r, w = os.pipe()
  229. self.monitorpid = os.fork()
  230. if self.monitorpid:
  231. os.close(r)
  232. self.monitorpipe = os.fdopen(w, "w")
  233. else:
  234. # child process
  235. os.setpgrp()
  236. os.close(w)
  237. r = os.fdopen(r)
  238. x = r.read()
  239. os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
  240. os._exit(0)
  241. self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
  242. self.logger.debug("waiting at most %d seconds for qemu pid (%s)" %
  243. (self.runqemutime, time.strftime("%D %H:%M:%S")))
  244. endtime = time.time() + self.runqemutime
  245. while not self.is_alive() and time.time() < endtime:
  246. if self.runqemu.poll():
  247. if self.runqemu_exited:
  248. self.logger.warning("runqemu during is_alive() test")
  249. return False
  250. if self.runqemu.returncode:
  251. # No point waiting any longer
  252. self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode)
  253. self.logger.warning("Output from runqemu:\n%s" % self.getOutput(output))
  254. self.stop()
  255. return False
  256. time.sleep(0.5)
  257. if self.runqemu_exited:
  258. self.logger.warning("runqemu after timeout")
  259. if self.runqemu.returncode:
  260. self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode)
  261. if not self.is_alive():
  262. self.logger.error("Qemu pid didn't appear in %d seconds (%s)" %
  263. (self.runqemutime, time.strftime("%D %H:%M:%S")))
  264. qemu_pid = None
  265. if os.path.isfile(self.qemu_pidfile):
  266. with open(self.qemu_pidfile, 'r') as f:
  267. qemu_pid = f.read().strip()
  268. self.logger.error("Status information, poll status: %s, pidfile exists: %s, pidfile contents %s, proc pid exists %s"
  269. % (self.runqemu.poll(), os.path.isfile(self.qemu_pidfile), str(qemu_pid), os.path.exists("/proc/" + str(qemu_pid))))
  270. # Dump all processes to help us to figure out what is going on...
  271. ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0]
  272. processes = ps.decode("utf-8")
  273. self.logger.debug("Running processes:\n%s" % processes)
  274. op = self.getOutput(output)
  275. self.stop()
  276. if op:
  277. self.logger.error("Output from runqemu:\n%s" % op)
  278. else:
  279. self.logger.error("No output from runqemu.\n")
  280. return False
  281. # Create the client socket for the QEMU Monitor Control Socket
  282. # This will allow us to read status from Qemu if the the process
  283. # is still alive
  284. self.logger.debug("QMP Initializing to %s" % (qmp_port))
  285. # chdir dance for path length issues with unix sockets
  286. origpath = os.getcwd()
  287. try:
  288. os.chdir(os.path.dirname(qmp_port))
  289. try:
  290. from qmp.legacy import QEMUMonitorProtocol
  291. self.qmp = QEMUMonitorProtocol(os.path.basename(qmp_port))
  292. except OSError as msg:
  293. self.logger.warning("Failed to initialize qemu monitor socket: %s File: %s" % (msg, msg.filename))
  294. return False
  295. self.logger.debug("QMP Connecting to %s" % (qmp_port))
  296. if not os.path.exists(qmp_port) and self.is_alive():
  297. self.logger.debug("QMP Port does not exist waiting for it to be created")
  298. endtime = time.time() + self.runqemutime
  299. while not os.path.exists(qmp_port) and self.is_alive() and time.time() < endtime:
  300. self.logger.info("QMP port does not exist yet!")
  301. time.sleep(0.5)
  302. if not os.path.exists(qmp_port) and self.is_alive():
  303. self.logger.warning("QMP Port still does not exist but QEMU is alive")
  304. return False
  305. try:
  306. # set timeout value for all QMP calls
  307. self.qmp.settimeout(self.runqemutime)
  308. self.qmp.connect()
  309. connect_time = time.time()
  310. self.logger.info("QMP connected to QEMU at %s and took %.2f seconds" %
  311. (time.strftime("%D %H:%M:%S"),
  312. time.time() - launch_time))
  313. except OSError as msg:
  314. self.logger.warning("Failed to connect qemu monitor socket: %s File: %s" % (msg, msg.filename))
  315. return False
  316. except qmp.legacy.QMPError as msg:
  317. self.logger.warning("Failed to communicate with qemu monitor: %s" % (msg))
  318. return False
  319. finally:
  320. os.chdir(origpath)
  321. # We worry that mmap'd libraries may cause page faults which hang the qemu VM for periods
  322. # causing failures. Before we "start" qemu, read through it's mapped files to try and
  323. # ensure we don't hit page faults later
  324. mapdir = "/proc/" + str(self.qemupid) + "/map_files/"
  325. try:
  326. for f in os.listdir(mapdir):
  327. try:
  328. linktarget = os.readlink(os.path.join(mapdir, f))
  329. if not linktarget.startswith("/") or linktarget.startswith("/dev") or "deleted" in linktarget:
  330. continue
  331. with open(linktarget, "rb") as readf:
  332. data = True
  333. while data:
  334. data = readf.read(4096)
  335. except FileNotFoundError:
  336. continue
  337. # Centos7 doesn't allow us to read /map_files/
  338. except PermissionError:
  339. pass
  340. # Release the qemu process to continue running
  341. self.run_monitor('cont')
  342. self.logger.info("QMP released QEMU at %s and took %.2f seconds from connect" %
  343. (time.strftime("%D %H:%M:%S"),
  344. time.time() - connect_time))
  345. # We are alive: qemu is running
  346. out = self.getOutput(output)
  347. netconf = False # network configuration is not required by default
  348. self.logger.debug("qemu started in %.2f seconds - qemu procces pid is %s (%s)" %
  349. (time.time() - (endtime - self.runqemutime),
  350. self.qemupid, time.strftime("%D %H:%M:%S")))
  351. cmdline = ''
  352. if get_ip:
  353. with open('/proc/%s/cmdline' % self.qemupid) as p:
  354. cmdline = p.read()
  355. # It is needed to sanitize the data received
  356. # because is possible to have control characters
  357. cmdline = re_control_char.sub(' ', cmdline)
  358. try:
  359. if self.use_slirp:
  360. tcp_ports = cmdline.split("hostfwd=tcp:")[1]
  361. ip, tcp_ports = tcp_ports.split(":")[:2]
  362. host_port = tcp_ports[:tcp_ports.find('-')]
  363. self.ip = "%s:%s" % (ip, host_port)
  364. else:
  365. ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1])
  366. self.ip = ips[0]
  367. self.server_ip = ips[1]
  368. self.logger.debug("qemu cmdline used:\n{}".format(cmdline))
  369. except (IndexError, ValueError):
  370. # Try to get network configuration from runqemu output
  371. match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+).*',
  372. out, re.MULTILINE | re.DOTALL)
  373. if match:
  374. self.ip, self.server_ip, self.netmask = match.groups()
  375. # network configuration is required as we couldn't get it
  376. # from the runqemu command line, so qemu doesn't run kernel
  377. # and guest networking is not configured
  378. netconf = True
  379. else:
  380. self.logger.error("Couldn't get ip from qemu command line and runqemu output! "
  381. "Here is the qemu command line used:\n%s\n"
  382. "and output from runqemu:\n%s" % (cmdline, out))
  383. self.stop()
  384. return False
  385. self.logger.debug("Target IP: %s" % self.ip)
  386. self.logger.debug("Server IP: %s" % self.server_ip)
  387. if self.serial_ports >= 2:
  388. self.thread = LoggingThread(self.log, self.threadsock, self.logger)
  389. self.thread.start()
  390. if not self.thread.connection_established.wait(self.boottime):
  391. self.logger.error("Didn't receive a console connection from qemu. "
  392. "Here is the qemu command line used:\n%s\nand "
  393. "output from runqemu:\n%s" % (cmdline, out))
  394. self.stop_thread()
  395. return False
  396. self.logger.debug("Output from runqemu:\n%s", out)
  397. self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
  398. (self.boottime, time.strftime("%D %H:%M:%S")))
  399. endtime = time.time() + self.boottime
  400. newlinetime = time.time() + 120
  401. filelist = [self.server_socket, self.runqemu.stdout]
  402. reachedlogin = False
  403. stopread = False
  404. sentnewlines = False
  405. qemusock = None
  406. bootlog = b''
  407. data = b''
  408. while time.time() < endtime and not stopread:
  409. try:
  410. sread, swrite, serror = select.select(filelist, [], [], 5)
  411. except InterruptedError:
  412. continue
  413. # With the 6.5 kernel, the serial port getty sometimes fails to appear, the data
  414. # appears lost in some buffer somewhere. Wait two minutes, then if we've not had a login,
  415. # try and provoke one. This is a workaround until we can work out the root cause.
  416. if time.time() > newlinetime and not sentnewlines:
  417. self.logger.warning('Probing the serial port to wake it up!')
  418. try:
  419. self.server_socket.sendall(bytes("\n\n", "utf-8"))
  420. except BrokenPipeError as e:
  421. self.logger.debug('Probe failed %s' % repr(e))
  422. sentnewlines = True
  423. for file in sread:
  424. if file is self.server_socket:
  425. qemusock, addr = self.server_socket.accept()
  426. qemusock.setblocking(False)
  427. filelist.append(qemusock)
  428. filelist.remove(self.server_socket)
  429. self.logger.debug("Connection from %s:%s" % addr)
  430. else:
  431. # try to avoid reading only a single character at a time
  432. time.sleep(0.1)
  433. if hasattr(file, 'read'):
  434. read = file.read(1024)
  435. elif hasattr(file, 'recv'):
  436. read = file.recv(1024)
  437. else:
  438. self.logger.error('Invalid file type: %s\n%s' % (file))
  439. read = b''
  440. self.logger.debug2('Partial boot log:\n%s' % (read.decode('utf-8', errors='backslashreplace')))
  441. data = data + read
  442. if data:
  443. bootlog += data
  444. self.log(data, extension = ".2")
  445. data = b''
  446. if bytes(self.boot_patterns['search_reached_prompt'], 'utf-8') in bootlog:
  447. self.server_socket.close()
  448. self.server_socket = qemusock
  449. stopread = True
  450. reachedlogin = True
  451. self.logger.debug("Reached login banner in %.2f seconds (%s)" %
  452. (time.time() - (endtime - self.boottime),
  453. time.strftime("%D %H:%M:%S")))
  454. else:
  455. # no need to check if reachedlogin unless we support multiple connections
  456. self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" %
  457. time.strftime("%D %H:%M:%S"))
  458. filelist.remove(file)
  459. file.close()
  460. stopread = True
  461. if not reachedlogin:
  462. if time.time() >= endtime:
  463. self.logger.warning("Target didn't reach login banner in %d seconds (%s)" %
  464. (self.boottime, time.strftime("%D %H:%M:%S")))
  465. tail = lambda l: "\n".join(l.splitlines()[-25:])
  466. bootlog = self.decode_qemulog(bootlog)
  467. self.logger.warning("Last 25 lines of login console (%d):\n%s" % (len(bootlog), tail(bootlog)))
  468. self.logger.warning("Last 25 lines of all logging (%d):\n%s" % (len(self.msg), tail(self.msg)))
  469. self.logger.warning("Check full boot log: %s" % self.logfile)
  470. self.stop()
  471. return False
  472. # If we are not able to login the tests can continue
  473. try:
  474. (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120)
  475. if re.search(self.boot_patterns['search_login_succeeded'], output):
  476. self.logged = True
  477. self.logger.debug("Logged in as %s in serial console" % self.boot_patterns['send_login_user'].replace("\n", ""))
  478. if netconf:
  479. # configure guest networking
  480. cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask)
  481. output = self.run_serial(cmd, raw=True)[1]
  482. if re.search(r"root@[a-zA-Z0-9\-]+:~#", output):
  483. self.logger.debug("configured ip address %s", self.ip)
  484. else:
  485. self.logger.debug("Couldn't configure guest networking")
  486. else:
  487. self.logger.warning("Couldn't login into serial console"
  488. " as %s using blank password" % self.boot_patterns['send_login_user'].replace("\n", ""))
  489. self.logger.warning("The output:\n%s" % output)
  490. except:
  491. self.logger.warning("Serial console failed while trying to login")
  492. return True
  493. def stop(self):
  494. if hasattr(self, "origchldhandler"):
  495. signal.signal(signal.SIGCHLD, self.origchldhandler)
  496. self.stop_thread()
  497. self.stop_qemu_system()
  498. if self.runqemu:
  499. if hasattr(self, "monitorpid"):
  500. os.kill(self.monitorpid, signal.SIGKILL)
  501. self.logger.debug("Sending SIGTERM to runqemu")
  502. try:
  503. os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
  504. except OSError as e:
  505. if e.errno != errno.ESRCH:
  506. raise
  507. try:
  508. outs, errs = self.runqemu.communicate(timeout=self.runqemutime)
  509. if outs:
  510. self.logger.info("Output from runqemu:\n%s", outs.decode("utf-8"))
  511. if errs:
  512. self.logger.info("Stderr from runqemu:\n%s", errs.decode("utf-8"))
  513. except subprocess.TimeoutExpired:
  514. self.logger.debug("Sending SIGKILL to runqemu")
  515. os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL)
  516. if not self.runqemu.stdout.closed:
  517. self.logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout))
  518. self.runqemu.stdin.close()
  519. self.runqemu.stdout.close()
  520. self.runqemu_exited = True
  521. if hasattr(self, 'qmp') and self.qmp:
  522. self.qmp.close()
  523. self.qmp = None
  524. if hasattr(self, 'server_socket') and self.server_socket:
  525. self.server_socket.close()
  526. self.server_socket = None
  527. if hasattr(self, 'threadsock') and self.threadsock:
  528. self.threadsock.close()
  529. self.threadsock = None
  530. self.qemupid = None
  531. self.ip = None
  532. if os.path.exists(self.qemu_pidfile):
  533. try:
  534. os.remove(self.qemu_pidfile)
  535. except FileNotFoundError as e:
  536. # We raced, ignore
  537. pass
  538. if self.monitorpipe:
  539. self.monitorpipe.close()
  540. def stop_qemu_system(self):
  541. if self.qemupid:
  542. try:
  543. # qemu-system behaves well and a SIGTERM is enough
  544. os.kill(self.qemupid, signal.SIGTERM)
  545. except ProcessLookupError as e:
  546. self.logger.warning('qemu-system ended unexpectedly')
  547. def stop_thread(self):
  548. if self.thread and self.thread.is_alive():
  549. self.thread.stop()
  550. self.thread.join()
  551. def allowexit(self):
  552. self.canexit = True
  553. if self.thread:
  554. self.thread.allowexit()
  555. def restart(self, qemuparams = None):
  556. self.logger.warning("Restarting qemu process")
  557. if self.runqemu.poll() is None:
  558. self.stop()
  559. if self.start(qemuparams):
  560. return True
  561. return False
  562. def is_alive(self):
  563. if not self.runqemu or self.runqemu.poll() is not None or self.runqemu_exited:
  564. return False
  565. if os.path.isfile(self.qemu_pidfile):
  566. # when handling pidfile, qemu creates the file, stat it, lock it and then write to it
  567. # so it's possible that the file has been created but the content is empty
  568. pidfile_timeout = time.time() + 3
  569. while time.time() < pidfile_timeout:
  570. with open(self.qemu_pidfile, 'r') as f:
  571. qemu_pid = f.read().strip()
  572. # file created but not yet written contents
  573. if not qemu_pid:
  574. time.sleep(0.5)
  575. continue
  576. else:
  577. if os.path.exists("/proc/" + qemu_pid):
  578. self.qemupid = int(qemu_pid)
  579. return True
  580. return False
  581. def run_monitor(self, command, args=None, timeout=60):
  582. if hasattr(self, 'qmp') and self.qmp:
  583. self.qmp.settimeout(timeout)
  584. if args is not None:
  585. return self.qmp.cmd(command, args)
  586. else:
  587. return self.qmp.cmd(command)
  588. def run_serial(self, command, raw=False, timeout=60):
  589. # Returns (status, output) where status is 1 on success and 0 on error
  590. # We assume target system have echo to get command status
  591. if not raw:
  592. command = "%s; echo $?\n" % command
  593. data = ''
  594. status = 0
  595. self.server_socket.sendall(command.encode('utf-8'))
  596. start = time.time()
  597. end = start + timeout
  598. while True:
  599. now = time.time()
  600. if now >= end:
  601. data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout
  602. break
  603. try:
  604. sread, _, _ = select.select([self.server_socket],[],[], end - now)
  605. except InterruptedError:
  606. continue
  607. if sread:
  608. # try to avoid reading single character at a time
  609. time.sleep(0.1)
  610. answer = self.server_socket.recv(1024)
  611. if answer:
  612. data += answer.decode('utf-8')
  613. # Search the prompt to stop
  614. if re.search(self.boot_patterns['search_cmd_finished'], data):
  615. break
  616. else:
  617. if self.canexit:
  618. return (1, "")
  619. raise Exception("No data on serial console socket, connection closed?")
  620. if data:
  621. if raw:
  622. status = 1
  623. else:
  624. # Remove first line (command line) and last line (prompt)
  625. data = data[data.find('$?\r\n')+4:data.rfind('\r\n')]
  626. index = data.rfind('\r\n')
  627. if index == -1:
  628. status_cmd = data
  629. data = ""
  630. else:
  631. status_cmd = data[index+2:]
  632. data = data[:index]
  633. if (status_cmd == "0"):
  634. status = 1
  635. return (status, str(data))
  636. # This class is for reading data from a socket and passing it to logfunc
  637. # to be processed. It's completely event driven and has a straightforward
  638. # event loop. The mechanism for stopping the thread is a simple pipe which
  639. # will wake up the poll and allow for tearing everything down.
  640. class LoggingThread(threading.Thread):
  641. def __init__(self, logfunc, sock, logger):
  642. self.connection_established = threading.Event()
  643. self.serversock = sock
  644. self.logfunc = logfunc
  645. self.logger = logger
  646. self.readsock = None
  647. self.running = False
  648. self.canexit = False
  649. self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL
  650. self.readevents = select.POLLIN | select.POLLPRI
  651. threading.Thread.__init__(self, target=self.threadtarget)
  652. def threadtarget(self):
  653. try:
  654. self.eventloop()
  655. finally:
  656. self.teardown()
  657. def run(self):
  658. self.logger.debug("Starting logging thread")
  659. self.readpipe, self.writepipe = os.pipe()
  660. threading.Thread.run(self)
  661. def stop(self):
  662. self.logger.debug("Stopping logging thread")
  663. if self.running:
  664. os.write(self.writepipe, bytes("stop", "utf-8"))
  665. def teardown(self):
  666. self.logger.debug("Tearing down logging thread")
  667. self.close_socket(self.serversock)
  668. if self.readsock is not None:
  669. self.close_socket(self.readsock)
  670. self.close_ignore_error(self.readpipe)
  671. self.close_ignore_error(self.writepipe)
  672. self.running = False
  673. def allowexit(self):
  674. self.canexit = True
  675. def eventloop(self):
  676. poll = select.poll()
  677. event_read_mask = self.errorevents | self.readevents
  678. poll.register(self.serversock.fileno())
  679. poll.register(self.readpipe, event_read_mask)
  680. breakout = False
  681. self.running = True
  682. self.logger.debug("Starting thread event loop")
  683. while not breakout:
  684. events = poll.poll()
  685. for event in events:
  686. # An error occurred, bail out
  687. if event[1] & self.errorevents:
  688. raise Exception(self.stringify_event(event[1]))
  689. # Event to stop the thread
  690. if self.readpipe == event[0]:
  691. self.logger.debug("Stop event received")
  692. breakout = True
  693. break
  694. # A connection request was received
  695. elif self.serversock.fileno() == event[0]:
  696. self.logger.debug("Connection request received")
  697. self.readsock, _ = self.serversock.accept()
  698. self.readsock.setblocking(0)
  699. poll.unregister(self.serversock.fileno())
  700. poll.register(self.readsock.fileno(), event_read_mask)
  701. self.logger.debug("Setting connection established event")
  702. self.connection_established.set()
  703. # Actual data to be logged
  704. elif self.readsock.fileno() == event[0]:
  705. data = self.recv(1024)
  706. self.logfunc(data)
  707. # Since the socket is non-blocking make sure to honor EAGAIN
  708. # and EWOULDBLOCK.
  709. def recv(self, count):
  710. try:
  711. data = self.readsock.recv(count)
  712. except socket.error as e:
  713. if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK:
  714. return b''
  715. else:
  716. raise
  717. if data is None:
  718. raise Exception("No data on read ready socket")
  719. elif not data:
  720. # This actually means an orderly shutdown
  721. # happened. But for this code it counts as an
  722. # error since the connection shouldn't go away
  723. # until qemu exits.
  724. if not self.canexit:
  725. raise Exception("Console connection closed unexpectedly")
  726. return b''
  727. return data
  728. def stringify_event(self, event):
  729. val = ''
  730. if select.POLLERR == event:
  731. val = 'POLLER'
  732. elif select.POLLHUP == event:
  733. val = 'POLLHUP'
  734. elif select.POLLNVAL == event:
  735. val = 'POLLNVAL'
  736. return val
  737. def close_socket(self, sock):
  738. sock.shutdown(socket.SHUT_RDWR)
  739. sock.close()
  740. def close_ignore_error(self, fd):
  741. try:
  742. os.close(fd)
  743. except OSError:
  744. pass