Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bracketed-paste mode makes ShellDriver prompt detection fail #969

Closed
Fermi-4 opened this issue Aug 17, 2022 · 9 comments · Fixed by #1010
Closed

Bracketed-paste mode makes ShellDriver prompt detection fail #969

Fermi-4 opened this issue Aug 17, 2022 · 9 comments · Fixed by #1010

Comments

@Fermi-4
Copy link

Fermi-4 commented Aug 17, 2022

I am following the getting starting steps and running the first test

I have local config file setup for my pi zerow:

targets:
  main:
    resources:
      RawSerialPort:
        port: "/dev/ttyUSB0"
    drivers:
      ManualPowerDriver:
        name: "example"
      SerialDriver: {}
      ShellDriver:
        prompt: 'pi@\w+:[^ ]+ '
        login_prompt: 'raspberrypi login: '
        username: 'pi'
        password: 'password'

I have verified the port /dev/ttyUSB0 is correct using dmesg

When I run the test using:

pytest --lg-env local.yaml test_shell.py

I consistently get this timeout error:

**ERROR test_shell.py::test_shell - pexpect.exceptions.TIMEOUT: Timeout of 4.93 seconds exceeded or connection closed by peer**

I also see this error in dmesg after test is run (bold):

[670927.706302] usb 1-7: new full-speed USB device number 72 using xhci_hcd
[670927.866892] usb 1-7: New USB device found, idVendor=067b, idProduct=2303, bcdDevice= 4.00
[670927.866900] usb 1-7: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[670927.866903] usb 1-7: Product: USB-Serial Controller
[670927.866906] usb 1-7: Manufacturer: Prolific Technology Inc.
[670927.869636] pl2303 1-7:1.0: pl2303 converter detected
[670927.871602] usb 1-7: pl2303 converter now attached to ttyUSB0
[670972.423388] pl2303 ttyUSB0: pl2303_get_line_request - failed: -32
[670972.423787] pl2303 ttyUSB0: pl2303_get_line_request - failed: -32
[670980.558787] pl2303 ttyUSB0: error sending break = -32

I am using the pl2303 to convert serial/usb

One last thing to note is that when the test is over and I minicom to the pi I can see that it did indeed login successfully:

pi@raspberrypi:~$ whoami
pi
@Bastian-Krause
Copy link
Member

Please run the pytest command with -vvv and post the complete output.

@Fermi-4
Copy link
Author

Fermi-4 commented Aug 21, 2022

Thanks - here is the output when I run with -vvv:

(venv) fermi-4@fermi4-MS-7A67:~/first_test$ pytest --lg-env local.yaml test_shell.py
========================================================================================== test session starts ==========================================================================================
platform linux -- Python 3.8.10, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/fermi-4/first_test
plugins: pylint-0.18.0, isort-2.0.0, dependency-0.5.1, labgrid-0.4.1.dev238+g6ad1d66, anyio-1.3.1, cov-3.0.0, mock-3.6.1
collected 1 item                                                                                                                                                                                        

test_shell.py E                                                                                                                                                                                   [100%]

================================================================================================ ERRORS =================================================================================================
_____________________________________________________________________________________ ERROR at setup of test_shell ______________________________________________________________________________________

target = Target(name='main', env=Environment(config_file='local.yaml'))

    @pytest.fixture(scope='session')
    def command(target):
>       shell = target.get_driver('CommandProtocol')

