RE: [PATCH v4 4/9] dts: add ssh pexpect library

["Juraj Linkeš" <juraj.linkes@pantheon.tech>]

> -----Original Message-----
> From: Stanislaw Kardach <kda@semihalf.com>
> Sent: Thursday, September 22, 2022 4:32 PM
> To: Juraj Linkeš <juraj.linkes@pantheon.tech>
> Cc: thomas@monjalon.net; david.marchand@redhat.com;
> ronan.randles@intel.com; Honnappa.Nagarahalli@arm.com;
> ohilyard@iol.unh.edu; lijuan.tu@intel.com; dev@dpdk.org
> Subject: Re: [PATCH v4 4/9] dts: add ssh pexpect library
> 
> On Thu, Sep 22, 2022 at 09:41:40AM +0000, Juraj Linkeš wrote:
> > Hi Stanislaw,
> First a preface. I understand that the DTS rework is sponsored by someone and
> there may be people waiting with their labs for this job to be done.
> Everything that I'll write below is from a point of view of a developer who'd like
> to utilize DTS as a test suite for DPDK when adding support for new PMDs or
> architectures/boards. This might be in conflict with time-to-market metric at this
> point in time but I'm more focused on the state of DPDK+DTS in the long run.
> So feel free to disregard my comments if there are higher priorities.
> >
> > Neither of the current DTS maintainer nor me are the author of the code, so
> we can only speculate as to why certain parts were implemented the way they
> are.
> >
> > We've thought a lot about replacing pexpect with something else, such as
> Fabric. Fabric is supposedly faster, which is the biggest draw and instead of
> fixing/reworking pexpect code, it makes sense to switch our focus on Fabric. For
> this PoC version though, we'd like to stay with this pexpect code and work on
> other appoaches in the next release cycle. The code is well tested so there's not
> much point in poking in it if it's to be replaced.
> I have a nasty experience of code staying without re-factoring for long "because
> it works". When it comes to DTS my experience is that it works only if used
> exactly on the setups it was meant for. Adapting it to a new setup, new PMD or
> "even" running in the cloud shows that parts of it are held together with a string.
> I'm not blaming DTS devs here. Such approach is often needed for various
> reasons (usually time-to-market) and it's hard to be forward-compatible.
> 
> That said I would suggest to use this opportunity to refactor DTS while it's still
> not merged. Otherwise we'll be left with code that we're uncertain why it works.
> That's not a quality-first approach and it'll bite us in the backside in the future.
> 
> Let's do things right, not fast.

Absolutely, but effective time use is also something to consider. Our current plan doesn't won't really have to contend with problems in the future, as we want to add the Farbic implementation in the next release cycle. I'm also working on refactoring the code a bit - I'm adding an abstraction that would allow us to easily replace the pexpect implementation with Fabric (with no impact on DTS behavior - the same APIs will need to be implemented). Also, we'll remove the pexpect implementation once Fabric is in place (unless we can think of a reason for pexpect to stay, in which case we'll need to refactor it). I think that instead of focusing on pexpect we could focus on making sure the replacement won't cause any issues. What do you think?

