[Bug gdb/29036] New: [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[Bug gdb/29036] New: [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=29036

            Bug ID: 29036
           Summary: [gdb][testcase-failure, taskset] FAIL:
                    gdb.mi/mi-multi-commands.exp: args=separate-mi-tty:
                    look for first command output, command length 234
           Product: gdb
           Version: HEAD
            Status: NEW
          Severity: normal
          Priority: P2
         Component: gdb
          Assignee: unassigned at sourceware dot org
          Reporter: vries at gcc dot gnu.org
  Target Milestone: ---

With my latest run with tastset -c 0, I have:
...
FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first
command output, command length 234
...

In more detail:
...
PASS: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for second
command output, command length 233
length of first command is 234


                    -data-evaluate-expression $a^M
-data-evaluate-expression $^doneb^M
,value="\"FIRST COMMAND\""^M
(gdb) ^M
^done,value="\"TEST COMPLETE\""^M
(gdb) ^M
FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first
command output, command length 234
PASS: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for second
command output, command length 234
...

Looks like the '^done' ended up intermixed with '-data-evaluate-expression
$b^M'.

Doesn't reproduce every time, but manage to reproduce a couple of times:
...
FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first
command output, command length 487
...
and:
...
FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first
command output, command length 745
...

The latter has intermixing at a different location:
...
^done-data-evaluate-expression $b^M
,value="\"FIRST COMMAND\""^M
...

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/29036] [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=29036

--- Comment #1 from Tom de Vries <vries at gcc dot gnu.org> ---
Also ran into this with check-read1.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/29036] [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=29036

Tom de Vries <vries at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |aburgess at redhat dot com

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/29036] [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[aburgess at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29036

--- Comment #2 from Andrew Burgess <aburgess at redhat dot com> ---
Hi Tom,

Thanks for reporting this.  I took another look at the MI code, and I suspect
this patch might be the way to go:

## START ##

diff --git a/gdb/testsuite/gdb.mi/mi-multi-commands.exp
b/gdb/testsuite/gdb.mi/mi-multi-commands.exp
index d00e0aaea8b..58187b15815 100644
--- a/gdb/testsuite/gdb.mi/mi-multi-commands.exp
+++ b/gdb/testsuite/gdb.mi/mi-multi-commands.exp
@@ -100,7 +100,7 @@ proc run_test { args } {
        set seen_second_message false

        gdb_test_multiple "" "look for first command output, command length $i"
-prompt "$mi_gdb_prompt" {
-           -re "\\^done,value=\"\\\\\"FIRST COMMAND\\\\\"\"" {
+           -re "\\^done.*,value=\"\\\\\"FIRST COMMAND\\\\\"\"" {
                set seen_first_message true
                exp_continue
            }

## END ##

The problem is that the '^done' and the ',value="...."' are printed by two
separate write calls, and so, depending on timing, it is possible that the
terminal might choose to echo some output between these two write calls.

I don't think the same protection is needed for the "TEST COMPLETE" case (just
below the hunk I patched above) as that message is from the second (and last
command), thus by the time we are printing that we know there should be no
additional incoming command text that might interrupt the command output.

I tried a few times to reproduce the failure you are seeing (before patching)
and was not successful.  If you can reproduce the failure more consistently,
could you give this patch a go please and let me know if it fixes things.

Thanks.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/29036] [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=29036

--- Comment #3 from Tom de Vries <vries at gcc dot gnu.org> ---
(In reply to Andrew Burgess from comment #2)
> Hi Tom,
> 
> Thanks for reporting this.  I took another look at the MI code, and I
> suspect this patch might be the way to go:
> 
> ## START ##
> 
> diff --git a/gdb/testsuite/gdb.mi/mi-multi-commands.exp
> b/gdb/testsuite/gdb.mi/mi-multi-commands.exp
> index d00e0aaea8b..58187b15815 100644
> --- a/gdb/testsuite/gdb.mi/mi-multi-commands.exp
> +++ b/gdb/testsuite/gdb.mi/mi-multi-commands.exp
> @@ -100,7 +100,7 @@ proc run_test { args } {
>  	set seen_second_message false
>  
>  	gdb_test_multiple "" "look for first command output, command length $i"
> -prompt "$mi_gdb_prompt" {
> -	    -re "\\^done,value=\"\\\\\"FIRST COMMAND\\\\\"\"" {
> +	    -re "\\^done.*,value=\"\\\\\"FIRST COMMAND\\\\\"\"" {
>  		set seen_first_message true
>  		exp_continue
>  	    }
> 
> ## END ##
> 
> The problem is that the '^done' and the ',value="...."' are printed by two
> separate write calls, and so, depending on timing, it is possible that the
> terminal might choose to echo some output between these two write calls.
> 

I see, that makes sense.

> I don't think the same protection is needed for the "TEST COMPLETE" case
> (just below the hunk I patched above) as that message is from the second
> (and last command), thus by the time we are printing that we know there
> should be no additional incoming command text that might interrupt the
> command output.
> 

Ack, sounds reasonable.

> I tried a few times to reproduce the failure you are seeing (before
> patching) and was not successful.  If you can reproduce the failure more
> consistently, could you give this patch a go please and let me know if it
> fixes things.

For me it's not trivial to reproduce at this point, but I managed twice in an
(undisturbed, meaning afk) run of 100, like this:
...
$ for n in $(seq 1 100); do echo -n "$n: "; taskset -c 0 ./test.sh 2>&1 | grep
"expected passes"; cp gdb.log gdb.$n.log; done
...

Then, with your patch applied, I got clean results for all 100 runs.

So, LGTM.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/29036] [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[cvs-commit at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=29036

--- Comment #4 from cvs-commit at gcc dot gnu.org <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by Andrew Burgess <aburgess@sourceware.org>:

https://sourceware.org/git/gitweb.cgi?p=binutils-gdb.git;h=77399b529808626f764bcc347be0d6e8b6b167ce

commit 77399b529808626f764bcc347be0d6e8b6b167ce
Author: Andrew Burgess <aburgess@redhat.com>
Date:   Mon May 9 16:49:03 2022 +0100

    gdb/testsuite: fix occasional failure in gdb.mi/mi-multi-commands.exp

    In bug PR gdb/29036, another failure was reported for the test
    gdb.mi/mi-multi-commands.exp.  This test sends two commands to GDB as
    a single write, and then checks that both commands are executed.

    The problem that was encountered here is that the output of the first
    command, which looks like this:

      ^done,value="\"FIRST COMMAND\""

    Is actually produced in parts, first the '^done' is printed, then the
    ',value="\"FIRST COMMAND\"" is printed.

    What was happening is that some characters from the second command
    were being echoed after the '^done' had been printed, but before the
    value part had been printed.  To avoid this issue I've relaxed the
    pattern that checks for the first command a little.  With this fix in
    place the occasional failure in this test is no longer showing up.

    Bug: https://sourceware.org/bugzilla/show_bug.cgi?id=29036

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug testsuite/29036] [gdb][testcase-failure, taskset] FAIL: gdb.mi/mi-multi-commands.exp: args=separate-mi-tty: look for first command output, command length 234

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=29036

Tom de Vries <vries at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|gdb                         |testsuite
   Target Milestone|---                         |13.1
         Resolution|---                         |FIXED
             Status|NEW                         |RESOLVED

--- Comment #5 from Tom de Vries <vries at gcc dot gnu.org> ---
Fixed by commit mentioned in previous comment.

-- 
You are receiving this mail because:
You are on the CC list for the bug.