Login to shelldriver

[initBasti]

Hey, I just wanted to quickly ask if you know a good way to debug why a login for the activation of a shell driver times out.
The configuration for the login prompt and the login data looks like this:

targets:
    example:
        resources:
            - RemotePlace:
                name: rpi_serial
        drivers:
            - NetworkPowerDriver: {}
            - SerialDriver: {}
            - ShellDriver:
                prompt: 'testlab_user@\w+:[^ ]+ '
                login_prompt: ' login: '
                username: 'testlab_user'
                password: '1234test'
options:
    crossbar_url: 'ws://192.168.178.70:20408/ws'

And I try to activate it like this:

env = Environment('example_conf.yaml')
rpi = env.get_target('example')
sd = rpi.get_driver('ShellDriver', activate=True)
sd.run_check('echo OK')

But the problem is that it just times out. Without any clue about where the problem may be. The user exists and the raspberryPi and the prompt looks like this: testlab_user@raspberrypi:~ $, which I checked in a regex tester and which is matched except for the $ sign.

I have also attempted to use the CommandProtocol directly and I tried to get a ShellDriver object directly like this:

env = Environment('example_conf.yaml')
rpi = env.get_target('example')
sd = ShellDriver(rpi, "shell", prompt='testlab_user@\w+:[^ ]+ ',
                 login_prompt='login: ', username='testlab_user')

rpi.activate(sd)
sd.run_check('echo OK')

Greetings,
Sebastian

[initBasti]

Hey,
just wanted to extend my question, with a bit more info.
I tested if I can access the device via minicom from the exporter device:
sudo minicom --device /dev/ttyUSB0

Welcome to minicom 2.8

OPTIONS: I18n 
Port /dev/ttyUSB0, 19:13:28


raspberrypi login: testlab_user
Password: 
Last login: Wed Nov  3 18:10:29 GMT 2021 on ttyS0

Which works.

I can also access the console via labgrid_client -c config.yaml console.

I tried out the first test again: https://labgrid.readthedocs.io/en/latest/getting_started.html#running-your-first-test
And it fails with the same problem a timeout after 60 seconds.

My problem is that I don't really have a clue where to start, the serial port seems to work, I can access the device via SSH, the user account works and I can communicate with the exporter without problems.

I would be really happy if someone could help me out with this problem.

Greetings,
Sebastian

[Emantor]

The only way to debug whats happening currently is with more verbosity. Higher verbosity levels, i.e. -vvv will print out what labgrid is searching for and will also print the input bytes. Another option is to try #680, which augments the logging infrastructure and makes it easier to parse for humans. I need it to update first though.

Please post a log of the test run with -vvv.

[initBasti]

Hey @Emantor ,

It seems like I receive empty input bytes, could my configuration be incorrect?

Raspberry_Pi_libcamera:
  location: Testbox_1
  USBSerialPort:
      match:
        '@ID_PATH': platform-xhci-hcd.1.auto-usb-0:1.2
      speed: 115200
  NetworkPowerPort:
      model: eg_pms2_network
      host: 192.168.178.29
      index: 1

Like I said I can access the Raspberry Pi via serial port without problems from the exporter device.

To give a better overview of my setup here is a small graph:
Labgrid setup

And here is the output of the pytest output with -vvv:

Programming_Projects/PyProjects/labgrid_test via 🐍 labgrid-venv
✦ ➜ labgrid-client -c local.yaml acquire
Selected role main and place rpi_serial from configuration file
acquired place rpi_serial
Programming_Projects/PyProjects/labgrid_test via 🐍 labgrid-venv
✦ ➜ python3 -m pytest --lg-env local.yaml test_shell.py -vvv
======================================================================== test session starts =========================================================================
platform linux -- Python 3.8.10, pytest-6.2.5, py-1.10.0, pluggy-0.13.1 -- /home/basti/Documents/Programming_Projects/PyProjects/labgrid-venv/bin/python3
cachedir: .pytest_cache
rootdir: /home/basti/Documents/Programming_Projects/PyProjects/labgrid_test
plugins: labgrid-0.3.1.dev162+gc194216
collected 1 item                                                                                                                                                     

