[1/5] dts: fix InteractiveShell command prompt filtering
Checks
Commit Message
When sending a command using an instance of InteractiveShell the output
is meant to filter out the leading shell prompt. The filtering logic is
present but the line is appended anyways.
Bugzilla ID: 1411
Fixes: 88489c0501af ("dts: add smoke tests")
Signed-off-by: Luca Vizzarro <luca.vizzarro@arm.com>
Reviewed-by: Paul Szczepanek <paul.szczepanek@arm.com>
Reviewed-by: Jack Bond-Preston <jack.bond-preston@arm.com>
---
Cc: Jeremy Spewock <jspewock@iol.unh.edu>
---
dts/framework/remote_session/interactive_shell.py | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
Comments
On Fri, Apr 12, 2024 at 1:11 PM Luca Vizzarro <luca.vizzarro@arm.com> wrote:
>
> When sending a command using an instance of InteractiveShell the output
> is meant to filter out the leading shell prompt. The filtering logic is
> present but the line is appended anyways.
>
I don't think that's what's happening here. The output collecting
logic is "stop when we encounter a prompt, but not the prompt with the
command we sent". We could change the comment though.
> Bugzilla ID: 1411
> Fixes: 88489c0501af ("dts: add smoke tests")
>
> Signed-off-by: Luca Vizzarro <luca.vizzarro@arm.com>
> Reviewed-by: Paul Szczepanek <paul.szczepanek@arm.com>
> Reviewed-by: Jack Bond-Preston <jack.bond-preston@arm.com>
> ---
> Cc: Jeremy Spewock <jspewock@iol.unh.edu>
> ---
> dts/framework/remote_session/interactive_shell.py | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/dts/framework/remote_session/interactive_shell.py b/dts/framework/remote_session/interactive_shell.py
> index 5cfe202e15..8a9bf96ea9 100644
> --- a/dts/framework/remote_session/interactive_shell.py
> +++ b/dts/framework/remote_session/interactive_shell.py
> @@ -132,11 +132,11 @@ def send_command(self, command: str, prompt: str | None = None) -> str:
> self._stdin.flush()
> out: str = ""
> for line in self._stdout:
> - out += line
> if prompt in line and not line.rstrip().endswith(
> command.rstrip()
> ): # ignore line that sent command
> break
> + out += line
If we do this, we'll only filter out the last prompt, which may not be
desirable, since the last prompt is there only because all of our
interactive shells force an extra prompt with _command_extra_chars.
One thing we could improve though is removing the distribution welcome
message from logs, or at least separate it from the first command sent
with the interactive shell. The second option will allow us to see
clearly that an interactive session has been established, although we
could just emit a shorter log (something like "Started a testpmd
session" and then flush the welcome screen output).
> self._logger.debug(f"Got output: {out}")
> return out
>
> --
> 2.34.1
>
Thank you for your review Juraj!
On 16/04/2024 09:40, Juraj Linkeš wrote:
>> When sending a command using an instance of InteractiveShell the output
>> is meant to filter out the leading shell prompt. The filtering logic is
>> present but the line is appended anyways.
>>
>
> I don't think that's what's happening here. The output collecting
> logic is "stop when we encounter a prompt, but not the prompt with the
> command we sent". We could change the comment though.
Yeah, I actually identified the behaviour better after writing this.
Will update the commit body accordingly. And I mixed-up leading with
trailing! This is meant to say "trailing shell prompt".
>> @@ -132,11 +132,11 @@ def send_command(self, command: str, prompt: str | None = None) -> str:
>> self._stdin.flush()
>> out: str = ""
>> for line in self._stdout:
>> - out += line
>> if prompt in line and not line.rstrip().endswith(
>> command.rstrip()
>> ): # ignore line that sent command
>> break
>> + out += line
>
> If we do this, we'll only filter out the last prompt, which may not be
> desirable, since the last prompt is there only because all of our
> interactive shells force an extra prompt with _command_extra_chars.
Could you please expand more on this?
> One thing we could improve though is removing the distribution welcome
> message from logs, or at least separate it from the first command sent
> with the interactive shell. The second option will allow us to see
> clearly that an interactive session has been established, although we
> could just emit a shorter log (something like "Started a testpmd
> session" and then flush the welcome screen output).
I am not sure what you are referring to exactly, could you also expand
more on this please?
Given it's not particularly explained, I thought having two command
prompts (especially a trailing one) was an error. The main reason behind
this is that when we go to parse the port info, the last entry which is
"device private info" appears to be open ended, and I couldn't gather
much information from the testpmd source code. So I opted to parse
everything until the end. With a trailing command prompt this meant
that: device_private_info="....testpmd> ".
On Tue, Apr 16, 2024 at 2:12 PM Luca Vizzarro <Luca.Vizzarro@arm.com> wrote:
>
> Thank you for your review Juraj!
>
> On 16/04/2024 09:40, Juraj Linkeš wrote:
>
> >> When sending a command using an instance of InteractiveShell the output
> >> is meant to filter out the leading shell prompt. The filtering logic is
> >> present but the line is appended anyways.
> >>
> >
> > I don't think that's what's happening here. The output collecting
> > logic is "stop when we encounter a prompt, but not the prompt with the
> > command we sent". We could change the comment though.
>
> Yeah, I actually identified the behaviour better after writing this.
> Will update the commit body accordingly. And I mixed-up leading with
> trailing! This is meant to say "trailing shell prompt".
>
> >> @@ -132,11 +132,11 @@ def send_command(self, command: str, prompt: str | None = None) -> str:
> >> self._stdin.flush()
> >> out: str = ""
> >> for line in self._stdout:
> >> - out += line
> >> if prompt in line and not line.rstrip().endswith(
> >> command.rstrip()
> >> ): # ignore line that sent command
> >> break
> >> + out += line
> >
> > If we do this, we'll only filter out the last prompt, which may not be
> > desirable, since the last prompt is there only because all of our
> > interactive shells force an extra prompt with _command_extra_chars.
>
> Could you please expand more on this?
>
Actually, filtering out the last prompt is fine. I got this mixed up
with processing the last prompt. We must process the last prompt, but
we don't need to print it (and there's not much reason to do so).
And the reason we must process it is because we're consuming the
output line by line. A line appears in (or is yielded by) self._stdout
only after a newline appears in the output. For a typical command
output:
prompt> command\n
<command output>\n
prompt>
The last line in self._stdout is the last line of <command output>
because that's the last line with a newline. We send
_command_extra_chars to force another prompt into the output:
prompt> command\n
<command output>\n
prompt>\n
prompt>
Now the last line with a newline contains a prompt. The actual extra
trailing prompt is then pushed to the next command execution:
prompt_from_command1> command2\n
<command2 output>\n
<prompt_from_command2>
Maybe you already knew this but maybe we could archive this and point
to it in case anyone asks. :-)
> > One thing we could improve though is removing the distribution welcome
> > message from logs, or at least separate it from the first command sent
> > with the interactive shell. The second option will allow us to see
> > clearly that an interactive session has been established, although we
> > could just emit a shorter log (something like "Started a testpmd
> > session" and then flush the welcome screen output).
>
> I am not sure what you are referring to exactly, could you also expand
> more on this please?
>
Let's look at logs. The first thing to note is we don't log when we
start the interactive session. The first log from the session is the
output from the first command, such as testpmd:
2024/04/11 13:29:27 - test_suite - dts.SUT 1 - INFO - Sending: 'sudo
-- sh -c '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd -l
1-2 -n 4 --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
--tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
--hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
--tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall''
2024/04/11 13:29:28 - test_suite - dts.SUT 1 - DEBUG - Got output:
Welcome to Ubuntu 22.04.2 LTS (GNU/Linux 5.15.0-97-generic x86_64)^M
<the welcome screen continues>
Last login: Thu Apr 11 11:24:44 2024 from 192.168.122.1^M^M
sudo -- sh -c '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd
-l 1-2 -n 4 --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
--tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
--hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
--tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall'^M
^M
^[[?2004hjlinkes@dts-sut:~$ sudo -- sh -c
'/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd -l 1-2 -n 4
--file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
--tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
--hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
--tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall'^M
^[[?2004l^M^M
EAL: Detected CPU lcores: 4^M
<tespmd startup continues>
Done^M
testpmd> ^M^M
2024/04/11 13:29:28 - test_suite - dts.SUT 1 - INFO - Sending: 'show
device info all'
What we see is the testpmd command being sent and then the output is:
Welcome screen
Testpmd command we've sent
Testpmd command echoed with the os prompt
Testpmd output
The next command
What's extra is the welcome screen with the first command we've sent.
We don't capture any output right after establishing the channel so it
all stays there to be captured by the first command we send.
> Given it's not particularly explained, I thought having two command
> prompts (especially a trailing one) was an error. The main reason behind
> this is that when we go to parse the port info, the last entry which is
> "device private info" appears to be open ended, and I couldn't gather
> much information from the testpmd source code. So I opted to parse
> everything until the end. With a trailing command prompt this meant
> that: device_private_info="....testpmd> ".
So the command output doesn't end with a newline? What's the exact
output that's captured?
On 17/04/2024 14:06, Juraj Linkeš wrote:
> Actually, filtering out the last prompt is fine. I got this mixed up
> with processing the last prompt. We must process the last prompt, but
> we don't need to print it (and there's not much reason to do so).
Yeah, my confusion was about displaying the last prompt indeed. I
recognise we need to process it to use it as an end reading symbol.
> And the reason we must process it is because we're consuming the
> output line by line. A line appears in (or is yielded by) self._stdout
> only after a newline appears in the output. For a typical command
> output:
> prompt> command\n
> <command output>\n
> prompt>
>
> The last line in self._stdout is the last line of <command output>
> because that's the last line with a newline. We send
> _command_extra_chars to force another prompt into the output:
> prompt> command\n
> <command output>\n
> prompt>\n
> prompt>
>
> Now the last line with a newline contains a prompt. The actual extra
> trailing prompt is then pushed to the next command execution:
> prompt_from_command1> command2\n
> <command2 output>\n
> <prompt_from_command2>
>
> Maybe you already knew this but maybe we could archive this and point
> to it in case anyone asks. :-)
I think the confusion is the actual end meaning of this. So this is just
so that the log for the next command starts with `testpmd> `... as
otherwise it'd be consumed by the previous one.
One of the original reasons for reporting the logging improvements
Bugzilla ticket 1361 was that perhaps we could provide the user with a
the full stdout/err buffer piped into a file without any other DTS
details. As I thought that for debugging reasons it would have been
easier to read. Thus avoiding this kind of trickery. And the 10 lines as
you mentioned in the ticket could just be the contents of the buffer.
>>> One thing we could improve though is removing the distribution welcome
>>> message from logs, or at least separate it from the first command sent
>>> with the interactive shell. The second option will allow us to see
>>> clearly that an interactive session has been established, although we
>>> could just emit a shorter log (something like "Started a testpmd
>>> session" and then flush the welcome screen output).
>>
>> I am not sure what you are referring to exactly, could you also expand
>> more on this please?
>>
>
> Let's look at logs. The first thing to note is we don't log when we
> start the interactive session. The first log from the session is the
> output from the first command, such as testpmd:
> 2024/04/11 13:29:27 - test_suite - dts.SUT 1 - INFO - Sending: 'sudo
> -- sh -c '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd -l
> 1-2 -n 4 --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
> 0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
> --tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
> --hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
> --tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall''
> 2024/04/11 13:29:28 - test_suite - dts.SUT 1 - DEBUG - Got output:
> Welcome to Ubuntu 22.04.2 LTS (GNU/Linux 5.15.0-97-generic x86_64)^M
> <the welcome screen continues>
> Last login: Thu Apr 11 11:24:44 2024 from 192.168.122.1^M^M
> sudo -- sh -c '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd
> -l 1-2 -n 4 --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
> 0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
> --tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
> --hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
> --tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall'^M
> ^M
> ^[[?2004hjlinkes@dts-sut:~$ sudo -- sh -c
> '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd -l 1-2 -n 4
> --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
> 0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
> --tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
> --hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
> --tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall'^M
> ^[[?2004l^M^M
> EAL: Detected CPU lcores: 4^M
> <tespmd startup continues>
> Done^M
> testpmd> ^M^M
>
> 2024/04/11 13:29:28 - test_suite - dts.SUT 1 - INFO - Sending: 'show
> device info all'
>
> What we see is the testpmd command being sent and then the output is:
> Welcome screen
> Testpmd command we've sent
> Testpmd command echoed with the os prompt
> Testpmd output
> The next command
>
> What's extra is the welcome screen with the first command we've sent.
> We don't capture any output right after establishing the channel so it
> all stays there to be captured by the first command we send.
Oh, I see. Didn't even realise this gets captured!
>> Given it's not particularly explained, I thought having two command
>> prompts (especially a trailing one) was an error. The main reason behind
>> this is that when we go to parse the port info, the last entry which is
>> "device private info" appears to be open ended, and I couldn't gather
>> much information from the testpmd source code. So I opted to parse
>> everything until the end. With a trailing command prompt this meant
>> that: device_private_info="....testpmd> ".
>
> So the command output doesn't end with a newline? What's the exact
> output that's captured?
The command output does end with a new line, the problem is that the
last data entry may or may not be a multi-line one, and I have no way to
delimit it. So the current behaviour is capture everything until the
end, and when the end is ` testpmd> `, this becomes part of it. Example
of actual output:
********************* Infos for port 0 *********************
<snip>
Device error handling mode: none
Device private info:
none
testpmd>
Here `Device error handling mode` is printed as if it's on a
single-line, so I use \n as delimiter. Whereas `Device private info`
just goes on a new line and if unset it prints `none`, otherwise it
prints whatever the device has to print. Given I cannot assume how
assume how the format will be (I don't even have examples available)...
just parse till the end.
On Wed, Apr 17, 2024 at 4:17 PM Luca Vizzarro <Luca.Vizzarro@arm.com> wrote:
>
> On 17/04/2024 14:06, Juraj Linkeš wrote:
> > Actually, filtering out the last prompt is fine. I got this mixed up
> > with processing the last prompt. We must process the last prompt, but
> > we don't need to print it (and there's not much reason to do so).
>
> Yeah, my confusion was about displaying the last prompt indeed. I
> recognise we need to process it to use it as an end reading symbol.
>
> > And the reason we must process it is because we're consuming the
> > output line by line. A line appears in (or is yielded by) self._stdout
> > only after a newline appears in the output. For a typical command
> > output:
> > prompt> command\n
> > <command output>\n
> > prompt>
> >
> > The last line in self._stdout is the last line of <command output>
> > because that's the last line with a newline. We send
> > _command_extra_chars to force another prompt into the output:
> > prompt> command\n
> > <command output>\n
> > prompt>\n
> > prompt>
> >
> > Now the last line with a newline contains a prompt. The actual extra
> > trailing prompt is then pushed to the next command execution:
> > prompt_from_command1> command2\n
> > <command2 output>\n
> > <prompt_from_command2>
> >
> > Maybe you already knew this but maybe we could archive this and point
> > to it in case anyone asks. :-)
>
> I think the confusion is the actual end meaning of this. So this is just
> so that the log for the next command starts with `testpmd> `... as
> otherwise it'd be consumed by the previous one.
>
> One of the original reasons for reporting the logging improvements
> Bugzilla ticket 1361 was that perhaps we could provide the user with a
> the full stdout/err buffer piped into a file without any other DTS
> details. As I thought that for debugging reasons it would have been
> easier to read. Thus avoiding this kind of trickery. And the 10 lines as
> you mentioned in the ticket could just be the contents of the buffer.
>
I mentioned the last 10 executed commands, not lines, so that's
different. The idea with the full stdout/err piped into a file sounds
very interesting, that could be helpful for debugging.
> >>> One thing we could improve though is removing the distribution welcome
> >>> message from logs, or at least separate it from the first command sent
> >>> with the interactive shell. The second option will allow us to see
> >>> clearly that an interactive session has been established, although we
> >>> could just emit a shorter log (something like "Started a testpmd
> >>> session" and then flush the welcome screen output).
> >>
> >> I am not sure what you are referring to exactly, could you also expand
> >> more on this please?
> >>
> >
> > Let's look at logs. The first thing to note is we don't log when we
> > start the interactive session. The first log from the session is the
> > output from the first command, such as testpmd:
> > 2024/04/11 13:29:27 - test_suite - dts.SUT 1 - INFO - Sending: 'sudo
> > -- sh -c '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd -l
> > 1-2 -n 4 --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
> > 0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
> > --tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
> > --hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
> > --tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall''
> > 2024/04/11 13:29:28 - test_suite - dts.SUT 1 - DEBUG - Got output:
> > Welcome to Ubuntu 22.04.2 LTS (GNU/Linux 5.15.0-97-generic x86_64)^M
> > <the welcome screen continues>
> > Last login: Thu Apr 11 11:24:44 2024 from 192.168.122.1^M^M
> > sudo -- sh -c '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd
> > -l 1-2 -n 4 --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
> > 0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
> > --tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
> > --hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
> > --tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall'^M
> > ^M
> > ^[[?2004hjlinkes@dts-sut:~$ sudo -- sh -c
> > '/tmp/dpdk-22.07/x86_64-linux-native-gcc/app/dpdk-testpmd -l 1-2 -n 4
> > --file-prefix=dpdk_71695_20240411132902 -a 0000:07:00.0 -a
> > 0000:08:00.0 -- -i --nb-cores=1 --port-topology=paired --numa
> > --tx-ip=198.18.0.1,198.18.0.2 --tx-udp=9 --forward-mode=io
> > --hairpin-mode=0x0 --rx-offloads=0x0 --rx-mq-mode=0x7
> > --tx-offloads=0x0 --mask-event=intr_lsc --no-mlockall'^M
> > ^[[?2004l^M^M
> > EAL: Detected CPU lcores: 4^M
> > <tespmd startup continues>
> > Done^M
> > testpmd> ^M^M
> >
> > 2024/04/11 13:29:28 - test_suite - dts.SUT 1 - INFO - Sending: 'show
> > device info all'
> >
> > What we see is the testpmd command being sent and then the output is:
> > Welcome screen
> > Testpmd command we've sent
> > Testpmd command echoed with the os prompt
> > Testpmd output
> > The next command
> >
> > What's extra is the welcome screen with the first command we've sent.
> > We don't capture any output right after establishing the channel so it
> > all stays there to be captured by the first command we send.
>
> Oh, I see. Didn't even realise this gets captured!
>
> >> Given it's not particularly explained, I thought having two command
> >> prompts (especially a trailing one) was an error. The main reason behind
> >> this is that when we go to parse the port info, the last entry which is
> >> "device private info" appears to be open ended, and I couldn't gather
> >> much information from the testpmd source code. So I opted to parse
> >> everything until the end. With a trailing command prompt this meant
> >> that: device_private_info="....testpmd> ".
> >
> > So the command output doesn't end with a newline? What's the exact
> > output that's captured?
>
> The command output does end with a new line, the problem is that the
> last data entry may or may not be a multi-line one, and I have no way to
> delimit it. So the current behaviour is capture everything until the
> end, and when the end is ` testpmd> `, this becomes part of it. Example
> of actual output:
>
> ********************* Infos for port 0 *********************
> <snip>
> Device error handling mode: none
> Device private info:
> none
> testpmd>
>
> Here `Device error handling mode` is printed as if it's on a
> single-line, so I use \n as delimiter. Whereas `Device private info`
> just goes on a new line and if unset it prints `none`, otherwise it
> prints whatever the device has to print. Given I cannot assume how
> assume how the format will be (I don't even have examples available)...
> just parse till the end.
>
Ok this makes sense now. Let's definitely drop the last prompt, there
aren't any upsides (that I can see) and this sort of downside may
occur elsewhere.
On Thu, Apr 18, 2024 at 2:31 AM Juraj Linkeš <juraj.linkes@pantheon.tech> wrote:
>
<snip>
>
> Ok this makes sense now. Let's definitely drop the last prompt, there
> aren't any upsides (that I can see) and this sort of downside may
> occur elsewhere.
+1
@@ -132,11 +132,11 @@ def send_command(self, command: str, prompt: str | None = None) -> str:
self._stdin.flush()
out: str = ""
for line in self._stdout:
- out += line
if prompt in line and not line.rstrip().endswith(
command.rstrip()
): # ignore line that sent command
break
+ out += line
self._logger.debug(f"Got output: {out}")
return out