> >
> > With that said, some more comments inline.
> >
> > > > +class SSHPexpect:
> > > > +    username: str
> > > > +    password: str
> > > > +    node: str
> > > > +    logger: DTSLOG
> > > > +    magic_prompt: str
> > > > +
> > > > +    def __init__(
> > > > +        self,
> > > > +        node: str,
> > > > +        username: str,
> > > > +        password: Optional[str],
> > > > +        logger: DTSLOG,
> > > > +    ):
> > > > +        self.magic_prompt = "MAGIC PROMPT"
> > > Why is this necessary? pxssh is already setting target prompt to
> > > pxssh.UNIQUE_PROMPT in the session constructor, to be specific:
> > >
> > >   self.UNIQUE_PROMPT = r"\[PEXPECT\][\$\#] "
> > >   self.PROMPT = self.UNIQUE_PROMPT
> > >
> > > Also session.login() will change target prompt to that, exactly for
> > > the reason of achieving a unique prompt that can be easily matched by
> pxssh.
> > >
> > > So if "MAGIC PROMPT is the prompt that you'd like to have on the
> > > remote host, then the following should be run after opening the session:
> > >
> >
> > I believe this is here to have a prompt that won't be matched anywhere, to
> induce a timeout a collect all data up to that point.
> The only reason I can think of for doing this is to get the intermediate output
> updates while the test is running. Are there any others?
> 
> If I'm right, how would that be different from matching an actual prompt with a
> timeout? pexpect is already setting an unusual prompt that will not be matched
> by anything else ("[PEXPECT] #").
> Just use that with a small timeout and you get the same effect, including
> timeout triggering an exception.

Some of my comments were only speculation I could come up. That doesn't justify anything, but it could shed some light on the motivation behind the implementation.
You're probably right on this point. Parts of the DTS code seem somewhat pointless to me as well.

> >
> > >   self.session.PROMPT = self.magic_prompt
> > >   if not self.session.set_unique_prompt():
> > >     do_some_error_handling()
> > >
> > > Otherwise it's unnecessary.
> > > > +        self.logger = logger
> > > > +
> > > > +        self.node = node
> > > > +        self.username = username
> > > > +        self.password = password or ""
> > > > +        self.logger.info(f"ssh {self.username}@{self.node}")
> > > > +
> > > > +        self._connect_host()
> > > > +
> > > > +    def _connect_host(self) -> None:
> > > > +        """
> > > > +        Create connection to assigned node.
> > > > +        """
> > > > +        retry_times = 10
> > > > +        try:
> > > > +            if ":" in self.node:
> > > > +                while retry_times:
> > > > +                    self.ip = self.node.split(":")[0]
> > > > +                    self.port = int(self.node.split(":")[1])
> > > > +                    self.session = pxssh.pxssh(encoding="utf-8")
> > > > +                    try:
> > > > +                        self.session.login(
> > > > +                            self.ip,
> > > > +                            self.username,
> > > > +                            self.password,
> > > > +                            original_prompt="[$#>]",
> > > > +                            port=self.port,
> > > > +                            login_timeout=20,
> > > > +
> > > > + password_regex=r"(?i)(?:password:)|(?:passphrase for
> > > key)|(?i)(password for .+:)",
> > > > +                        )
> > > > +                    except Exception as e:
> > > > +                        print(e)
> > > > +                        time.sleep(2)
> > > > +                        retry_times -= 1
> > > > +                        print("retry %d times connecting..." % (10 - retry_times))
> > > > +                    else:
> > > > +                        break
> > > > +                else:
> > > > +                    raise Exception("connect to %s:%s failed" % (self.ip, self.port))
> > > > +            else:
> > > > +                self.session = pxssh.pxssh(encoding="utf-8")
> > > > +                self.session.login(
> > > > +                    self.node,
> > > > +                    self.username,
> > > > +                    self.password,
> > > > +                    original_prompt="[$#>]",
> > > > +
> > > > + password_regex=r"(?i)(?:password:)|(?:passphrase for
> > > key)|(?i)(password for .+:)",
> > > > +                )
> > > > +                self.logger.info(f"Connection to {self.node} succeeded")
> > > > +            self.send_expect("stty -echo", "#")
> > > > +            self.send_expect("stty columns 1000", "#")
> > > This works only by chance and makes hacks in get_output_before()
> necessary.
> > > After some testing it seems that pxssh is matching AND chomping the
> > > session.PROMPT when session.prompt() is called. Given the
> > > UNIQUE_PROMPT, the root user prompt will be "[PEXPECT]#" so this
> > > send_expect() will chomp # and leave "[PEXPECT]" as part of the output.
> > >
> > > Given that the two above lines do not require any special output I
> > > think
> > > self.send_command() should be used here.
> >
> > Since we want to move away form using root, we'd need to address this, but
> this would be better left to the Fabric implementation and stay with the root
> requirement for now.
> It's more than that. This self.send_expect("...", "#") pattern will cause the hacks
> on removing the pexpect's prompt that are done below.
> Those hack are not necessary at all if pexpect is used properly. If this is not
> understood, then when switching to Fabric, someone might repeat them
> thinking they're on purpose.

True. But we know the code is not great so the new implementation won't really consider the pexpect implementation. I mentioned an abstraction above - that will define what needs to be implemented in Fabric.

> >
> > > > +        except Exception as e:
> > > > +            print(RED(str(e)))
> > > > +            if getattr(self, "port", None):
> > > > +                suggestion = (
> > > > +                    "\nSuggession: Check if the firewall on [ %s ] " % self.ip
> > > > +                    + "is stopped\n"
> > > > +                )
> > > > +                print(GREEN(suggestion))
> > > > +
> > > > +            raise SSHConnectionException(self.node)
> > > > +
> > > > +    def send_expect_base(self, command: str, expected: str,
> > > > + timeout: float) ->
> > > str:
> > > > +        self.clean_session()
> > > > +        self.session.PROMPT = expected
> > > > +        self.__sendline(command)
> > > > +        self.__prompt(command, timeout)
> > > > +
> > > > +        before = self.get_output_before()
> > > Prompt should be reverted to whatever it was before leaving this function.
> >
> > Seems reasonable. I guess it wasn't needed because of the requirement to use
> root. Adding this seems innocent enough.
> >
> > > > +        return before
> > > > +
> > > > +    def send_expect(
> > > > +        self, command: str, expected: str, timeout: float = 15, verify: bool =
> False
> > > > +    ) -> str | int:
> > > > +
> > > > +        try:
> > > > +            ret = self.send_expect_base(command, expected, timeout)
> > > > +            if verify:
> > > > +                ret_status = self.send_expect_base("echo $?",
> > > > + expected, timeout)
> > > "echo $?" will only print the return code. How is it supposed to
> > > match "expected"? If "expected" is a return code then the first
> > > command's output probably won't match.
> > > I think send_command() should be used here.
> >
> > Expected is the prompt to expect, "#" in most cases.
> Then it should not be called "expected" but "prompt", otherwise someone might
> use this API to actually match something in the ssh output (which is a totally
> valid use-case). Look at the docstring of
> dts.framework.node.Node.send_expect():
> 
> """
> Send commands to node and return string before expected string.
> """
> 
> Not to mention that the "verify" parameter is not documented and will NOT
> work if "expected" is anything else than a prompt.
> 

I'll rename it, that won't really impact anything. And I can also document the "verify" parameter.

> I wonder how many DTS tests have to work around or utilize those hacks?
> There may be some test cases which work only because of them which is a
> wrong way to solve a problem but again - maybe there were other priorities.

I'd image this being the case.