test_shell.py::test_shell 
   ShellDriver._await_login state='start'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
     SerialDriver.expect state='start' args={'pattern': ['testlab_user@\\w+:[^ ]+ ', ' login: ', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]}
     SerialDriver.expect state='stop' result=(3, b'', <class 'pexpect.exceptions.TIMEOUT'>, <class 'pexpect.exceptions.TIMEOUT'>) duration='2.000'
   ShellDriver._await_login state='stop' exception=TIMEOUT('Timeout of 60 seconds exceeded during waiting for login') duration='60.015'
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/target.py:217: in get_driver
    return self._get_driver(cls, name=name, activate=activate)
../labgrid-venv/lib/python3.8/site-packages/labgrid/target.py:193: in _get_driver
    self.activate(found[0])
../labgrid-venv/lib/python3.8/site-packages/labgrid/target.py:433: in activate
    client.on_activate()
../labgrid-venv/lib/python3.8/site-packages/labgrid/driver/shelldriver.py:69: in on_activate
    self._await_login()
../labgrid-venv/lib/python3.8/site-packages/labgrid/step.py:219: in wrapper
    _result = func(*_args, **_kwargs)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = ShellDriver(target=Target(name='main', env=Environment(config_file='local.yaml')), name=None, state=<BindingState.boun..., password='1234test', keyfile='', login_timeout=60, console_ready='', await_login_timeout=2, post_login_settle_time=0)

    @step()
    def _await_login(self):
        """Awaits the login prompt and logs the user in"""
    
        timeout = Timeout(float(self.login_timeout))
    
        expectations = [self.prompt, self.login_prompt, "Password: ", TIMEOUT]
        if self.console_ready != "":
            expectations.append(self.console_ready)
    
        # We call console.expect with a short timeout here to detect if the
        # console is idle, which results in a timeout without any changes to
        # the before property. So we store the last before value we've seen.
        # Because pexpect keeps any read data in it's buffer when a timeout
        # occours, we can't lose any data this way.
        last_before = b''
        did_login = False
    
        while True:
            index, before, _, _ = self.console.expect(
                expectations,
                timeout=self.await_login_timeout
            )
    
            if index == 0:
                # we got a promt. no need for any further action to activate
                # this driver.
                self.status = 1
                break
    
            elif index == 1:
                # we need to login
                self.console.sendline(self.username)
                did_login = True
    
            elif index == 2:
                if self.password:
                    self.console.sendline(self.password)
                else:
                    raise Exception("Password entry needed but no password set")
    
            elif index == 3:
                # expect hit a timeout while waiting for a match
                if before == last_before:
                    # we did not receive anything during
                    # self.await_login_timeout.
                    # let's assume the target is idle and we can safely issue a
                    # newline to check the state
                    self.console.sendline("")
    
            elif index == 4:
                # we have just activated a console here
                # lets start over again and see if login or prompt will appear
                # now.
                self.console.sendline("")
    
            last_before = before
    
            if timeout.expired:
>               raise TIMEOUT("Timeout of {} seconds exceeded during waiting for login".format(self.login_timeout))  # pylint: disable=line-too-long
E               pexpect.exceptions.TIMEOUT: Timeout of 60 seconds exceeded during waiting for login

../labgrid-venv/lib/python3.8/site-packages/labgrid/driver/shelldriver.py:176: TIMEOUT
----------------------------------------------------------------------- Captured stderr setup ------------------------------------------------------------------------
  DEBUG: expanded remote resources for place rpi_serial: [NetworkPowerPort(target=Target(name='main', env=Environment(config_file='local.yaml')), name='NetworkPowerPort', state=<BindingState.bound: 1>, avail=True, model='eg_pms2_network', host='192.168.178.29', index='1'), NetworkSerialPort(target=Target(name='main', env=Environment(config_file='local.yaml')), name='USBSerialPort', state=<BindingState.bound: 1>, avail=True, host='nanopct4', port=56243, speed=115200, protocol='rfc2217')]
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
  DEBUG: Write 1 bytes: b'\n'
