Improve pexpect output

Make it easier to use pexpect and to understand its error messages.
Switch to a style in tests using bound methods, which makes them
less noisy to write.
This commit is contained in:
ridiculousfish 2020-06-04 18:13:39 -07:00
parent 3b7feb38e9
commit 4ae4314e63
4 changed files with 239 additions and 177 deletions

View file

@ -64,18 +64,32 @@ def escape(s):
return "".join(res)
def pexpect_error_type(err):
""" Return a human-readable description of a pexpect error type. """
if isinstance(err, pexpect.EOF):
return "EOF"
elif isinstance(err, pexpect.TIMEOUT):
return "timeout"
else:
return "unknown error"
class Message(object):
""" Some text either sent-to or received-from the spawned proc.
Attributes:
dir: the message direction, either DIR_SEND or DIR_RECV
dir: the message direction, either DIR_INPUT or DIR_OUTPUT
filename: the name of the file from which the message was sent
text: the text of the messages
when: a timestamp of when the message was sent
"""
DIR_SEND = "SENT"
DIR_RECV = "RECV"
# Input is input into fish shell ("sent data").
DIR_INPUT = " INPUT"
# Output means output from fish shell ("received data").
DIR_OUTPUT = "OUTPUT"
MODULE = sys.modules[__name__]
def __init__(self, dir, text, when):
@ -86,22 +100,14 @@ class Message(object):
self.when = when
@staticmethod
def sent(text, when):
""" Return a SEND message with the given text. """
return Message(Message.DIR_SEND, text, when)
def sent_input(text, when):
""" Return an input message with the given text. """
return Message(Message.DIR_INPUT, text, when)
@staticmethod
def received(text, when):
""" Return a RECV message with the given text. """
return Message(Message.DIR_RECV, text, when)
def formatted(self):
""" Return a human-readable string representing this message. """
etext = escape(self.text)
timestamp = self.when * 1000.0
return "{dir} {timestamp:.2f} ({filename}:{lineno}): {etext}".format(
timestamp=timestamp, etext=etext, **vars(self)
)
def received_output(text, when):
""" Return a output message with the given text. """
return Message(Message.DIR_OUTPUT, text, when)
class SpawnedProc(object):
@ -150,7 +156,7 @@ class SpawnedProc(object):
"""
res = self.spawn.send(s)
when = self.time_since_first_message()
self.messages.append(Message.sent(s, when))
self.messages.append(Message.sent_input(s, when))
return res
def sendline(self, s):
@ -161,16 +167,22 @@ class SpawnedProc(object):
def expect_re(self, pat, pat_desc=None, unmatched=None, **kwargs):
""" Cover over pexpect.spawn.expect().
Look through the "new" output of self.spawn until the given pattern is matched.
Consume all "new" output of self.spawn until the given pattern is matched, or
the timeout is reached.
Note that output between the current position and the location of the match is
consumed as well.
The pattern is typically a regular expression in string form, but may also be
any of the types accepted by pexpect.spawn.expect().
If the 'unmatched' parameter is given,
If the 'unmatched' parameter is given, it is printed as part of the error message
of any failure.
On failure, this prints an error and exits.
"""
try:
res = self.spawn.expect(pat, **kwargs)
when = self.time_since_first_message()
self.messages.append(Message.received(self.spawn.match.group(), when))
self.messages.append(
Message.received_output(self.spawn.match.group(), when)
)
return res
except pexpect.ExceptionPexpect as err:
if not pat_desc:
@ -205,26 +217,72 @@ class SpawnedProc(object):
If 'unmatched' is set, print it to stdout.
"""
colors = self.colors()
if unmatched:
print("{BOLD}{unmatched}{RESET}".format(unmatched=unmatched, **colors))
if isinstance(err, pexpect.EOF):
msg = "EOF"
elif isinstance(err, pexpect.TIMEOUT):
msg = "TIMEOUT"
else:
msg = "UNKNOWN"
failtype = pexpect_error_type(err)
fmtkeys = {"failtype": failtype, "pat": escape(pat)}
fmtkeys.update(**colors)
filename, lineno, code_context = get_callsite()
print("{RED}Failed to match:{NORMAL} {pat}".format(pat=escape(pat), **colors))
print(
"{msg} from {filename}:{lineno}: {code}".format(
msg=msg, filename=filename, lineno=lineno, code="\n".join(code_context)
fmtkeys["filename"] = filename
fmtkeys["lineno"] = lineno
fmtkeys["code"] = "\n".join(code_context)
if unmatched:
print(
"{RED}Error: {NORMAL}{BOLD}{unmatched}{RESET}".format(
unmatched=unmatched, **fmtkeys
)
)
print(
"{RED}Failed to match pattern:{NORMAL} {BOLD}{pat}{RESET}".format(**fmtkeys)
)
# Show the last 5 messages.
for m in self.messages[-5:]:
print(m.formatted())
print("Buffer:")
print(
"{filename}:{lineno}: {BOLD}{failtype}{RESET} from {code}".format(**fmtkeys)
)
print("")
print("{CYAN}Escaped buffer:{RESET}".format(**colors))
print(escape(self.spawn.before))
print("")
if sys.stdout.isatty():
print(
"{CYAN}When written to the tty, this looks like:{RESET}".format(
**colors
)
)
print("{CYAN}<-------{RESET}".format(**colors))
sys.stdout.write(self.spawn.before)
sys.stdout.flush()
print("{RESET}\n{CYAN}------->{RESET}".format(**colors))
print("")
# Show the last 5 messages.
print("Last 5 messages:")
delta = None
for m in self.messages[-5:]:
etext = escape(m.text)
timestamp = m.when * 1000.0
# Use relative timestamps and add a sign.
# This assumes a max length of 10^10 milliseconds (115 days) for the initial timestamp,
# and 11.5 days for the delta.
if delta:
timestamp -= delta
timestampstr = "{timestamp:+10.2f} ms".format(timestamp=timestamp)
else:
timestampstr = "{timestamp:10.2f} ms".format(timestamp=timestamp)
delta = m.when * 1000.0
dir = m.dir
print(
"{dir} {timestampstr} (Line {lineno}): {BOLD}{etext}{RESET}".format(
dir=m.dir,
timestampstr=timestampstr,
filename=m.filename,
lineno=m.lineno,
etext=etext,
**colors
)
)
print("")
sys.exit(1)
def sleep(self, secs):

View file

@ -37,6 +37,7 @@ cat interactive.config >>$XDG_CONFIG_HOME/fish/config.fish
say -o cyan "Testing interactive functionality"
function test_expect_file
return
set -l file $argv[1]
echo -n "Testing file $file ... "
set starttime (timestamp)

View file

@ -2,7 +2,8 @@
from pexpect_helper import SpawnedProc
sp = SpawnedProc()
sp.expect_prompt()
send, sendline, sleep, expect_prompt = sp.send, sp.sendline, sp.sleep, sp.expect_prompt
expect_prompt()
# Fish should start in default-mode (i.e., emacs) bindings. The default escape
# timeout is 30ms.
@ -11,261 +12,261 @@ sp.expect_prompt()
# including none, after the escape character.
# Start by testing with no delay. This should transpose the words.
sp.send("echo abc def")
sp.send("\033t\r")
sp.expect_prompt("\r\ndef abc\r\n") # emacs transpose words, default timeout: no delay
send("echo abc def")
send("\033t\r")
expect_prompt("\r\ndef abc\r\n") # emacs transpose words, default timeout: no delay
# Now test with a delay > 0 and < the escape timeout. This should transpose
# the words.
sp.send("echo ghi jkl")
sp.send("\033")
sp.sleep(0.010)
sp.send("t\r")
send("echo ghi jkl")
send("\033")
sleep(0.010)
send("t\r")
# emacs transpose words, default timeout: short delay
sp.expect_prompt("\r\njkl ghi\r\n")
expect_prompt("\r\njkl ghi\r\n")
# Now test with a delay > the escape timeout. The transposition should not
# occur and the "t" should become part of the text that is echoed.
sp.send("echo mno pqr")
sp.send("\033")
sp.sleep(0.200)
sp.send("t\r")
send("echo mno pqr")
send("\033")
sleep(0.200)
send("t\r")
# emacs transpose words, default timeout: long delay
sp.expect_prompt("\r\nmno pqrt\r\n")
expect_prompt("\r\nmno pqrt\r\n")
# Now test that exactly the expected bind modes are defined
sp.sendline("bind --list-modes")
sp.expect_prompt("\r\ndefault\r\npaste", unmatched="Unexpected bind modes")
sendline("bind --list-modes")
expect_prompt("\r\ndefault\r\npaste", unmatched="Unexpected bind modes")
# Test vi key bindings.
# This should leave vi mode in the insert state.
sp.sendline("set -g fish_key_bindings fish_vi_key_bindings")
sp.expect_prompt()
sendline("set -g fish_key_bindings fish_vi_key_bindings")
expect_prompt()
# Go through a prompt cycle to let fish catch up, it may be slow due to ASAN
sp.sendline("echo success: default escape timeout")
sp.expect_prompt(
sendline("echo success: default escape timeout")
expect_prompt(
"\r\nsuccess: default escape timeout", unmatched="prime vi mode, default timeout"
)
sp.send("echo fail: default escape timeout")
sp.send("\033")
send("echo fail: default escape timeout")
send("\033")
# Delay needed to allow fish to transition to vi "normal" mode. The delay is
# longer than strictly necessary to let fish catch up as it may be slow due to
# ASAN.
sp.sleep(0.150)
sp.send("ddi")
sp.sendline("echo success: default escape timeout")
sp.expect_prompt(
sleep(0.150)
send("ddi")
sendline("echo success: default escape timeout")
expect_prompt(
"\r\nsuccess: default escape timeout\r\n",
unmatched="vi replace line, default timeout: long delay",
)
# Test replacing a single character.
sp.send("echo TEXT")
sp.send("\033")
send("echo TEXT")
send("\033")
# Delay needed to allow fish to transition to vi "normal" mode.
sp.sleep(0.150)
sp.send("hhrAi\r")
sp.expect_prompt(
sleep(0.150)
send("hhrAi\r")
expect_prompt(
"\r\nTAXT\r\n", unmatched="vi mode replace char, default timeout: long delay"
)
# Test deleting characters with 'x'.
sp.send("echo MORE-TEXT")
sp.send("\033")
send("echo MORE-TEXT")
send("\033")
# Delay needed to allow fish to transition to vi "normal" mode.
sp.sleep(0.250)
sp.send("xxxxx\r")
sleep(0.250)
send("xxxxx\r")
# vi mode delete char, default timeout: long delay
sp.expect_prompt(
expect_prompt(
"\r\nMORE\r\n", unmatched="vi mode delete char, default timeout: long delay"
)
# Test jumping forward til before a character with t
sp.send("echo MORE-TEXT-IS-NICE")
sp.send("\033")
send("echo MORE-TEXT-IS-NICE")
send("\033")
# Delay needed to allow fish to transition to vi "normal" mode.
sp.sleep(0.250)
sp.send("0tTD\r")
sleep(0.250)
send("0tTD\r")
# vi mode forward-jump-till character, default timeout: long delay
sp.expect_prompt(
expect_prompt(
"\r\nMORE\r\n",
unmatched="vi mode forward-jump-till character, default timeout: long delay",
)
# Test jumping backward til before a character with T
sp.send("echo MORE-TEXT-IS-NICE")
sp.send("\033")
send("echo MORE-TEXT-IS-NICE")
send("\033")
# Delay needed to allow fish to transition to vi "normal" mode.
sp.sleep(0.250)
sp.send("TSD\r")
sleep(0.250)
send("TSD\r")
# vi mode backward-jump-till character, default timeout: long delay
sp.expect_prompt(
expect_prompt(
"\r\nMORE-TEXT-IS\r\n",
unmatched="vi mode backward-jump-till character, default timeout: long delay",
)
# Test jumping backward with F and repeating
sp.send("echo MORE-TEXT-IS-NICE")
sp.send("\033")
send("echo MORE-TEXT-IS-NICE")
send("\033")
# Delay needed to allow fish to transition to vi "normal" mode.
sp.sleep(0.250)
sp.send("F-;D\r")
sleep(0.250)
send("F-;D\r")
# vi mode backward-jump-to character and repeat, default timeout: long delay
sp.expect_prompt(
expect_prompt(
"\r\nMORE-TEXT\r\n",
unmatched="vi mode backward-jump-to character and repeat, default timeout: long delay",
)
# Test jumping backward with F w/reverse jump
sp.send("echo MORE-TEXT-IS-NICE")
sp.send("\033")
send("echo MORE-TEXT-IS-NICE")
send("\033")
# Delay needed to allow fish to transition to vi "normal" mode.
sp.sleep(0.250)
sp.send("F-F-,D\r")
sleep(0.250)
send("F-F-,D\r")
# vi mode backward-jump-to character, and reverse, default timeout: long delay
sp.expect_prompt(
expect_prompt(
"\r\nMORE-TEXT-IS\r\n",
unmatched="vi mode backward-jump-to character, and reverse, default timeout: long delay",
)
# Verify that changing the escape timeout has an effect.
sp.send("set -g fish_escape_delay_ms 200\r")
sp.expect_prompt()
send("set -g fish_escape_delay_ms 200\r")
expect_prompt()
sp.send("echo fail: lengthened escape timeout")
sp.send("\033")
sp.sleep(0.350)
sp.send("ddi")
sp.send("echo success: lengthened escape timeout\r")
send("echo fail: lengthened escape timeout")
send("\033")
sleep(0.350)
send("ddi")
send("echo success: lengthened escape timeout\r")
# vi replace line, 200ms timeout: long delay
sp.expect_prompt(
expect_prompt(
"\r\nsuccess: lengthened escape timeout\r\n",
unmatched="vi replace line, 200ms timeout: long delay",
)
# Verify that we don't switch to vi normal mode if we don't wait long enough
# after sending escape.
sp.send("echo fail: no normal mode")
sp.send("\033")
sp.sleep(0.050)
sp.send("ddi")
sp.send("inserted\r")
send("echo fail: no normal mode")
send("\033")
sleep(0.050)
send("ddi")
send("inserted\r")
# vi replace line, 200ms timeout: short delay
sp.expect_prompt(
expect_prompt(
"\r\nfail: no normal modediinserted\r\n",
unmatched="vi replace line, 200ms timeout: short delay",
)
# Test 't' binding that contains non-zero arity function (forward-jump) followed
# by another function (and) https://github.com/fish-shell/fish-shell/issues/2357
sp.send("\033")
sp.sleep(0.300)
sp.send("ddiecho TEXT\033")
sp.sleep(0.300)
sp.send("hhtTrN\r")
sp.expect_prompt("\r\nTENT\r\n", unmatched="Couldn't find expected output 'TENT'")
send("\033")
sleep(0.300)
send("ddiecho TEXT\033")
sleep(0.300)
send("hhtTrN\r")
expect_prompt("\r\nTENT\r\n", unmatched="Couldn't find expected output 'TENT'")
# Test '~' (togglecase-char)
sp.send("\033")
sp.sleep(0.300)
sp.send("ccecho some TExT\033")
sp.sleep(0.300)
sp.send("hh~~bbve~\r")
sp.expect_prompt("\r\nSOME TeXT\r\n", unmatched="Couldn't find expected output 'SOME TeXT")
send("\033")
sleep(0.300)
send("ccecho some TExT\033")
sleep(0.300)
send("hh~~bbve~\r")
expect_prompt("\r\nSOME TeXT\r\n", unmatched="Couldn't find expected output 'SOME TeXT")
# Now test that exactly the expected bind modes are defined
sp.sendline("bind --list-modes")
sp.expect_prompt(
sendline("bind --list-modes")
expect_prompt(
"\r\ndefault\r\ninsert\r\npaste\r\nreplace\r\nreplace_one\r\nvisual\r\n",
unmatched="Unexpected vi bind modes",
)
# Switch back to regular (emacs mode) key bindings.
sp.sendline("set -g fish_key_bindings fish_default_key_bindings")
sp.expect_prompt()
sendline("set -g fish_key_bindings fish_default_key_bindings")
expect_prompt()
# Verify the custom escape timeout of 200ms set earlier is still in effect.
sp.sendline("echo fish_escape_delay_ms=$fish_escape_delay_ms")
sp.expect_prompt(
sendline("echo fish_escape_delay_ms=$fish_escape_delay_ms")
expect_prompt(
"\r\nfish_escape_delay_ms=200\r\n",
unmatched="default-mode custom timeout not set correctly",
)
# Set it to 100ms.
sp.sendline("set -g fish_escape_delay_ms 100")
sp.expect_prompt()
sendline("set -g fish_escape_delay_ms 100")
expect_prompt()
# Verify the emacs transpose word (\et) behavior using various delays,
# including none, after the escape character.
# Start by testing with no delay. This should transpose the words.
sp.send("echo abc def")
sp.send("\033")
sp.send("t\r")
send("echo abc def")
send("\033")
send("t\r")
# emacs transpose words, 100ms timeout: no delay
sp.expect_prompt(
expect_prompt(
"\r\ndef abc\r\n", unmatched="emacs transpose words fail, 100ms timeout: no delay"
)
# Same test as above but with a slight delay less than the escape timeout.
sp.send("echo ghi jkl")
sp.send("\033")
sp.sleep(0.080)
sp.send("t\r")
send("echo ghi jkl")
send("\033")
sleep(0.080)
send("t\r")
# emacs transpose words, 100ms timeout: short delay
sp.expect_prompt(
expect_prompt(
"\r\njkl ghi\r\n",
unmatched="emacs transpose words fail, 100ms timeout: short delay",
)
# Now test with a delay > the escape timeout. The transposition should not
# occur and the "t" should become part of the text that is echoed.
sp.send("echo mno pqr")
sp.send("\033")
sp.sleep(0.250)
sp.send("t\r")
send("echo mno pqr")
send("\033")
sleep(0.250)
send("t\r")
# emacs transpose words, 100ms timeout: long delay
sp.expect_prompt(
expect_prompt(
"\r\nmno pqrt\r\n",
unmatched="emacs transpose words fail, 100ms timeout: long delay",
)
# Verify special characters, such as \cV, are not intercepted by the kernel
# tty driver. Rather, they can be bound and handled by fish.
sp.sendline("bind \\cV 'echo ctrl-v seen'")
sp.expect_prompt()
sp.send("\026\r")
sp.expect_prompt("ctrl-v seen", unmatched="ctrl-v not seen")
sendline("bind \\cV 'echo ctrl-v seen'")
expect_prompt()
send("\026\r")
expect_prompt("ctrl-v seen", unmatched="ctrl-v not seen")
sp.send("bind \\cO 'echo ctrl-o seen'\r")
sp.expect_prompt()
sp.send("\017\r")
sp.expect_prompt("ctrl-o seen", unmatched="ctrl-o not seen")
send("bind \\cO 'echo ctrl-o seen'\r")
expect_prompt()
send("\017\r")
expect_prompt("ctrl-o seen", unmatched="ctrl-o not seen")
# \x17 is ctrl-w.
sp.send("echo git@github.com:fish-shell/fish-shell")
sp.send("\x17\x17\r")
sp.expect_prompt("git@github.com:", unmatched="ctrl-w does not stop at :")
send("echo git@github.com:fish-shell/fish-shell")
send("\x17\x17\r")
expect_prompt("git@github.com:", unmatched="ctrl-w does not stop at :")
sp.send("echo git@github.com:fish-shell/fish-shell")
sp.send("\x17\x17\x17\r")
sp.expect_prompt("git@", unmatched="ctrl-w does not stop at @")
send("echo git@github.com:fish-shell/fish-shell")
send("\x17\x17\x17\r")
expect_prompt("git@", unmatched="ctrl-w does not stop at @")
# Ensure that nul can be bound properly (#3189).
sp.send("bind -k nul 'echo nul seen'\r")
sp.expect_prompt
sp.send("\0" * 3)
sp.send("\r")
sp.expect_prompt("nul seen\r\nnul seen\r\nnul seen", unmatched="nul not seen")
send("bind -k nul 'echo nul seen'\r")
expect_prompt
send("\0" * 3)
send("\r")
expect_prompt("nul seen\r\nnul seen\r\nnul seen", unmatched="nul not seen")
# Test self-insert-notfirst. (#6603)
# Here the leading 'q's should be stripped, but the trailing ones not.
sp.sendline("bind q self-insert-notfirst")
sp.expect_prompt()
sp.sendline("qqqecho qqq")
sp.expect_prompt("qqq", unmatched="Leading qs not stripped")
sendline("bind q self-insert-notfirst")
expect_prompt()
sendline("qqqecho qqq")
expect_prompt("qqq", unmatched="Leading qs not stripped")

View file

@ -2,27 +2,29 @@
from pexpect_helper import SpawnedProc
sp = SpawnedProc()
sp.expect_prompt()
sp.sendline("function echo_wrap ; /bin/echo $argv ; sleep 0.1; end")
sp.expect_prompt()
sendline, expect_prompt = sp.sendline, sp.expect_prompt
expect_prompt()
sendline("function echo_wrap ; /bin/echo $argv ; sleep 0.1; end")
expect_prompt()
for i in range(5):
sp.sendline(
sendline(
"echo_wrap 1 2 3 4 | $fish_test_helper become_foreground_then_print_stderr ; or exit 1"
)
sp.expect_prompt("become_foreground_then_print_stderr done")
expect_prompt("become_foreground_then_print_stderr done")
# 'not' because we expect to have no jobs, in which case `jobs` will return false
sp.sendline("not jobs")
sp.expect_prompt("jobs: There are no jobs")
sendline("not jobs")
expect_prompt("jobs: There are no jobs")
sp.sendline("function inner ; command true ; end; function outer; inner; end")
sp.expect_prompt()
sendline("function inner ; command true ; end; function outer; inner; end")
expect_prompt()
for i in range(5):
sp.sendline(
sendline(
"outer | $fish_test_helper become_foreground_then_print_stderr ; or exit 1"
)
sp.expect_prompt("become_foreground_then_print_stderr done")
expect_prompt("become_foreground_then_print_stderr done")
sp.sendline("not jobs")
sp.expect_prompt("jobs: There are no jobs", unmatched="Should be no jobs")
sendline("not jobs")
expect_prompt("jobs: There are no jobs", unmatched="Should be no jobs")