> >
> > > > +                if not int(ret_status):
> > > > +                    return ret
> > > The condition above seems like a C-ism used in python which again
> > > works by mistake. Return code 0 will convert to integer 0 which will
> > > be promoted to a boolean False. It would be more readable to change this
> block to:
> > >   ri = int(ret_status)
> > >   if ri != 0:
> > >     # error prints
> > >   return ri
> >
> > This is common in Python, but really only usable if you know the object type. In
> this case it's always integer and it's perfectly fine to use it this way (0 = False,
> anything else = 1), but I agree that the double negative doesn't help with
> readibility. In any case, this is a minor thing a I there's not much of a reason to
> change it if we're to replace it with Fabric.
> Agreed, this can wait.
> >
> > > > +                else:
> > > > +                    self.logger.error("Command: %s failure!" % command)
> > > > +                    self.logger.error(ret)
> > > > +                    return int(ret_status)
> > > > +            else:
> > > > +                return ret
> > > > +        except Exception as e:
> > > > +            print(
> > > > +                RED(
> > > > +                    "Exception happened in [%s] and output is [%s]"
> > > > +                    % (command, self.get_output_before())
> > > > +                )
> > > > +            )
> > > > +            raise e
> > > > +
> > > > +    def send_command(self, command: str, timeout: float = 1) -> str:
> > > > +        try:
> > > > +            self.clean_session()
> > > > +            self.__sendline(command)
> > > > +        except Exception as e:
> > > > +            raise e
> > > > +
> > > > +        output = self.get_session_before(timeout=timeout)
> > > > +        self.session.PROMPT = self.session.UNIQUE_PROMPT
> > > > +        self.session.prompt(0.1)
> > > This is wrong:
> > > 1. self.get_session_before() will return output of the command but since
> > >    it changed the expected (not real!) prompt to self.magic_prompt, that
> > >    won't be matched so the output will contain the prompt set by pxssh
> > >    (UNIQUE_PROMPT).
> > > 2. Then prompt is reset to UNIQUE_PROMPT but and prompt() is called but
> > >    that will only clean up the pxssh buffer. If get_session_before() was
> > >    not changing the session.PROMPT from UNIQUE_PROMPT to
> magic_prompt,
> > >    the second prompt() call would be unnecessary.
> > > > +
> > > > +        return output
> > > > +
> > > > +    def clean_session(self) -> None:
> > > > +        self.get_session_before(timeout=0.01)
> > > What if remote host is slow for any reason? We'll timeout here. It
> > > seems that such a small timeout value was used because
> > > clean_session() is used in every
> > > send_command() call.
> > > Come to think of it, why is this call necessary when we have self.__flush()?
> >
> > I think the timeout is deliberate. More below.
> >
> > > > +
> > > > +    def get_session_before(self, timeout: float = 15) -> str:
> > > > +        """
> > > > +        Get all output before timeout
> > > > +        """
> > > > +        self.session.PROMPT = self.magic_prompt
> > > This line has no effect. Remote prompt was never set to self.magic_prompt.
> >
> > I think this is to ensure that we hit the timeout.
> Why would we intentionally want to hit a timeout? Unless I'm missing
> something, it'll only cause us to wait for "timeout" even if the command ended
> already. Also note the full logic of the "get_session_before()":
> 1. Trigger self.session.prompt() to get the session buffer updated with
>    whatever output was between now and now+timeout seconds.
> 2. Get the output but since we were matching the self.magic_prompt,
>    self.get_output_all() has to remove the real prompt ([PEXPECT]) if
>    the command ended.
> 3. Flush the pexpect's ssh buffer so that next call won't read what has
>    already been returned (that's the job of self.__flush()).
> 
> So I don't think there is any reason to use this always-timeout logic.

Yes. It seems to me there's a lot of superfluous stuff in the pexpect implementation. We basically only need send_command and get_output apart from the init/cleanup methods.

> >
> > > > +        try:
> > > > +            self.session.prompt(timeout)
> > > > +        except Exception as e:
> > > > +            pass
> > > > +
> > > > +        before = self.get_output_all()
> > > > +        self.__flush()
> > > > +
> > > > +        return before
> > > > +
> > > > +    def __flush(self) -> None:
> > > > +        """
> > > > +        Clear all session buffer
> > > > +        """
> > > > +        self.session.buffer = ""
> > > > +        self.session.before = ""
> > > > +
> > > > +    def __prompt(self, command: str, timeout: float) -> None:
> > > > +        if not self.session.prompt(timeout):
> > > > +            raise TimeoutException(command,
> > > > + self.get_output_all()) from None
> > > > +
> > > > +    def __sendline(self, command: str) -> None:
> > > > +        if not self.isalive():
> > > > +            raise SSHSessionDeadException(self.node)
> > > > +        if len(command) == 2 and command.startswith("^"):
> > > > +            self.session.sendcontrol(command[1])
> > > > +        else:
> > > > +            self.session.sendline(command)
> > > > +
> > > > +    def get_output_before(self) -> str:
> > > The name is missleading. In pxssh terms "before" means all the lines
> > > before the matched expect()/prompt(). Here it returns the last line
> > > of the output. Perhaps
> > > get_last_output_line() is better?
> >
> > I thought so too, but this actually returns all lines except the last:
> > 'a.b.c.d'.rsplit('.', 1)[0]
> > 'a.b.c'
> >
> Oh, I've totally missed that!
> If that's the case then this function is a result of the always-timeout logic. Note
> that get_output_before() is only called from
> send_expect_base() (and indirectly by send_expect()) to get the output of the
> command without the prompt.
> So the reason why self.send_expect("echo 'foo'", "#") returns a proper output
> ('foo\n') is:
> 0. On login() time pexpect sets the remote prompt to "[PEXPECT]#".
> 1. send_expect() -> self.send_expect_base() sets the match prompt to #.
>    This causes self.session.prompt() to update the self.session.buffer,
>    match # and chomp it, leaving the ssh buffer as:
>      foo
>      [PEXPECT]
> 2. send_expect_base() calls self.get_output_before() which cuts the last
>    line of the output. Note that the "if" at the end is necessary for
>    commands that do not return any output. Otherwise the output would
>    be "[PEXPECT]". Also note that if there are any control characters
>    printed by the remote shell, then this will also not work because
>    a straight string comparison is done, not a regex match.
> 
> Contrary, if self.magic_prompt was not used and pexpect's original prompt was
> left undisturbed, then all the hacks above would not be needed and the code
> would be cleaner.

Yes. On top of that, the two output functions actually do the same thing. Or maybe not strictly, but I think the intention in both was to remove the last line containing "[PEXPECT]".

> > > > +        if not self.isalive():
> > > > +            raise SSHSessionDeadException(self.node)
> > > > +        before: list[str] = self.session.before.rsplit("\r\n", 1)
> > > > +        if before[0] == "[PEXPECT]":
> > > > +            before[0] = ""
> > > Unnecessary if prompt was handled in proper way as mentioned above.
> > > > +
> > > > +        return before[0]
> > > > +
> > > > +    def get_output_all(self) -> str:
> > > > +        output: str = self.session.before
> > > > +        output.replace("[PEXPECT]", "")
> > > Ditto. If session.PROMPT was restored properly, this function would
> > > not be necessary at all.
> > > > +        return output
> > > > +
> > > > +    def close(self, force: bool = False) -> None:
> > > > +        if force is True:
> > > > +            self.session.close()
> > > > +        else:
> > > > +            if self.isalive():
> > > > +                self.session.logout()
> > > > +
> > > > +    def isalive(self) -> bool:
> > > > +        return self.session.isalive()
> > > > diff --git a/dts/framework/utils.py b/dts/framework/utils.py new
> > > > file mode 100644 index 0000000000..db87349827
> > > > --- /dev/null
> > > > +++ b/dts/framework/utils.py
> > > > @@ -0,0 +1,12 @@
> > > > +# SPDX-License-Identifier: BSD-3-Clause # Copyright(c) 2010-2014
> > > > +Intel Corporation # Copyright(c) 2022 PANTHEON.tech s.r.o.
> > > > +# Copyright(c) 2022 University of New Hampshire #
> > > > +
> > > > +def RED(text: str) -> str:
> > > > +    return f"\u001B[31;1m{str(text)}\u001B[0m"
> > > > +
> > > > +
> > > > +def GREEN(text: str) -> str:
> > > > +    return f"\u001B[32;1m{str(text)}\u001B[0m"
> > > > --
> > > > 2.30.2
> > > >
> > >
> > > --
> > > Best Regards,
> > > Stanislaw Kardach
> >
> 
> --
> Best Regards,
> Stanislaw Kardach