Re: [PATCH 1/5] dts: fix InteractiveShell command prompt filtering

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

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.