diff --git a/wexpect/console_reader.py b/wexpect/console_reader.py index 3ac0398..a971b27 100644 --- a/wexpect/console_reader.py +++ b/wexpect/console_reader.py @@ -42,6 +42,7 @@ import logging import os import traceback import pkg_resources +import psutil from io import StringIO import ctypes @@ -54,6 +55,8 @@ import winerror import win32pipe import socket +from .wexpect_util import init_logger + # # System-wide constants # @@ -72,28 +75,8 @@ except: # pragma: no cover # console manipulation. # logger = logging.getLogger('wexpect') - -def init_logger(): - logger = logging.getLogger('wexpect') - os.environ['WEXPECT_LOGGER_LEVEL'] = 'DEBUG' - try: - logger_level = os.environ['WEXPECT_LOGGER_LEVEL'] - try: - logger_filename = os.environ['WEXPECT_LOGGER_FILENAME'] - except KeyError: - pid = os.getpid() - logger_filename = f'./.wlog/wexpect_{pid}' - logger.setLevel(logger_level) - logger_filename = f'{logger_filename}.log' - os.makedirs(os.path.dirname(logger_filename), exist_ok=True) - fh = logging.FileHandler(logger_filename, 'w', 'utf-8') - formatter = logging.Formatter('%(asctime)s - %(filename)s:%(lineno)d - %(levelname)s - %(message)s') - fh.setFormatter(formatter) - logger.addHandler(fh) - except KeyError: - logger.setLevel(logging.ERROR) -init_logger() +init_logger(logger) class ConsoleReaderBase: """Consol class (aka. client-side python class) for the child. @@ -101,7 +84,7 @@ class ConsoleReaderBase: This class initialize the console starts the child in it and reads the console periodically. """ - def __init__(self, path, parent_pid, cp=None, window_size_x=80, window_size_y=25, + def __init__(self, path, host_pid, cp=None, window_size_x=80, window_size_y=25, buffer_size_x=80, buffer_size_y=16000, **kwargs): """Initialize the console starts the child in it and reads the console periodically. @@ -121,7 +104,9 @@ class ConsoleReaderBase: self.consin = None self.consout = None self.local_echo = True - self.pid = os.getpid() + self.console_pid = os.getpid() + self.host_pid = host_pid + self.host_process = psutil.Process(host_pid) logger.info("ConsoleReader started") @@ -151,6 +136,7 @@ class ConsoleReaderBase: logger.error(traceback.format_exc()) time.sleep(.1) finally: + self.terminate_child() time.sleep(.1) self.send_to_host(self.readConsoleToCursor()) time.sleep(.1) @@ -161,26 +147,20 @@ class ConsoleReaderBase: paused = False while True: + if not self.isalive(self.host_process): + logger.info('Host process has been died.') + return + + if win32process.GetExitCodeProcess(self.__childProcess) != win32con.STILL_ACTIVE: + logger.info('Child finished.') + return + consinfo = self.consout.GetConsoleScreenBufferInfo() cursorPos = consinfo['CursorPosition'] self.send_to_host(self.readConsoleToCursor()) s = self.get_from_host() self.write(s) - if win32process.GetExitCodeProcess(self.__childProcess) != win32con.STILL_ACTIVE: - logger.info('Child finished.') - time.sleep(.1) - try: - win32process.TerminateProcess(self.__childProcess, 0) - except pywintypes.error as e: - """ 'Access denied' happens always? Perhaps if not running as admin (or UAC - enabled under Vista/7). Don't log. Child process will exit regardless when - calling sys.exit - """ - if e.args[0] != winerror.ERROR_ACCESS_DENIED: - logger.info(e) - return - if cursorPos.Y > maxconsoleY and not paused: logger.info('cursorPos %s' % cursorPos) self.suspendThread() @@ -192,7 +172,27 @@ class ConsoleReaderBase: paused = False time.sleep(.1) + + def terminate_child(self): + try: + win32process.TerminateProcess(self.__childProcess, 0) + except pywintypes.error as e: + """ 'Access denied' happens always? Perhaps if not running as admin (or UAC + enabled under Vista/7). Don't log. Child process will exit regardless when + calling sys.exit + """ + # if e.args[0] != winerror.ERROR_ACCESS_DENIED: + logger.info(e) + return + + def isalive(self, process): + """True if the child is still alive, false otherwise""" + try: + process.wait(timeout=0) + return False + except psutil.TimeoutExpired: + return True def write(self, s): """Writes input into the child consoles input buffer.""" @@ -439,6 +439,7 @@ class ConsoleReaderSocket(ConsoleReaderBase): def send_to_host(self, msg): # convert to bytes msg_bytes = str.encode(msg) + logger.debug(f'Sending msg: {msg_bytes}') self.connection.sendall(msg_bytes) def get_from_host(self): @@ -482,6 +483,7 @@ class ConsoleReaderPipe(ConsoleReaderBase): def send_to_host(self, msg): # convert to bytes msg_bytes = str.encode(msg) + logger.debug(f'Sending msg: {msg_bytes}') win32file.WriteFile(self.pipe, msg_bytes) def get_from_host(self): diff --git a/wexpect/spawn.py b/wexpect/spawn.py index 556a2de..f18b04b 100644 --- a/wexpect/spawn.py +++ b/wexpect/spawn.py @@ -73,23 +73,29 @@ import traceback import types import psutil import signal +import socket +import logging import pywintypes import win32process import win32con -import win32api import win32file import winerror import win32pipe -import socket from .wexpect_util import ExceptionPexpect from .wexpect_util import EOF from .wexpect_util import TIMEOUT from .wexpect_util import split_command_line +from .wexpect_util import init_logger + +logger = logging.getLogger('wexpect') + +init_logger(logger) -def run (command, timeout=-1, withexitstatus=False, events=None, extra_args=None, logfile=None, cwd=None, env=None): +def run (command, timeout=-1, withexitstatus=False, events=None, extra_args=None, logfile=None, + cwd=None, env=None, **kwargs): """ This function runs the given command; waits for it to finish; then @@ -152,9 +158,9 @@ def run (command, timeout=-1, withexitstatus=False, events=None, extra_args=None dictionary passed to a callback. """ if timeout == -1: - child = SpawnSocket(command, maxread=2000, logfile=logfile, cwd=cwd, env=env) + child = SpawnSocket(command, maxread=2000, logfile=logfile, cwd=cwd, env=env, **kwargs) else: - child = SpawnSocket(command, timeout=timeout, maxread=2000, logfile=logfile, cwd=cwd, env=env) + child = SpawnSocket(command, timeout=timeout, maxread=2000, logfile=logfile, cwd=cwd, env=env, **kwargs) if events is not None: patterns = list(events.keys()) responses = list(events.values()) @@ -198,7 +204,7 @@ def run (command, timeout=-1, withexitstatus=False, events=None, extra_args=None class SpawnBase: def __init__(self, command, args=[], timeout=30, maxread=60000, searchwindowsize=None, - logfile=None, cwd=None, env=None, codepage=None, echo=True, **kwargs): + logfile=None, cwd=None, env=None, codepage=None, echo=True, safe_exit=True, **kwargs): """This starts the given command in a child process. This does all the fork/exec type of stuff for a pty. This is called by __init__. If args is empty then command will be parsed (split on spaces) and args will be @@ -218,6 +224,7 @@ class SpawnBase: self.child_process = None self.child_pid = None + self.safe_exit = safe_exit self.searcher = None self.ignorecase = False self.before = None @@ -260,25 +267,19 @@ class SpawnBase: command_with_path = shutil.which(self.command) if command_with_path is None: - raise ExceptionPexpect ('The command was not found or was not executable: %s.' % self.command) + logger.warning('The command was not found or was not executable: %s.' % self.command) + raise ExceptionPexpect ('The command was not found or was not executable: %s.' % self.command) self.command = command_with_path self.args[0] = self.command self.name = '<' + ' '.join (self.args) + '>' - - if self.cwd is not None: - os.chdir(self.cwd) - - - if self.cwd is not None: - # Restore the original working dir - os.chdir(self.ocwd) self.terminated = False self.closed = False self.child_fd = self.startChild(self.args, self.env) self.get_child_process() + logger.info(f'Child pid: {self.child_pid} Console pid: {self.console_pid}') self.connect_to_child() def __del__(self): @@ -288,6 +289,8 @@ class SpawnBase: try: self.terminate() self.disconnect_from_child() + if self.safe_exit: + self.wait() except: traceback.print_exc() @@ -370,7 +373,10 @@ class SpawnBase: def kill(self, sig=signal.SIGTERM): """Sig == sigint for ctrl-c otherwise the child is terminated.""" - self.child_process.send_signal(sig) + try: + self.child_process.send_signal(sig) + except psutil._exceptions.NoSuchProcess as e: + logger.info('Child has already died. %s', e) def wait(self, child=True, console=True): if child: @@ -766,7 +772,7 @@ class SpawnPipe(SpawnBase): def connect_to_child(self): pipe_name = 'wexpect_{}'.format(self.console_pid) pipe_full_path = r'\\.\pipe\{}'.format(pipe_name) -# print('Trying to connect to pipe: {}'.format(pipe_full_path)) + logger.debug(f'Trying to connect to pipe: {pipe_full_path}') while True: try: self.pipe = win32file.CreateFile( @@ -778,14 +784,14 @@ class SpawnPipe(SpawnBase): 0, None ) -# print("pipe found!") + logger.debug('Pipe found') res = win32pipe.SetNamedPipeHandleState(self.pipe, win32pipe.PIPE_READMODE_MESSAGE, None, None) -# if res == 0: -# print(f"SetNamedPipeHandleState return code: {res}") + if res == 0: + logger.debug(f"SetNamedPipeHandleState return code: {res}") return except pywintypes.error as e: if e.args[0] == winerror.ERROR_FILE_NOT_FOUND: #2 -# print("no pipe, trying again in a bit later") + logger.debug("no pipe, trying again in a bit later") time.sleep(0.2) else: raise @@ -806,6 +812,7 @@ class SpawnPipe(SpawnBase): This is a wrapper around Wtty.read(). """ if self.closed: + logger.info('I/O operation on closed file in read_nonblocking().') raise ValueError ('I/O operation on closed file in read_nonblocking().') try: @@ -815,22 +822,27 @@ class SpawnPipe(SpawnBase): # the last output. # The flag_child_finished flag shows that this is the second trial, where we raise the EOF. if self.flag_child_finished: + logger.info("EOF('self.flag_child_finished')") raise EOF('self.flag_child_finished') if not self.isalive(): self.flag_child_finished = True + logger.info('self.isalive() == False: Child has been died, lets do a last read!') try: s = win32file.ReadFile(self.pipe, size)[1] + logger.debug(f's: {s}') return s.decode() except pywintypes.error as e: if e.args[0] == winerror.ERROR_BROKEN_PIPE: #109 self.flag_eof = True + logger.info("EOF('broken pipe, bye bye')") raise EOF('broken pipe, bye bye') elif e.args[0] == winerror.ERROR_NO_DATA: '''232 (0xE8) The pipe is being closed. ''' self.flag_eof = True + logger.info("EOF('The pipe is being closed.')") raise EOF('The pipe is being closed.') else: raise @@ -905,6 +917,8 @@ class SpawnPipe(SpawnBase): "wexpect.console_reader.logger.info('Console finished2.');" ) + logger.info(f'Console starter command:{commandLine}') + _, _, self.console_pid, __otid = win32process.CreateProcess(None, commandLine, None, None, False, win32process.CREATE_NEW_CONSOLE, None, None, si) @@ -933,6 +947,7 @@ class SpawnSocket(SpawnBase): def connect_to_child(self): self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) self.sock.connect((self.host, self.port)) + self.sock.settimeout(.2) def disconnect_from_child(self): if self.sock: @@ -951,6 +966,7 @@ class SpawnSocket(SpawnBase): This is a wrapper around Wtty.read(). """ if self.closed: + logger.info('I/O operation on closed file in read_nonblocking().') raise ValueError ('I/O operation on closed file in read_nonblocking().') try: @@ -960,14 +976,20 @@ class SpawnSocket(SpawnBase): # the last output. # The flag_child_finished flag shows that this is the second trial, where we raise the EOF. if self.flag_child_finished: + logger.info("EOF('self.flag_child_finished')") raise EOF('self.flag_child_finished') if not self.isalive(): self.flag_child_finished = True + logger.info('self.isalive() == False: Child has been died, lets do a last read!') + logger.debug(f'Reading socket...') s = self.sock.recv(size) + logger.debug(f's: {s}') except EOF: self.flag_eof = True raise + except socket.timeout: + return '' return s.decode() @@ -1012,6 +1034,8 @@ class SpawnSocket(SpawnBase): "wexpect.console_reader.logger.info('Console finished2.');" ) + logger.info(f'Console starter command:{commandLine}') + _, _, self.console_pid, __otid = win32process.CreateProcess(None, commandLine, None, None, False, win32process.CREATE_NEW_CONSOLE, None, None, si) diff --git a/wexpect/wexpect_util.py b/wexpect/wexpect_util.py index ee17e8c..ef532ac 100644 --- a/wexpect/wexpect_util.py +++ b/wexpect/wexpect_util.py @@ -40,6 +40,27 @@ Wexpect Copyright (c) 2019 Benedek Racz import re import traceback import sys +import os +import logging + +def init_logger(logger): + os.environ['WEXPECT_LOGGER_LEVEL'] = 'DEBUG' + try: + logger_level = os.environ['WEXPECT_LOGGER_LEVEL'] + try: + logger_filename = os.environ['WEXPECT_LOGGER_FILENAME'] + except KeyError: + pid = os.getpid() + logger_filename = f'./.wlog/wexpect_{pid}' + logger.setLevel(logger_level) + logger_filename = f'{logger_filename}.log' + os.makedirs(os.path.dirname(logger_filename), exist_ok=True) + fh = logging.FileHandler(logger_filename, 'w', 'utf-8') + formatter = logging.Formatter('%(asctime)s - %(filename)s:%(lineno)d - %(levelname)s - %(message)s') + fh.setFormatter(formatter) + logger.addHandler(fh) + except KeyError: + logger.setLevel(logging.ERROR) def split_command_line(command_line, escape_char = '^'): """This splits a command line into a list of arguments. It splits arguments