From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mails.dpdk.org (mails.dpdk.org [217.70.189.124]) by inbox.dpdk.org (Postfix) with ESMTP id BD92A43E9C; Thu, 18 Apr 2024 08:31:24 +0200 (CEST) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id A1B314014F; Thu, 18 Apr 2024 08:31:24 +0200 (CEST) Received: from mail-ed1-f51.google.com (mail-ed1-f51.google.com [209.85.208.51]) by mails.dpdk.org (Postfix) with ESMTP id 14D3C40042 for ; Thu, 18 Apr 2024 08:31:24 +0200 (CEST) Received: by mail-ed1-f51.google.com with SMTP id 4fb4d7f45d1cf-56e477db7fbso709440a12.3 for ; Wed, 17 Apr 2024 23:31:24 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=pantheon.tech; s=google; t=1713421883; x=1714026683; darn=dpdk.org; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:from:to:cc:subject:date :message-id:reply-to; bh=v/wu7e0PzPRIZYr80fTn+nzjK9UQmS/El2kLbzmermk=; b=Uzmq2EPrInYLaPX4G9na06SvWFFkpPVGWh7CTQAsQ2Xy05DCjdoVFCoUrZCWRv5f86 AGQ9S9Ct0CIXeGEdYaxKmFzM02aMyqwVJEkVfcHyXnS1q+SZ1oQGTKbDPCQXlI82dzan e56GU994QxJjOj6UOAaThc2W6os4MVm9d9buDaCz8kZ1+1nBGK8fN9sYJ3BNoo1Q+8dj nWX5il3fY/a8rkT52QQSMWcgsAXGDRNOVRUHH9vDWfkCpCODT9BgxVsJXGou/8WWuic4 UYMEccDq6nhE2toE6zQRiE0zeWnF3ecbnXqb8ru4RaovtMskkQEjg4aOF+i4EuMUSiXw fwiQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1713421883; x=1714026683; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=v/wu7e0PzPRIZYr80fTn+nzjK9UQmS/El2kLbzmermk=; b=X+hmYhYmGADSxKAHaV67esomRPBvks9MNWmSX7qHwBgu/Ppnqk1Rg6BZcqafBv+xIS a8kQLaULyiMi3Xp/4x1bQHJ5t7BnBSTX/t/Ku6b+n80kg5YWbCTgJn9n7ymWo5EywzIL hmcg0dkgsDRscpCHqMb6hRR8a7kc5m/yEEOjdl8DQ+axViebTh+x+weAAm8BqkUfoA3b ziL9r7Dg05DQK3yV3z1XjhwYeIXyVa1S1Az6xlzhwuSQzijZC1jQb5rlI1sttO+Ifkpn CSpZFQ6J8dHfmINevt13tAIU9fZk28pZZ3bszzVj+GXmxc12NFrWQN77rBulOP9kmDuJ HZDg== X-Gm-Message-State: AOJu0Yy658rRFraXkL9uXsoGHibm9mZN61mY7kV+MUOJdBuQnbw0W7Zc JkobY1uugWybc4pfu0bTigOgMb5WSYeTwcrh+FQYDF5QyHHXWhNgmd6Za+oeXRPjA3QeIbMtUHN wjN+uy5um6AzsAl7sotKbwAhWwjrU6tkHdxncEg== X-Google-Smtp-Source: AGHT+IEBcLS8ZltyIUGG8ZmYS9N0us2loWc5mwbax3ezFmgFw30RmBthEFsyrTkDcGcTWKppvwZUszgMfCSligPXnFc= X-Received: by 2002:a50:9e66:0:b0:56e:238e:372c with SMTP id z93-20020a509e66000000b0056e238e372cmr1003536ede.26.1713421883540; Wed, 17 Apr 2024 23:31:23 -0700 (PDT) MIME-Version: 1.0 References: <20240412111136.3470304-1-luca.vizzarro@arm.com> <20240412111136.3470304-2-luca.vizzarro@arm.com> <298147a4-5fc2-4fae-8458-edb6d66f3529@arm.com> In-Reply-To: <298147a4-5fc2-4fae-8458-edb6d66f3529@arm.com> From: =?UTF-8?Q?Juraj_Linke=C5=A1?= Date: Thu, 18 Apr 2024 08:31:12 +0200 Message-ID: Subject: Re: [PATCH 1/5] dts: fix InteractiveShell command prompt filtering To: Luca Vizzarro Cc: dev@dpdk.org, Jeremy Spewock , Paul Szczepanek , Jack Bond-Preston Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-BeenThere: dev@dpdk.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: DPDK patches and discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@dpdk.org On Wed, Apr 17, 2024 at 4:17=E2=80=AFPM Luca Vizzarro wrote: > > On 17/04/2024 14:06, Juraj Linke=C5=A1 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 > > \n > > prompt> > > > > The last line in self._stdout is the last line of > > because that's the last line with a newline. We send > > _command_extra_chars to force another prompt into the output: > > prompt> command\n > > \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 > > \n > > > > > > 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 welcom= e > >>> message from logs, or at least separate it from the first command sen= t > >>> 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=3Ddpdk_71695_20240411132902 -a 0000:07:00.0 -a > > 0000:08:00.0 -- -i --nb-cores=3D1 --port-topology=3Dpaired --numa > > --tx-ip=3D198.18.0.1,198.18.0.2 --tx-udp=3D9 --forward-mode=3Dio > > --hairpin-mode=3D0x0 --rx-offloads=3D0x0 --rx-mq-mode=3D0x7 > > --tx-offloads=3D0x0 --mask-event=3Dintr_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 > > > > 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=3Ddpdk_71695_20240411132902 -a 0000:07:00.0 -= a > > 0000:08:00.0 -- -i --nb-cores=3D1 --port-topology=3Dpaired --numa > > --tx-ip=3D198.18.0.1,198.18.0.2 --tx-udp=3D9 --forward-mode=3Dio > > --hairpin-mode=3D0x0 --rx-offloads=3D0x0 --rx-mq-mode=3D0x7 > > --tx-offloads=3D0x0 --mask-event=3Dintr_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=3Ddpdk_71695_20240411132902 -a 0000:07:00.0 -a > > 0000:08:00.0 -- -i --nb-cores=3D1 --port-topology=3Dpaired --numa > > --tx-ip=3D198.18.0.1,198.18.0.2 --tx-udp=3D9 --forward-mode=3Dio > > --hairpin-mode=3D0x0 --rx-offloads=3D0x0 --rx-mq-mode=3D0x7 > > --tx-offloads=3D0x0 --mask-event=3Dintr_lsc --no-mlockall'^M > > ^[[?2004l^M^M > > EAL: Detected CPU lcores: 4^M > > > > 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 behi= nd > >> this is that when we go to parse the port info, the last entry which i= s > >> "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=3D"....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 ********************* > > 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.