------------------------------------------------------------------------- Captured log setup -------------------------------------------------------------------------
DEBUG    RemotePlaceManager():remote.py:64 expanded remote resources for place rpi_serial: [NetworkPowerPort(target=Target(name='main', env=Environment(config_file='local.yaml')), name='NetworkPowerPort', state=<BindingState.bound: 1>, avail=True, model='eg_pms2_network', host='192.168.178.29', index='1'), NetworkSerialPort(target=Target(name='main', env=Environment(config_file='local.yaml')), name='USBSerialPort', state=<BindingState.bound: 1>, avail=True, host='nanopct4', port=56243, speed=115200, protocol='rfc2217')]
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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 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:41 Write 1 bytes: b'\n'
====================================================================== short test summary info =======================================================================
ERROR test_shell.py::test_shell - pexpect.exceptions.TIMEOUT: Timeout of 60 seconds exceeded during waiting for login
==================================================================== 1 error in 61.83s (0:01:01) =====================================================================

Greetings and thank you!

[Emantor]

From the log it looks like we are only sending bytes via pyserial, but are not reading anything. That's weird. Is the console still open somewhere else? In that case the other program may receive the output instead of labgrid reading the output.

[initBasti]

@Emantor
Alright, I have completely reset the devices and the labgrid setup on my laptop. Here is a complete write-down of every step I have performed (I hope this is not too long).
I am a step further it doesn't timeout anymore.

1. Prepare Raspberry Pi:

• Use rpi-imager to write the image to Raspberry Pi
• Choose Raspberry Pi OS lite (32-bit)
• Add empty file to boot mount on SD card called "SSH" to access per ssh on first boot
• Create a separate user outside of the sudoers group (password 1234test):\

  sudo useradd -m testlab_user
  sudo passwd testlab_user
  sudo deluser testlab_user sudo
  

• Start sudo raspi-config, go to "Interface Options", "P6 Serial Port", hit Enter and choose "Yes" and "Ok", reboot the Raspberry Pi

2. Prepare laptop:

Add the user to the dialout group and reboot:

sudo usermod -a -G dialout $USER && sudo reboot

Install the labgrid client, merge networkpower driver and adjust pyserial:

cd /tmp
virtualenv -p python3 labgrid-venv
source labgrid-venv/bin/activate
git clone https://github.com/labgrid-project/labgrid.git && cd labgrid
git remote add initBasti git@github.com:initBasti/labgrid.git
git fetch initBasti
git pull initBasti eg_pms2_network_power_driver
pip install --upgrade pip
pip install -r requirements.txt 
pip uninstall pyserial
pip install https://github.com/labgrid-project/pyserial/archive/v3.4.0.1.zip#egg=pyserial
python3 setup.py install
mkdir ../first_test
cp examples/shell/* ../first_test/
cd ../first_test/

3. Test with a direct connection between Raspberry Pi and Laptop:

Now I adjust the local.yaml to look like this:

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

Make sure the that port is correct:

➜ ls -l /dev/ttyUSB*
crw-rw---- 1 root dialout 188, 0 Nov 27 08:47 /dev/ttyUSB0

Test the serial connection:

sudo screen /dev/ttyUSB0 115200
# Close the session properly with CTRL + A -> type: `:quit` -> Enter

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

Failed with Output:
https://termbin.com/3q5k

4. Prepare NanoPC-T4:

• Get the fitting Armbian image: https://www.armbian.com/nanopc-t4/#kernels-archive-all
  (Armbian 21.08.1 Ubuntu Focal with Linux 5.10.60-rockchip64)
• Write the image to the SD card with Balena etcher

Prepare Labgrid exporter and coordinator on NanoPC-T4:

• 4.1: sudo apt update && curl -fsSL test.docker.com -o get-docker.sh && sh get-docker.sh && sudo usermod -aG docker $USER && sudo apt install -y docker-compose
• 4.2: git clone https://github.com/labgrid-project/labgrid && cd labgrid
• 4.3: Merge my power driver from an open pull request (EG PMS2 Network power driver)
• 4.4: Build all containers: ./dockerfiles/build.sh
• 4.5: Apply the following changes:

diff --git a/dockerfiles/staging/docker-compose.yml b/dockerfiles/staging/docker-compose.yml
index 8600529..1c34271 100644
--- a/dockerfiles/staging/docker-compose.yml
+++ b/dockerfiles/staging/docker-compose.yml
@@ -6,8 +6,7 @@ services:
       - "./crossbar:/home/root/crossbar"
     tty: true
     network_mode: "host"
-    command: bash -c "cp /home/root/crossbar/places_example.yaml /opt/crossbar/places.yaml &&
-      crossbar start --config /opt/labgrid/.crossbar/config.yaml"
+    command: bash -c "crossbar start --config /opt/labgrid/.crossbar/config.yaml"
   client:
     image: "labgrid-client"
     volumes:
@@ -37,6 +36,8 @@ services:
     volumes:
       - "./exporter-conf:/opt/conf"
       - "/run/udev:/run/udev:ro"
+    devices:
+      - "/dev/ttyUSB0:/dev/ttyUSB0"
     depends_on:
       - coordinator
     tty: true

• 4.6: Set up a startup script and a systemd service file.

/usr/lib/systemd/system/labgrid.service

[Unit]
Description=Labgrid Coordinator & Exporter
After=docker.service

[Service]
Type=simple
StandardInput=null
StandardOutput=journal
StandardError=journal
ExecStart=labgrid-compose-start.sh

[Install]
WantedBy=default.target

/usr/local/bin/labgrid-compose-start.sh

#!/bin/bash

cd /home/basti/labgrid/dockerfiles/staging
CURRENT_UID=$(id -u):$(id -g) docker-compose up -d coordinator exporter

• 4.7: Enable the service:

sudo systemctl daemon-reload
sudo systemctl enable labgrid.service

• 4.8: Connect the raspberry Pi with the NanoPC-T4 via a USB serial cable
• 4.9: Get the DEVPATH with udevadm info /dev/ttyUSB0 (seems to be the only reliable udev attribute that also exists within the docker container)
• 4.10: Get the IP address of the networt power device with sudo nmap -sn 192.168.178.0/24
• 4.11: Write configuration to /home/${USER}/labgrid/dockerfiles/staging/exporter-conf/exporter.yaml

Raspberry_Pi_libcamera:
  location: Testbox_1
  USBSerialPort:
    match:
      DEVPATH: /devices/platform/usb@fe900000/fe900000.usb/xhci-hcd.1.auto/usb1/1-1/1-1.1/1-1.1:1.0/ttyUSB0/tty/ttyUSB0
    speed: 115200
  NetworkPowerPort:
      model: eg_pms2_network
      host: 192.168.178.29
      index: 1

• 4.12: Reboot NanoPC-T4 and check the status of exporter and coordinator afterward

basti@nanopct4:~$ docker-compose logs

5. Connect with NanoPC-T4 from Laptop

• Test if a connection works directly:

export LG_CROSSBAR="ws://192.168.178.70:20408/ws"
labgrid-client --place rpi_serial create
labgrid-client --place rpi_serial add-match nanopct4/Raspberry_Pi_libcamera/NetworkPowerPort
labgrid-client --place rpi_serial add-match nanopct4/Raspberry_Pi_libcamera/NetworkSerialPort
labgrid-client -c local.yaml acquire
labgrid-client -c local.yaml con

(Side note: this sometimes just doesn't work, where I get an error message that the host cannot be found, and after a quick reboot it works again, very very annoying and strange. I currently have no idea how to debug that issue)

After I confirmed that I can connect to the Raspberry Pi via the exporter, I try the test:

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

Which sadly fails similar to the test with the direct connection between laptop and Raspberry Pi:
https://termbin.com/fr5g

[Emantor]

This is definitely our bug. It looks like the rpi console uses a VT100 code which is not correctly filtered by the VT100 regex within the shelldriver. The failing regex is:

HXAJTILEVM\s+testlab_user@\w+:[^ ]+

but it reads:

HXAJTILEVM\r\n\x1b[?2004htestlab_user@raspberrypi:~$

which does not match since the \x1b[?2004h prevents the match.
Looks like we have to adjust the VT100 regex.

[Bastian-Krause]

See #1010.