shell.py 12.5 KB
Newer Older
1
# Copyright (C) 2014-2019 Linaro Limited
Neil Williams's avatar
Neil Williams committed
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
#
# Author: Neil Williams <neil.williams@linaro.org>
#
# This file is part of LAVA Dispatcher.
#
# LAVA Dispatcher is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; either version 2 of the License, or
# (at your option) any later version.
#
# LAVA Dispatcher is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along
# with this program; if not, see <http://www.gnu.org/licenses>.

21
import contextlib
22
import logging
23
import pexpect
24
import sre_constants
Neil Williams's avatar
Neil Williams committed
25
import time
26
from lava_dispatcher.action import Action
Neil Williams's avatar
Neil Williams committed
27
from lava_common.exceptions import InfrastructureError, JobError, LAVABug, TestError
28
from lava_common.timeout import Timeout
Rémi Duraffort's avatar
Rémi Duraffort committed
29
from lava_dispatcher.connection import Connection
30
from lava_common.constants import LINE_SEPARATOR
Rémi Duraffort's avatar
Rémi Duraffort committed
31
from lava_dispatcher.utils.strings import seconds_to_str
Neil Williams's avatar
Neil Williams committed
32
33


Rémi Duraffort's avatar
Rémi Duraffort committed
34
class ShellLogger:
35
36
37
38
39
40
    """
    Builds a YAML log message out of the incremental output of the pexpect.spawn
    using the logfile support built into pexpect.
    """

    def __init__(self, logger):
Neil Williams's avatar
Neil Williams committed
41
        self.line = ""
42
        self.logger = logger
43
        self.is_feedback = False
44
45
46

    def write(self, new_line):
        replacements = {
Neil Williams's avatar
Neil Williams committed
47
48
49
50
            "\n\n": "\n",  # double lines to single
            "\r": "",
            '"': '\\"',  # escape double quotes for YAML syntax
            "\x1b": "",  # remove escape control characters
51
52
53
        }
        for key, value in replacements.items():
            new_line = new_line.replace(key, value)
Rémi Duraffort's avatar
Rémi Duraffort committed
54
55
56
        lines = self.line + new_line

        # Print one full line at a time. A partial line is kept in memory.
Neil Williams's avatar
Neil Williams committed
57
58
59
        if "\n" in lines:
            last_ret = lines.rindex("\n")
            self.line = lines[last_ret + 1 :]
Rémi Duraffort's avatar
Rémi Duraffort committed
60
            lines = lines[:last_ret]
Neil Williams's avatar
Neil Williams committed
61
            for line in lines.split("\n"):
62
63
64
65
                if self.is_feedback:
                    self.logger.feedback(line)
                else:
                    self.logger.target(line)
66
        else:
Rémi Duraffort's avatar
Rémi Duraffort committed
67
            self.line = lines
68
        return
69

70
71
72
    def flush(self, force=False):
        if force and self.line:
            self.write("\n")
73
74


75
class ShellCommand(pexpect.spawn):
Neil Williams's avatar
Neil Williams committed
76
77
78
79
80
    """
    Run a command over a connection using pexpect instead of
    subprocess, i.e. not on the dispatcher itself.
    Takes a Timeout object (to support overrides and logging)

81
82
83
84
85
    https://pexpect.readthedocs.io/en/stable/api/pexpect.html#spawn-class

    Window size is managed to limit impact on performance.
    maxread is left at default to ensure the entire log is captured.

Neil Williams's avatar
Neil Williams committed
86
87
88
    A ShellCommand is a raw_connection for a ShellConnection instance.
    """

89
    def __init__(self, command, lava_timeout, logger=None, cwd=None, window=2000):
90
91
92
93
94
        if isinstance(window, str):
            # constants need to be stored as strings.
            try:
                window = int(window)
            except ValueError:
Neil Williams's avatar
Neil Williams committed
95
96
97
98
                raise LAVABug(
                    "ShellCommand was passed an invalid window size of %s bytes."
                    % window
                )
99
        if not lava_timeout or not isinstance(lava_timeout, Timeout):