conftest.py:6: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:220: in get_driver
    return self._get_driver(cls, name=name, activate=activate)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:196: in _get_driver
    self.activate(found[0])
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:454: in activate
    client.on_activate()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:72: in on_activate
    self._await_login()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/step.py:215: in wrapper
    _result = func(*_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:186: in _await_login
    self._check_prompt()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:203: in _check_prompt
    self.console.expect(
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/binding.py:96: in wrapper
    return func(self, *_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/step.py:215: in wrapper
    _result = func(*_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/consoleexpectmixin.py:59: in expect
    index = self._expect.expect(pattern, timeout=timeout)
../labgrid/venv/lib/python3.8/site-packages/pexpect/spawnbase.py:343: in expect
    return self.expect_list(compiled_pattern_list,
../labgrid/venv/lib/python3.8/site-packages/pexpect/spawnbase.py:372: in expect_list
    return exp.expect_loop(timeout)
../labgrid/venv/lib/python3.8/site-packages/pexpect/expect.py:181: in expect_loop
    return self.timeout(e)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <pexpect.expect.Expecter object at 0x7f0d9aa10580>, err = TIMEOUT('Timeout of 4.93 seconds exceeded or connection closed by peer')

    def timeout(self, err=None):
        spawn = self.spawn
    
        spawn.before = spawn._before.getvalue()
        spawn.after = TIMEOUT
        index = self.searcher.timeout_index
        if index >= 0:
            spawn.match = TIMEOUT
            spawn.match_index = index
            return index
        else:
            spawn.match = None
            spawn.match_index = None
            msg = str(spawn)
            msg += '\nsearcher: %s' % self.searcher
            if err is not None:
                msg = str(err) + '\n' + msg
    
            exc = TIMEOUT(msg)
            exc.__cause__ = None    # in Python 3.x we can use "raise exc from None"
>           raise exc
E           pexpect.exceptions.TIMEOUT: Timeout of 4.93 seconds exceeded or connection closed by peer
E           <labgrid.util.expect.PtxExpect object at 0x7f0d9aa78280>
E           command: None
E           args: None
E           buffer (last 100 chars): b"echo 'AXNQ''AESXSL'\r\n\x1b[?2004l\rAXNQAESXSL\r\n\x1b[?2004hpi@raspberrypi:~$ "
E           before (last 100 chars): b"echo 'AXNQ''AESXSL'\r\n\x1b[?2004l\rAXNQAESXSL\r\n\x1b[?2004hpi@raspberrypi:~$ "
E           after: <class 'pexpect.exceptions.TIMEOUT'>
E           match: None
E           match_index: None
E           exitstatus: None
E           pid: None
E           child_fd: -1
E           closed: True
E           timeout: 30
E           delimiter: <class 'pexpect.exceptions.EOF'>
E           logfile: None
E           logfile_read: None
E           logfile_send: None
E           maxread: 1
E           ignorecase: False
E           searchwindowsize: None
E           delaybeforesend: 0.05
E           delayafterclose: 0.1
E           delayafterterminate: 0.1
E           searcher: searcher_re:
E               0: re.compile(b'AXNQAESXSL\\s+pi@\\w+:[^ ]+ ')

../labgrid/venv/lib/python3.8/site-packages/pexpect/expect.py:144: TIMEOUT
=========================================================================================== warnings summary ============================================================================================
../labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114
  /home/fermi-4/labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114: PytestAssertRewriteWarning: Module already imported so cannot be rewritten: __editable___labgrid_0_4_1_dev238_g6ad1d66_finder
    self._mark_plugins_for_rewrite(hook)

-- Docs: https://docs.pytest.org/en/stable/warnings.html
======================================================================================== short test summary info ========================================================================================
ERROR test_shell.py::test_shell - pexpect.exceptions.TIMEOUT: Timeout of 4.93 seconds exceeded or connection closed by peer
====================================================================================== 1 warning, 1 error in 8.20s ======================================================================================
(venv) fermi-4@fermi4-MS-7A67:~/first_test$ pytest -vvv --lg-env local.yaml test_shell.py
========================================================================================== test session starts ==========================================================================================
platform linux -- Python 3.8.10, pytest-6.2.5, py-1.11.0, pluggy-1.0.0 -- /home/fermi-4/labgrid/venv/bin/python3
cachedir: .pytest_cache
rootdir: /home/fermi-4/first_test
plugins: pylint-0.18.0, isort-2.0.0, dependency-0.5.1, labgrid-0.4.1.dev238+g6ad1d66, anyio-1.3.1, cov-3.0.0, mock-3.6.1
collected 1 item                                                                                                                                                                                        

test_shell.py::test_shell 
   ShellDriver._await_login state='start'
     SerialDriver.expect state='start' args={'pattern': ['pi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.003'
     SerialDriver.expect state='start' args={'pattern': ['pi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(0, b'\r\n\x1b[?2004l\r\x1b[?2004h', <re.Match object; span=(19, 37), match=b'pi@raspberrypi:~$ '>, b'pi@raspberrypi:~$ ') duration='0.032'
   ShellDriver._await_login state='stop' duration='2.036'
   SerialDriver.expect state='start' args={'pattern': 'pi@\\w+:[^ ]+ '}
   SerialDriver.expect state='stop' result=(0, b'run() { echo -n "$MARKER"; sh -c "$@"; echo "$MARKER $?"; }\r\n\x1b[?2004l\r\x1b[?2004h', <re.Match object; span=(78, 96), match=b'pi@raspberrypi:~$ '>, b'pi@raspberrypi:~$ ') duration='0.049'
   ShellDriver.run state='start' args={'cmd': 'cat /proc/version'}
     SerialDriver.expect state='start' args={'pattern': 'UGKGPTOQKV\\s+pi@\\w+:[^ ]+ '}
     SerialDriver.expect state='stop' exception=TIMEOUT('Timeout of 4.93 seconds exceeded or connection closed by peer\n<labgrid.util.expect.PtxExpect object at 0x7f995e3843a0>\ncommand: None\nargs: None\nbuffer (last 100 chars): b"echo \'UGKG\'\'PTOQKV\'\\r\\n\\x1b[?2004l\\rUGKGPTOQKV\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nbefore (last 100 chars): b"echo \'UGKG\'\'PTOQKV\'\\r\\n\\x1b[?2004l\\rUGKGPTOQKV\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nafter: <class \'pexpect.exceptions.TIMEOUT\'>\nmatch: None\nmatch_index: None\nexitstatus: None\npid: None\nchild_fd: -1\nclosed: True\ntimeout: 30\ndelimiter: <class \'pexpect.exceptions.EOF\'>\nlogfile: None\nlogfile_read: None\nlogfile_send: None\nmaxread: 1\nignorecase: False\nsearchwindowsize: None\ndelaybeforesend: 0.05\ndelayafterclose: 0.1\ndelayafterterminate: 0.1\nsearcher: searcher_re:\n    0: re.compile(b\'UGKGPTOQKV\\\\s+pi@\\\\w+:[^ ]+ \')') duration='5.002'
   ShellDriver.run state='stop' exception=TIMEOUT('Timeout of 4.93 seconds exceeded or connection closed by peer\n<labgrid.util.expect.PtxExpect object at 0x7f995e3843a0>\ncommand: None\nargs: None\nbuffer (last 100 chars): b"echo \'UGKG\'\'PTOQKV\'\\r\\n\\x1b[?2004l\\rUGKGPTOQKV\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nbefore (last 100 chars): b"echo \'UGKG\'\'PTOQKV\'\\r\\n\\x1b[?2004l\\rUGKGPTOQKV\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nafter: <class \'pexpect.exceptions.TIMEOUT\'>\nmatch: None\nmatch_index: None\nexitstatus: None\npid: None\nchild_fd: -1\nclosed: True\ntimeout: 30\ndelimiter: <class \'pexpect.exceptions.EOF\'>\nlogfile: None\nlogfile_read: None\nlogfile_send: None\nmaxread: 1\nignorecase: False\nsearchwindowsize: None\ndelaybeforesend: 0.05\ndelayafterclose: 0.1\ndelayafterterminate: 0.1\nsearcher: searcher_re:\n    0: re.compile(b\'UGKGPTOQKV\\\\s+pi@\\\\w+:[^ ]+ \')') duration='5.002'
FAILED                                                                                                                                                                                            [100%]

=============================================================================================== FAILURES ================================================================================================
______________________________________________________________________________________________ test_shell _______________________________________________________________________________________________

command = ShellDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.acti...password='120256cn35', keyfile='', login_timeout=60, console_ready='', await_login_timeout=2, post_login_settle_time=0)

    def test_shell(command):
        print('this is before command call')
>       stdout, stderr, returncode = command.run('cat /proc/version')

test_shell.py:3: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/binding.py:96: in wrapper
    return func(self, *_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/step.py:215: in wrapper
    _result = func(*_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:114: in run
    return self._run(cmd, timeout=timeout, codec=codec, decodeerrors=decodeerrors)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:93: in _run
    self._check_prompt()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:203: in _check_prompt
    self.console.expect(
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/binding.py:96: in wrapper
    return func(self, *_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/step.py:215: in wrapper
    _result = func(*_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/consoleexpectmixin.py:59: in expect
    index = self._expect.expect(pattern, timeout=timeout)
../labgrid/venv/lib/python3.8/site-packages/pexpect/spawnbase.py:343: in expect
    return self.expect_list(compiled_pattern_list,
../labgrid/venv/lib/python3.8/site-packages/pexpect/spawnbase.py:372: in expect_list
    return exp.expect_loop(timeout)
../labgrid/venv/lib/python3.8/site-packages/pexpect/expect.py:181: in expect_loop
    return self.timeout(e)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <pexpect.expect.Expecter object at 0x7f995e384fa0>, err = TIMEOUT('Timeout of 4.93 seconds exceeded or connection closed by peer')

    def timeout(self, err=None):
        spawn = self.spawn
    
        spawn.before = spawn._before.getvalue()
        spawn.after = TIMEOUT
        index = self.searcher.timeout_index
        if index >= 0:
            spawn.match = TIMEOUT
            spawn.match_index = index
            return index
        else:
            spawn.match = None
            spawn.match_index = None
            msg = str(spawn)
            msg += '\nsearcher: %s' % self.searcher
            if err is not None:
                msg = str(err) + '\n' + msg
    
            exc = TIMEOUT(msg)
            exc.__cause__ = None    # in Python 3.x we can use "raise exc from None"
>           raise exc
E           pexpect.exceptions.TIMEOUT: Timeout of 4.93 seconds exceeded or connection closed by peer
E           <labgrid.util.expect.PtxExpect object at 0x7f995e3843a0>
E           command: None
E           args: None
E           buffer (last 100 chars): b"echo 'UGKG''PTOQKV'\r\n\x1b[?2004l\rUGKGPTOQKV\r\n\x1b[?2004hpi@raspberrypi:~$ "
E           before (last 100 chars): b"echo 'UGKG''PTOQKV'\r\n\x1b[?2004l\rUGKGPTOQKV\r\n\x1b[?2004hpi@raspberrypi:~$ "
E           after: <class 'pexpect.exceptions.TIMEOUT'>
E           match: None
E           match_index: None
E           exitstatus: None
E           pid: None
E           child_fd: -1
E           closed: True
E           timeout: 30
E           delimiter: <class 'pexpect.exceptions.EOF'>
E           logfile: None
E           logfile_read: None
E           logfile_send: None
E           maxread: 1
E           ignorecase: False
E           searchwindowsize: None
E           delaybeforesend: 0.05
E           delayafterclose: 0.1
E           delayafterterminate: 0.1
E           searcher: searcher_re:
E               0: re.compile(b'UGKGPTOQKV\\s+pi@\\w+:[^ ]+ ')

../labgrid/venv/lib/python3.8/site-packages/pexpect/expect.py:144: TIMEOUT
----------------------------------------------------------------------------------------- Captured stderr setup -----------------------------------------------------------------------------------------
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Read 1 bytes: b'\r', timeout 2.00, requested size 1
  DEBUG: Read 10 bytes: b'\n\x1b[?2004l\r', timeout 2.00, requested size 1
  DEBUG: Read 1 bytes: b'\x1b', timeout 1.99, requested size 1
  DEBUG: Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 1.97, requested size 1
  DEBUG: Write 60 bytes: b'run() { echo -n "$MARKER"; sh -c "$@"; echo "$MARKER $?"; }\n'
  DEBUG: Read 1 bytes: b'r', timeout 30.00, requested size 1
  DEBUG: Read 61 bytes: b'un() { echo -n "$MARKER"; sh -c "$@"; echo "$MARKER $?"; }\r\n\x1b', timeout 29.99, requested size 1
  DEBUG: Read 1 bytes: b'[', timeout 29.99, requested size 1
  DEBUG: Read 7 bytes: b'?2004l\r', timeout 29.98, requested size 1
  DEBUG: Read 1 bytes: b'\x1b', timeout 29.98, requested size 1
  DEBUG: Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 29.95, requested size 1
------------------------------------------------------------------------------------------ Captured log setup -------------------------------------------------------------------------------------------
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 1 bytes: b'\n'
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\r', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 10 bytes: b'\n\x1b[?2004l\r', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\x1b', timeout 1.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 1.97, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 60 bytes: b'run() { echo -n "$MARKER"; sh -c "$@"; echo "$MARKER $?"; }\n'
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'r', timeout 30.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 61 bytes: b'un() { echo -n "$MARKER"; sh -c "$@"; echo "$MARKER $?"; }\r\n\x1b', timeout 29.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'[', timeout 29.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 7 bytes: b'?2004l\r', timeout 29.98, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\x1b', timeout 29.98, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 29.95, requested size 1
----------------------------------------------------------------------------------------- Captured stdout call ------------------------------------------------------------------------------------------
this is before command call
----------------------------------------------------------------------------------------- Captured stderr call ------------------------------------------------------------------------------------------
  DEBUG: Write 20 bytes: b"echo 'UGKG''PTOQKV'\n"
  DEBUG: Read 1 bytes: b'e', timeout 5.00, requested size 1
  DEBUG: Read 29 bytes: b"cho 'UGKG''PTOQKV'\r\n\x1b[?2004l\r", timeout 4.99, requested size 1
  DEBUG: Read 1 bytes: b'U', timeout 4.99, requested size 1
  DEBUG: Read 11 bytes: b'GKGPTOQKV\r\n', timeout 4.96, requested size 1
  DEBUG: Read 1 bytes: b'\x1b', timeout 4.96, requested size 1
  DEBUG: Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 4.93, requested size 1
------------------------------------------------------------------------------------------- Captured log call -------------------------------------------------------------------------------------------
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 20 bytes: b"echo 'UGKG''PTOQKV'\n"
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'e', timeout 5.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 29 bytes: b"cho 'UGKG''PTOQKV'\r\n\x1b[?2004l\r", timeout 4.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'U', timeout 4.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 11 bytes: b'GKGPTOQKV\r\n', timeout 4.96, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\x1b', timeout 4.96, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 4.93, requested size 1
=========================================================================================== warnings summary ============================================================================================
../labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114
  /home/fermi-4/labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114: PytestAssertRewriteWarning: Module already imported so cannot be rewritten: __editable___labgrid_0_4_1_dev238_g6ad1d66_finder
    self._mark_plugins_for_rewrite(hook)

-- Docs: https://docs.pytest.org/en/stable/warnings.html
======================================================================================== short test summary info ========================================================================================
FAILED test_shell.py::test_shell - pexpect.exceptions.TIMEOUT: Timeout of 4.93 seconds exceeded or connection closed by peer
===================================================================================== 1 failed, 1 warning in 7.38s ======================================================================================
(venv) fermi-4@fermi4-MS-7A67:~/first_test$ 

@Bastian-Krause
Copy link
Member

Interesting, looks like you have bracketed-paste mode enabled. See pexpect/pexpect#669. I only had time to skim through the issue, but I guess we need to handle this in labgrid. /cc @jluebbe @Emantor

@Bastian-Krause
Copy link
Member

@Fermi-4 Please test if #975 solves the issue for you.

@Fermi-4
Copy link
Author

Fermi-4 commented Aug 24, 2022

Still hitting the error:

(venv) fermi-4@fermi4-MS-7A67:~/first_test$ pytest -vvv --lg-env local.yaml test_shell.py
=========================================================================================== test session starts ===========================================================================================
platform linux -- Python 3.8.10, pytest-6.2.5, py-1.11.0, pluggy-1.0.0 -- /home/fermi-4/labgrid/venv/bin/python3
cachedir: .pytest_cache
rootdir: /home/fermi-4/first_test
plugins: pylint-0.18.0, isort-2.0.0, dependency-0.5.1, labgrid-0.4.1.dev238+g6ad1d66, anyio-1.3.1, cov-3.0.0, mock-3.6.1
collected 1 item                                                                                                                                                                                          

test_shell.py::test_shell 
   ShellDriver._await_login state='start'
     SerialDriver.expect state='start' args={'pattern': ['pi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.002'
     SerialDriver.expect state='start' args={'pattern': ['pi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(1, b'\r\r\n', <re.Match object; span=(3, 22), match=b'raspberrypi login: '>, b'raspberrypi login: ') duration='0.006'
     SerialDriver.expect state='start' args={'pattern': ['pi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(2, b'pi\r\r\n', <re.Match object; span=(5, 15), match=b'Password: '>, b'Password: ') duration='0.072'
     SerialDriver.expect state='start' args={'pattern': ['pi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(0, b'\r\nLinux raspberrypi 5.15.32+ #1538 Thu Mar 31 19:37:58 BST 2022 armv6l\r\n\r\nThe programs included with the Debian GNU/Linux system are free software;\r\nthe exact distribution terms for each program are described in the\r\nindividual files in /usr/share/doc/*/copyright.\r\n\r\nDebian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent\r\npermitted by applicable law.\r\nLast login: Tue Aug 23 21:06:46 CDT 2022 on ttyS0\r\n\x1b[?2004h', <re.Match object; span=(424, 442), match=b'pi@raspberrypi:~$ '>, b'pi@raspberrypi:~$ ') duration='0.734'
     SerialDriver.expect state='start' args={'pattern': ['pi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(0, b'dmesg -n 1\r\n\x1b[?2004l\rdmesg: klogctl failed: Operation not permitted\r\n\x1b[?2004h', <re.Match object; span=(77, 95), match=b'pi@raspberrypi:~$ '>, b'pi@raspberrypi:~$ ') duration='0.074'
     SerialDriver.expect state='start' args={'pattern': 'MRZDBCAGMN\\s+pi@\\w+:[^ ]+ '}
     SerialDriver.expect state='stop' exception=TIMEOUT('Timeout of 4.93 seconds exceeded or connection closed by peer\n<labgrid.util.expect.PtxExpect object at 0x7f01733423a0>\ncommand: None\nargs: None\nbuffer (last 100 chars): b"echo \'MRZD\'\'BCAGMN\'\\r\\n\\x1b[?2004l\\rMRZDBCAGMN\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nbefore (last 100 chars): b"echo \'MRZD\'\'BCAGMN\'\\r\\n\\x1b[?2004l\\rMRZDBCAGMN\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nafter: <class \'pexpect.exceptions.TIMEOUT\'>\nmatch: None\nmatch_index: None\nexitstatus: None\npid: None\nchild_fd: -1\nclosed: True\ntimeout: 30\ndelimiter: <class \'pexpect.exceptions.EOF\'>\nlogfile: None\nlogfile_read: None\nlogfile_send: None\nmaxread: 1\nignorecase: False\nsearchwindowsize: None\ndelaybeforesend: 0.05\ndelayafterclose: 0.1\ndelayafterterminate: 0.1\nsearcher: searcher_re:\n    0: re.compile(b\'MRZDBCAGMN\\\\s+pi@\\\\w+:[^ ]+ \')') duration='5.002'
   ShellDriver._await_login state='stop' exception=TIMEOUT('Timeout of 4.93 seconds exceeded or connection closed by peer\n<labgrid.util.expect.PtxExpect object at 0x7f01733423a0>\ncommand: None\nargs: None\nbuffer (last 100 chars): b"echo \'MRZD\'\'BCAGMN\'\\r\\n\\x1b[?2004l\\rMRZDBCAGMN\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nbefore (last 100 chars): b"echo \'MRZD\'\'BCAGMN\'\\r\\n\\x1b[?2004l\\rMRZDBCAGMN\\r\\n\\x1b[?2004hpi@raspberrypi:~$ "\nafter: <class \'pexpect.exceptions.TIMEOUT\'>\nmatch: None\nmatch_index: None\nexitstatus: None\npid: None\nchild_fd: -1\nclosed: True\ntimeout: 30\ndelimiter: <class \'pexpect.exceptions.EOF\'>\nlogfile: None\nlogfile_read: None\nlogfile_send: None\nmaxread: 1\nignorecase: False\nsearchwindowsize: None\ndelaybeforesend: 0.05\ndelayafterclose: 0.1\ndelayafterterminate: 0.1\nsearcher: searcher_re:\n    0: re.compile(b\'MRZDBCAGMN\\\\s+pi@\\\\w+:[^ ]+ \')') duration='7.896'
ERROR                                                                                                                                                                                               [100%]

================================================================================================= ERRORS ==================================================================================================
______________________________________________________________________________________ ERROR at setup of test_shell _______________________________________________________________________________________

target = Target(name='main', env=Environment(config_file='local.yaml'))

    @pytest.fixture(scope='session')
    def command(target):
>       shell = target.get_driver('CommandProtocol')

conftest.py:6: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:220: in get_driver
    return self._get_driver(cls, name=name, activate=activate)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:196: in _get_driver
    self.activate(found[0])
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:454: in activate
    client.on_activate()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:72: in on_activate
    self._await_login()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/step.py:215: in wrapper
    _result = func(*_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:186: in _await_login
    self._check_prompt()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:203: in _check_prompt
    self.console.expect(
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/binding.py:96: in wrapper
    return func(self, *_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/step.py:215: in wrapper
    _result = func(*_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/consoleexpectmixin.py:59: in expect
    index = self._expect.expect(pattern, timeout=timeout)
../labgrid/venv/lib/python3.8/site-packages/pexpect/spawnbase.py:343: in expect
    return self.expect_list(compiled_pattern_list,
../labgrid/venv/lib/python3.8/site-packages/pexpect/spawnbase.py:372: in expect_list
    return exp.expect_loop(timeout)
../labgrid/venv/lib/python3.8/site-packages/pexpect/expect.py:181: in expect_loop
    return self.timeout(e)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <pexpect.expect.Expecter object at 0x7f01732e2cd0>, err = TIMEOUT('Timeout of 4.93 seconds exceeded or connection closed by peer')

    def timeout(self, err=None):
        spawn = self.spawn
    
        spawn.before = spawn._before.getvalue()
        spawn.after = TIMEOUT
        index = self.searcher.timeout_index
        if index >= 0:
            spawn.match = TIMEOUT
            spawn.match_index = index
            return index
        else:
            spawn.match = None
            spawn.match_index = None
            msg = str(spawn)
            msg += '\nsearcher: %s' % self.searcher
            if err is not None:
                msg = str(err) + '\n' + msg
    
            exc = TIMEOUT(msg)
            exc.__cause__ = None    # in Python 3.x we can use "raise exc from None"
>           raise exc
E           pexpect.exceptions.TIMEOUT: Timeout of 4.93 seconds exceeded or connection closed by peer
E           <labgrid.util.expect.PtxExpect object at 0x7f01733423a0>
E           command: None
E           args: None
E           buffer (last 100 chars): b"echo 'MRZD''BCAGMN'\r\n\x1b[?2004l\rMRZDBCAGMN\r\n\x1b[?2004hpi@raspberrypi:~$ "
E           before (last 100 chars): b"echo 'MRZD''BCAGMN'\r\n\x1b[?2004l\rMRZDBCAGMN\r\n\x1b[?2004hpi@raspberrypi:~$ "
E           after: <class 'pexpect.exceptions.TIMEOUT'>
E           match: None
E           match_index: None
E           exitstatus: None
E           pid: None
E           child_fd: -1
E           closed: True
E           timeout: 30
E           delimiter: <class 'pexpect.exceptions.EOF'>
E           logfile: None
E           logfile_read: None
E           logfile_send: None
E           maxread: 1
E           ignorecase: False
E           searchwindowsize: None
E           delaybeforesend: 0.05
E           delayafterclose: 0.1
E           delayafterterminate: 0.1
E           searcher: searcher_re:
E               0: re.compile(b'MRZDBCAGMN\\s+pi@\\w+:[^ ]+ ')

../labgrid/venv/lib/python3.8/site-packages/pexpect/expect.py:144: TIMEOUT
------------------------------------------------------------------------------------------ Captured stderr setup ------------------------------------------------------------------------------------------
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Read 1 bytes: b'\r', timeout 2.00, requested size 1
  DEBUG: Read 21 bytes: b'\r\nraspberrypi login: ', timeout 1.99, requested size 1
  DEBUG: Write 3 bytes: b'pi\n'
  DEBUG: Read 1 bytes: b'p', timeout 2.00, requested size 1
  DEBUG: Read 4 bytes: b'i\r\r\n', timeout 2.00, requested size 1
  DEBUG: Read 1 bytes: b'P', timeout 1.99, requested size 1
  DEBUG: Read 9 bytes: b'assword: ', timeout 1.93, requested size 1
  DEBUG: Write 11 bytes: b'120256cn35\n'
  DEBUG: Read 1 bytes: b'\r', timeout 2.00, requested size 1
  DEBUG: Read 1 bytes: b'\n', timeout 2.00, requested size 1
  DEBUG: Read 1 bytes: b'L', timeout 1.99, requested size 1
  DEBUG: Read 61 bytes: b'inux raspberrypi 5.15.32+ #1538 Thu Mar 31 19:37:58 BST 2022 ', timeout 1.87, requested size 1
  DEBUG: Read 1 bytes: b'a', timeout 1.87, requested size 1
  DEBUG: Read 61 bytes: b'rmv6l\r\n\r\nThe programs included with the Debian GNU/Linux syst', timeout 1.87, requested size 1
  DEBUG: Read 1 bytes: b'e', timeout 1.87, requested size 1
  DEBUG: Read 61 bytes: b'm are free software;\r\nthe exact distribution terms for each p', timeout 1.86, requested size 1
  DEBUG: Read 1 bytes: b'r', timeout 1.86, requested size 1
  DEBUG: Read 61 bytes: b'ogram are described in the\r\nindividual files in /usr/share/do', timeout 1.86, requested size 1
  DEBUG: Read 1 bytes: b'c', timeout 1.86, requested size 1
  DEBUG: Read 61 bytes: b'/*/copyright.\r\n\r\nDebian GNU/Linux comes with ABSOLUTELY NO WA', timeout 1.85, requested size 1
  DEBUG: Read 1 bytes: b'R', timeout 1.85, requested size 1
  DEBUG: Read 61 bytes: b'RANTY, to the extent\r\npermitted by applicable law.\r\nLast logi', timeout 1.85, requested size 1
  DEBUG: Read 1 bytes: b'n', timeout 1.85, requested size 1
  DEBUG: Read 41 bytes: b': Tue Aug 23 21:06:46 CDT 2022 on ttyS0\r\n', timeout 1.84, requested size 1
  DEBUG: Read 1 bytes: b'\x1b', timeout 1.84, requested size 1
  DEBUG: Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 1.27, requested size 1
  DEBUG: Write 11 bytes: b'dmesg -n 1\n'
  DEBUG: Read 1 bytes: b'd', timeout 2.00, requested size 1
  DEBUG: Read 20 bytes: b'mesg -n 1\r\n\x1b[?2004l\r', timeout 1.99, requested size 1
  DEBUG: Read 1 bytes: b'd', timeout 1.99, requested size 1
  DEBUG: Read 47 bytes: b'mesg: klogctl failed: Operation not permitted\r\n', timeout 1.95, requested size 1
  DEBUG: Read 1 bytes: b'\x1b', timeout 1.95, requested size 1
  DEBUG: Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 1.93, requested size 1
  DEBUG: Write 20 bytes: b"echo 'MRZD''BCAGMN'\n"
  DEBUG: Read 1 bytes: b'e', timeout 5.00, requested size 1
  DEBUG: Read 29 bytes: b"cho 'MRZD''BCAGMN'\r\n\x1b[?2004l\r", timeout 4.99, requested size 1
  DEBUG: Read 1 bytes: b'M', timeout 4.99, requested size 1
  DEBUG: Read 11 bytes: b'RZDBCAGMN\r\n', timeout 4.96, requested size 1
  DEBUG: Read 1 bytes: b'\x1b', timeout 4.96, requested size 1
  DEBUG: Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 4.93, requested size 1
------------------------------------------------------------------------------------------- Captured log setup --------------------------------------------------------------------------------------------
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 1 bytes: b'\n'
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\r', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 21 bytes: b'\r\nraspberrypi login: ', timeout 1.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 3 bytes: b'pi\n'
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'p', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 4 bytes: b'i\r\r\n', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'P', timeout 1.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 9 bytes: b'assword: ', timeout 1.93, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 11 bytes: b'120256cn35\n'
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\r', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\n', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'L', timeout 1.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 61 bytes: b'inux raspberrypi 5.15.32+ #1538 Thu Mar 31 19:37:58 BST 2022 ', timeout 1.87, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'a', timeout 1.87, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 61 bytes: b'rmv6l\r\n\r\nThe programs included with the Debian GNU/Linux syst', timeout 1.87, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'e', timeout 1.87, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 61 bytes: b'm are free software;\r\nthe exact distribution terms for each p', timeout 1.86, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'r', timeout 1.86, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 61 bytes: b'ogram are described in the\r\nindividual files in /usr/share/do', timeout 1.86, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'c', timeout 1.86, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 61 bytes: b'/*/copyright.\r\n\r\nDebian GNU/Linux comes with ABSOLUTELY NO WA', timeout 1.85, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'R', timeout 1.85, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 61 bytes: b'RANTY, to the extent\r\npermitted by applicable law.\r\nLast logi', timeout 1.85, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'n', timeout 1.85, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 41 bytes: b': Tue Aug 23 21:06:46 CDT 2022 on ttyS0\r\n', timeout 1.84, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\x1b', timeout 1.84, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 1.27, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 11 bytes: b'dmesg -n 1\n'
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'd', timeout 2.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 20 bytes: b'mesg -n 1\r\n\x1b[?2004l\r', timeout 1.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'd', timeout 1.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 47 bytes: b'mesg: klogctl failed: Operation not permitted\r\n', timeout 1.95, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\x1b', timeout 1.95, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 1.93, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:45 Write 20 bytes: b"echo 'MRZD''BCAGMN'\n"
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'e', timeout 5.00, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 29 bytes: b"cho 'MRZD''BCAGMN'\r\n\x1b[?2004l\r", timeout 4.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'M', timeout 4.99, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 11 bytes: b'RZDBCAGMN\r\n', timeout 4.96, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 1 bytes: b'\x1b', timeout 4.96, requested size 1
DEBUG    SerialDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.bound: 1>, txdelay=0.0, timeout=3.0)(Target(name='main', env=Environment(config_file='local.yaml'))):consoleexpectmixin.py:29 Read 25 bytes: b'[?2004hpi@raspberrypi:~$ ', timeout 4.93, requested size 1
============================================================================================ warnings summary =============================================================================================
../labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114
  /home/fermi-4/labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114: PytestAssertRewriteWarning: Module already imported so cannot be rewritten: __editable___labgrid_0_4_1_dev238_g6ad1d66_finder
    self._mark_plugins_for_rewrite(hook)

-- Docs: https://docs.pytest.org/en/stable/warnings.html
========================================================================================= short test summary info =========================================================================================
ERROR test_shell.py::test_shell - pexpect.exceptions.TIMEOUT: Timeout of 4.93 seconds exceeded or connection closed by peer
======================================================================================= 1 warning, 1 error in 8.20s =======================================================================================
(venv) fermi-4@fermi4-MS-7A67:~/first_test$ 

@Bastian-Krause
Copy link
Member

Bastian-Krause commented Aug 25, 2022

Still hitting the error:

[...]
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:220: in get_driver
    return self._get_driver(cls, name=name, activate=activate)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:196: in _get_driver
    self.activate(found[0])
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/target.py:454: in activate
    client.on_activate()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:72: in on_activate
    self._await_login()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/step.py:215: in wrapper
    _result = func(*_args, **_kwargs)
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:186: in _await_login
    self._check_prompt()
../labgrid/venv/lib/python3.8/site-packages/labgrid-0.4.1.dev238+g6ad1d66-py3.8.egg/labgrid/driver/shelldriver.py:203: in _check_prompt
    self.console.expect(
[...]

Judging from the line numbers and code snippets from the traceback, you are not testing #975.

Instead of testing the PR, could you check if changing the ShellDriver's prompt in your environment config to '\x1b\[\?2004hpi@\w+:[^ ]+ ' works reliably for you?

@Bastian-Krause Bastian-Krause changed the title Getting Started test_shell.py Bracketed-paste mode makes ShellDriver prompt detection fail Aug 25, 2022
@Fermi-4
Copy link
Author

Fermi-4 commented Aug 25, 2022

This is where HEAD is pointing for that last run:

(venv) fermi-4@fermi4-MS-7A67:~/labgrid$ git log --oneline -n 5
5e038e6 (HEAD -> testing_pr) driver/shelldriver: handle bracketed-paste mode
f30264b (origin/master, origin/HEAD, master) Merge pull request #960 from Bastian-Krause/bst/siglent
97dfce7 Merge pull request #971 from jluebbe/suggest-usbpower
25d6663 Merge pull request #972 from jluebbe/openocd-st-link-3
60807bd Merge pull request #965 from Bastian-Krause/bst/uboot-idle-console

I did not recreate first test though after checking out that commit - so that is probably why it looks unchanged.

After updating my local.yaml to:

    ShellDriver:
        prompt: '\x1b\[\?2004hpi@\w+:[^ ]+ '

I get a passing test run with warning (HEAD still pointing at same commit as above):

(venv) fermi-4@fermi4-MS-7A67:~/first_test$ pytest --lg-env local.yaml test_shell.py
=========================================================================================== test session starts ===========================================================================================
platform linux -- Python 3.8.10, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/fermi-4/first_test
plugins: pylint-0.18.0, isort-2.0.0, dependency-0.5.1, labgrid-0.4.1.dev238+g6ad1d66, anyio-1.3.1, cov-3.0.0, mock-3.6.1
collected 1 item                                                                                                                                                                                          

test_shell.py .                                                                                                                                                                                     [100%]

============================================================================================ warnings summary =============================================================================================
../labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114
  /home/fermi-4/labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114: PytestAssertRewriteWarning: Module already imported so cannot be rewritten: __editable___labgrid_0_4_1_dev238_g6ad1d66_finder
    self._mark_plugins_for_rewrite(hook)

-- Docs: https://docs.pytest.org/en/stable/warnings.html
====================================================================================== 1 passed, 1 warning in 42.75s ======================================================================================
(venv) fermi-4@fermi4-MS-7A67:~/first_test$ 

and with verbose:

(venv) fermi-4@fermi4-MS-7A67:~/first_test$ pytest -vvv --lg-env local.yaml test_shell.py
=========================================================================================== test session starts ===========================================================================================
platform linux -- Python 3.8.10, pytest-6.2.5, py-1.11.0, pluggy-1.0.0 -- /home/fermi-4/labgrid/venv/bin/python3
cachedir: .pytest_cache
rootdir: /home/fermi-4/first_test
plugins: pylint-0.18.0, isort-2.0.0, dependency-0.5.1, labgrid-0.4.1.dev238+g6ad1d66, anyio-1.3.1, cov-3.0.0, mock-3.6.1
collected 1 item                                                                                                                                                                                          

test_shell.py::test_shell 
   ShellDriver._await_login state='start'
     SerialDriver.expect state='start' args={'pattern': ['\\x1b\\[\\?2004hpi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.001'
     SerialDriver.expect state='start' args={'pattern': ['\\x1b\\[\\?2004hpi@\\w+:[^ ]+ ', 'raspberrypi login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(0, b'\r\n\x1b[?2004l\r', <re.Match object; span=(11, 37), match=b'\x1b[?2004hpi@raspberrypi:~$ '>, b'\x1b[?2004hpi@raspberrypi:~$ ') duration='0.038'
   ShellDriver._await_login state='stop' duration='2.040'
   SerialDriver.expect state='start' args={'pattern': '\\x1b\\[\\?2004hpi@\\w+:[^ ]+ '}
   SerialDriver.expect state='stop' result=(0, b'run() { echo -n "$MARKER"; sh -c "$@"; echo "$MARKER $?"; }\r\n\x1b[?2004l\r', <re.Match object; span=(70, 96), match=b'\x1b[?2004hpi@raspberrypi:~$ '>, b'\x1b[?2004hpi@raspberrypi:~$ ') duration='0.040'
   ShellDriver.run state='start' args={'cmd': 'cat /proc/version'}
     SerialDriver.expect state='start' args={'pattern': 'ZEQLSRZUMU\\s+\\x1b\\[\\?2004hpi@\\w+:[^ ]+ '}
     SerialDriver.expect state='stop' result=(0, b"echo 'ZEQL''SRZUMU'\r\n\x1b[?2004l\r", <re.Match object; span=(30, 68), match=b'ZEQLSRZUMU\r\n\x1b[?2004hpi@raspberrypi:~$ '>, b'ZEQLSRZUMU\r\n\x1b[?2004hpi@raspberrypi:~$ ') duration='0.069'
     SerialDriver.expect state='start' args={'pattern': 'AUUFUBGNXJ(.*)AUUFUBGNXJ\\s+(\\d+)\\s+\\x1b\\[\\?2004hpi@\\w+:[^ ]+ '}
     SerialDriver.expect state='stop' result=(0, b"MARKER='AUUF''UBGNXJ' run 'cat /proc/version'\r\n\x1b[?2004l\r", <re.Match object; span=(56, 284), match=b'AUUFUBGNXJLinux version 5.15.32+ (dom@buildbot) >, b'AUUFUBGNXJLinux version 5.15.32+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1538 Thu Mar 31 19:37:58 BST 2022\r\nAUUFUBGNXJ 0\r\n\x1b[?2004hpi@raspberrypi:~$ ') duration='0.098'
   ShellDriver.run state='stop' result=(['Linux version 5.15.32+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1538 Thu Mar 31 19:37:58 BST 2022'], [], 0) duration='0.169'
PASSED                                                                                                                                                                                              [100%]

============================================================================================ warnings summary =============================================================================================
../labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114
  /home/fermi-4/labgrid/venv/lib/python3.8/site-packages/_pytest/config/__init__.py:1114: PytestAssertRewriteWarning: Module already imported so cannot be rewritten: __editable___labgrid_0_4_1_dev238_g6ad1d66_finder
    self._mark_plugins_for_rewrite(hook)

-- Docs: https://docs.pytest.org/en/stable/warnings.html
====================================================================================== 1 passed, 1 warning in 2.37s =======================================================================================
(venv) fermi-4@fermi4-MS-7A67:~/first_test$ 

@Bastian-Krause
Copy link
Member

Okay, then use this approach. The warning should be gone as soon as you follow the official setup steps (you probably used pip install -e . instead of python3 setup.py install).

@Bastian-Krause
Copy link
Member

@Fermi-4 Is this approach okay for you? And is the warning gone when installing labgrid in non-editable mode?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants