On Wed, Apr 17, 2024 at 4:17 PM Luca Vizzarro <luca.vizza...@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.