Rémi Duraffort's avatar
Rémi Duraffort committed
100
            raise LAVABug("ShellCommand needs a timeout set by the calling Action")
Neil Williams's avatar
Neil Williams committed
101
        if not logger:
Rémi Duraffort's avatar
Rémi Duraffort committed
102
            raise LAVABug("ShellCommand needs a logger")
Rémi Duraffort's avatar
Rémi Duraffort committed
103
        pexpect.spawn.__init__(
Neil Williams's avatar
Neil Williams committed
104
105
            self,
            command,
Rémi Duraffort's avatar
Rémi Duraffort committed
106
107
108
            timeout=lava_timeout.duration,
            cwd=cwd,
            logfile=ShellLogger(logger),
Neil Williams's avatar
Neil Williams committed
109
            encoding="utf-8",
110
111
112
            # Data before searchwindowsize point is preserved, but not searched.
            searchwindowsize=None,  # pattern match the entire buffer
            maxread=window,  # limit the size of the buffer. 1 to turn off buffering
Neil Williams's avatar
Neil Williams committed
113
            codec_errors="replace",
Rémi Duraffort's avatar
Rémi Duraffort committed
114
        )
115
        self.name = "ShellCommand"
116
        self.logger = logger
117
        # set a default newline character, but allow actions to override as neccessary
Neil Williams's avatar
Neil Williams committed
118
        self.linesep = LINE_SEPARATOR
Neil Williams's avatar
Neil Williams committed
119
120
        self.lava_timeout = lava_timeout

121
    def sendline(self, s="", delay=0):
Neil Williams's avatar
Neil Williams committed
122
123
124
125
126
127
128
129
        """
        Extends pexpect.sendline so that it can support the delay argument which allows a delay
        between sending each character to get around slow serial problems (iPXE).
        pexpect sendline does exactly the same thing: calls send for the string then os.linesep.

        :param s: string to send
        :param delay: delay in milliseconds between sending each character
        """
Matt Hart's avatar
Matt Hart committed
130
        send_char = False
Neil Williams's avatar
Neil Williams committed
131
        if delay > 0:
132
            self.logger.debug("Sending with %s millisecond of delay", delay)
Matt Hart's avatar
Matt Hart committed
133
            send_char = True
134
        self.logger.input(s + self.linesep)
Neil Williams's avatar
Neil Williams committed
135
        self.send(s, delay, send_char)
Neil Williams's avatar
Neil Williams committed
136
        self.send(self.linesep, delay)
Neil Williams's avatar
Neil Williams committed
137
138

    def sendcontrol(self, char):
139
        self.logger.input(char)
Rémi Duraffort's avatar
Rémi Duraffort committed
140
        return super().sendcontrol(char)
Neil Williams's avatar
Neil Williams committed
141

142
    def send(self, string, delay=0, send_char=True):
Neil Williams's avatar
Neil Williams committed
143
144
145
146
        """
        Extends pexpect.send to support extra arguments, delay and send by character flags.
        """
        sent = 0
147
148
        if not string:
            return sent
Neil Williams's avatar
Neil Williams committed
149
150
151
        delay = float(delay) / 1000
        if send_char:
            for char in string:
Rémi Duraffort's avatar
Rémi Duraffort committed
152
                sent += super().send(char)
Neil Williams's avatar
Neil Williams committed
153
154
                time.sleep(delay)
        else:
Rémi Duraffort's avatar
Rémi Duraffort committed
155
            sent = super().send(string)
Neil Williams's avatar
Neil Williams committed
156
157
        return sent

158
    def expect(self, *args, **kw):
Neil Williams's avatar
Neil Williams committed
159
160
161
162
        """
        No point doing explicit logging here, the SignalDirector can help
        the TestShellAction make much more useful reports of what was matched
        """
Neil Williams's avatar
Neil Williams committed
163
        try:
Rémi Duraffort's avatar
Rémi Duraffort committed
164
            proc = super().expect(*args, **kw)
165
166
167
        except sre_constants.error as exc:
            msg = "Invalid regular expression '%s': %s" % (exc.pattern, exc.msg)
            raise TestError(msg)
Neil Williams's avatar
Neil Williams committed
168
        except pexpect.TIMEOUT:
169
            raise TestError("ShellCommand command timed out.")
170
171
        except ValueError as exc:
            raise TestError(exc)
Neil Williams's avatar
Neil Williams committed
172
        except pexpect.EOF:
173
            # FIXME: deliberately closing the connection (and starting a new one) needs to be supported.
174
            raise InfrastructureError("Connection closed")
Neil Williams's avatar
Neil Williams committed
175
176
177
178
179
180
        return proc

    def empty_buffer(self):
        """Make sure there is nothing in the pexpect buffer."""
        index = 0
        while index == 0:
Neil Williams's avatar
Neil Williams committed
181
            index = self.expect([".+", pexpect.EOF, pexpect.TIMEOUT], timeout=1)
Neil Williams's avatar
Neil Williams committed
182

183
184
185
186
    def flush(self):
        """ Will be called by pexpect itself when closing the connection """
        self.logfile.flush(force=True)

Neil Williams's avatar
Neil Williams committed
187

Neil Williams's avatar
Neil Williams committed
188
189
class ShellSession(Connection):

190
191
    name = "ShellSession"

192
193
    def __init__(self, job, shell_command):
        """
194
195
196
        A ShellSession monitors a pexpect connection.
        Optionally, a prompt can be forced after
        a percentage of the timeout.
197
        """
Rémi Duraffort's avatar
Rémi Duraffort committed
198
        super().__init__(job, shell_command)
199
        # FIXME: rename __prompt_str__ to indicate it can be a list or str
200
        self.__prompt_str__ = None
201
        self.spawn = shell_command
202
        self.__runner__ = None
Neil Williams's avatar
Neil Williams committed
203
        self.timeout = shell_command.lava_timeout
204
205
206
207
208
209
210
        self.__logger__ = None

    @property
    def logger(self):
        if not self.__logger__:
            self.__logger__ = logging.getLogger("dispatcher")
        return self.__logger__
211

Neil Williams's avatar
Neil Williams committed
212
    def disconnect(self, reason=""):
213
        self.logger.debug("Disconnecting %s", self.name)
Rémi Duraffort's avatar
Rémi Duraffort committed
214
        super().disconnect(reason)
215

216
    # FIXME: rename prompt_str to indicate it can be a list or str
217
218
219
220
221
222
    @property
    def prompt_str(self):
        return self.__prompt_str__

    @prompt_str.setter
    def prompt_str(self, string):
223
224
225
226
227
228
        """
        pexpect allows the prompt to be a single string or a list of strings
        this property simply replaces the previous value with the new one
        whether that is a string or a list of strings.
        To use + the instance of the existing prompt_str must be checked.
        """
229
        self.logger.debug("Setting prompt string to %r" % string)
230
        self.__prompt_str__ = string
Neil Williams's avatar
Neil Williams committed
231

232
233
234
235
236
    @contextlib.contextmanager
    def test_connection(self):
        """
        Yields the actual connection which can be used to interact inside this shell.
        """
237
        yield self.raw_connection
238

239
240
241
242
243
244
245
246
247
248
249
250
251
252
    def force_prompt_wait(self, remaining=None):
        """
        One of the challenges we face is that kernel log messages can appear
        half way through a shell prompt.  So, if things are taking a while,
        we send a newline along to maybe provoke a new prompt.  We wait for
        half the timeout period and then wait for one tenth of the timeout
        6 times (so we wait for 1.1 times the timeout period overall).
        :return: the index into the connection.prompt_str list
        """
        prompt_wait_count = 0
        if not remaining:
            return self.wait()
        # connection_prompt_limit
        partial_timeout = remaining / 2.0
253
        self.logger.debug(
254
255
            "Waiting using forced prompt support (timeout %s)"
            % seconds_to_str(partial_timeout)
256
        )
257
258
        while True:
            try:
Neil Williams's avatar
Neil Williams committed
259
260
261
                return self.raw_connection.expect(
                    self.prompt_str, timeout=partial_timeout
                )
262
263
            except (pexpect.TIMEOUT, TestError) as exc:
                if prompt_wait_count < 6:
264
                    self.logger.warning(
Neil Williams's avatar
Neil Williams committed
265
266
267
268
269
270
                        "%s: Sending %s in case of corruption. Connection timeout %s, retry in %s",
                        exc,
                        self.check_char,
                        seconds_to_str(remaining),
                        seconds_to_str(partial_timeout),
                    )
271
                    self.logger.debug("pattern: %s", self.prompt_str)
272
273
274
275
276
                    prompt_wait_count += 1
                    partial_timeout = remaining / 10
                    self.sendline(self.check_char)
                    continue
                else:
Rémi Duraffort's avatar
Rémi Duraffort committed
277
                    # TODO: is someone expecting pexpect.TIMEOUT?
278
279
280
                    raise

    def wait(self, max_end_time=None):
281
282
283
284
285
        """
        Simple wait without sendling blank lines as that causes the menu
        to advance without data which can cause blank entries and can cause
        the menu to exit to an unrecognised prompt.
        """
286
287
288
289
290
        if not max_end_time:
            timeout = self.timeout.duration
        else:
            timeout = max_end_time - time.time()
        if timeout < 0:
Rémi Duraffort's avatar
Rémi Duraffort committed
291
            raise LAVABug("Invalid max_end_time value passed to wait()")
292
        try:
293
294
            return self.raw_connection.expect(self.prompt_str, timeout=timeout)
        except (TestError, pexpect.TIMEOUT):
295
            raise JobError("wait for prompt timed out")
296

297
298
299
    def listen_feedback(self, timeout):
        """
        Listen to output and log as feedback
300
        Returns the number of characters read.
301
        """
302
        index = 0
303
304
305
        if not self.raw_connection:
            # connection has already been closed.
            return index
306
307
308
309
        if timeout < 0:
            raise LAVABug("Invalid timeout value passed to listen_feedback()")
        try:
            self.raw_connection.logfile.is_feedback = True
310
            index = self.raw_connection.expect(
Neil Williams's avatar
Neil Williams committed
311
312
                [pexpect.EOF, pexpect.TIMEOUT], timeout=timeout
            )
313
314
        finally:
            self.raw_connection.logfile.is_feedback = False
315
316
317
318

        if index == 1:
            return len(self.raw_connection.before)
        return index
319

320

321
class ExpectShellSession(Action):
Neil Williams's avatar
Neil Williams committed
322
323
    """
    Waits for a shell connection to the device for the current job.
324
325
    The shell connection can be over any particular connection,
    all that is needed is a prompt.
Neil Williams's avatar
Neil Williams committed
326
    """
327

328
    compatibility = 2
329
330
331
    name = "expect-shell-connection"
    description = "Wait for a shell"
    summary = "Expect a shell prompt"
Neil Williams's avatar
Neil Williams committed
332

Neil Williams's avatar
Neil Williams committed
333
    def __init__(self):
Rémi Duraffort's avatar
Rémi Duraffort committed
334
        super().__init__()
335
        self.force_prompt = True
Neil Williams's avatar
Neil Williams committed
336

337
    def validate(self):
Rémi Duraffort's avatar
Rémi Duraffort committed
338
        super().validate()
Neil Williams's avatar
Neil Williams committed
339
        if "prompts" not in self.parameters:
340
            self.errors = "Unable to identify test image prompts from parameters."
341

342
343
    def run(self, connection, max_end_time):
        connection = super().run(connection, max_end_time)
344
345
        if not connection:
            raise JobError("No connection available.")
Neil Williams's avatar
Neil Williams committed
346
        connection.prompt_str = self.parameters["prompts"]
347
        connection.timeout = self.connection_timeout
Neil Williams's avatar
Neil Williams committed
348
        self.logger.debug(
349
350
            "Forcing a shell prompt, looking for %s", connection.prompt_str
        )
Neil Williams's avatar
Neil Williams committed
351
        connection.sendline("")
352
        self.wait(connection)
353
        return connection