[v2] Enable 'set print inferior-events' and cleanup attach/detach messages

  On 01/31/2018 04:57 PM, Sergio Durigan Junior wrote:
> This is a followup of Pedro's suggestion to turn 'set print
> inferior-events' always on, and do some cleanup on the messages
> printed by GDB when attaching/detaching a inferior, or when it exits.
> 
> To make sure that the patch is correct, I've tested it with a handful
> of combinations of 'set follow-fork-mode', 'set detach-on-fork' and
> 'set print inferior-events'.  In the end, I decided to make my
> hand-made test into an official testcase.  More on that below.
> 
> I've also made a few modifications to messages that are printed when
> 'set print inferior-events' is on.  For example, a few of the messages
> did not contain the '[' and ']' as prefix/suffix, which led to a few
> inconsistencies like:
> 
>   Attaching after process 22995 fork to child process 22995.
>   [New inferior 22999]
>   Detaching after fork from child process 22999.
>   [Inferior 22995 detached]
>   [Inferior 2 (process 22999) exited normally]
> 
> So I took the opportunity and included the square brackets where
> applicable.
> 
> As suggested by Pedro, the "[Inferior %d exited]" message from
> 'exit_inferior' has been removed, because it got duplicated when
> 'inferior-events' is on.  I'm also using the
> 'add_{thread,inferior}_silent' versions (instead of their verbose
> counterparts) on some locations, also to avoid duplicated messages.

Can you give examples of the latter?  (what led to 'add_{thread,inferior}_silent')

> As for the tests, the configuration options being exercised are:
> 
> - follow-fork-mode: child/parent
> - detach-on-fork: on/off
> - print inferior-events: on/off
> 
> Built and regtested on BuildBot, without regressions.

Can you update the log to include examples of what the new
output looks like?  Both "set inferior-events on/off".
That makes it much easier to review/discuss/evaluate.

Can you say what happens to the output with
"set print inferior-events off" compared to current master?
Does output change in that case compared to today?  Not changing
output is not the goal, but it'd be good to be clear.

I'm experimenting a bit, and I'm seeing some inconsistencies
that I wonder whether we should consider revising.

For example, with "set print inferior-events on/off", we see,
for detach:

 (gdb) detach
 Detaching from program: /home/pedro/gdb/build/gdb/testsuite/outputs/gdb.base/foll-fork/foll-fork, process 2685
 [Inferior 2685 detached]
 (gdb) 

But for kill, we see:

 (gdb) k
 Kill the program being debugged? (y or n) y
 (gdb) 

Should detach vs kill be consistent?  I'd think so off hand.

Another thing is related to what I was proposing in the other
thread.  With the patch, we say:

 (gdb) c
 Continuing.
 [New inferior 3239]
 [Inferior 5 (process 3236) exited normally]

The "New inferior 3239" one is showing the target process ID,
which is confusing.  I think we should tweak to mention the
inferior ID, like:

 (gdb) c
 Continuing.
 [New inferior 5 (process 3236)]
 [Inferior 5 (process 3236) exited normally]


Looking at follow-fork child, detach-on-fork on, we see:

 [Attaching after process 12069 fork to child process 12069.]
 [New inferior 12073]
 [Detaching after fork from child process 12073.]
 [Inferior 12069 detached]
 [Inferior 2 (process 12073) exited normally]

That could use some normalization to make messages consistent
with one another.

 [Attaching after process 12069 fork to child process 12069.]
 [New inferior 2 (process 12073)]
 [Detaching after fork from child process 12073.]
 [Inferior 1 (process 12069) detached]
 [Inferior 2 (process 12073) exited normally]

(see more about this case below)

>  
>  	      target_terminal::ours_for_output ();
>  	      fprintf_filtered (gdb_stdlog,
> -				_("Detaching after %s from child %s.\n"),
> +				_("[Detaching after %s from child %s.]\n"),
>  				has_vforked ? "vfork" : "fork",
>  				target_pid_to_str (process_ptid));

I also noticed that this ends up with a period at the end, while
other [] notices don't, like (playing with "set detach-on-fork on"):

 [Detaching after fork from child process 3417.]
 [Inferior 5 (process 3416) exited normally]

> diff --git a/gdb/testsuite/gdb.base/fork-detach-info.exp b/gdb/testsuite/gdb.base/fork-detach-info.exp
> new file mode 100644
> index 0000000000..aa9a85c0d5
> --- /dev/null
> +++ b/gdb/testsuite/gdb.base/fork-detach-info.exp

Maybe this could use a different name, since this isn't
just about _detach_ info?

fork-print-inferior-events.exp, maybe.

> @@ -0,0 +1,68 @@
> +# This testcase is part of GDB, the GNU debugger.
> +
> +# Copyright 2007-2018 Free Software Foundation, Inc.
> +
> +# This program is free software; you can redistribute it and/or modify
> +# it under the terms of the GNU General Public License as published by
> +# the Free Software Foundation; either version 3 of the License, or
> +# (at your option) any later version.
> +#
> +# This program is distributed in the hope that it will be useful,
> +# but WITHOUT ANY WARRANTY; without even the implied warranty of
> +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
> +# GNU General Public License for more details.
> +#
> +# You should have received a copy of the GNU General Public License
> +# along with this program.  If not, see <http://www.gnu.org/licenses/>.
> +

Please add an intro comment mentioning what the testcase is about.

> +if { [use_gdb_stub] || [target_info gdb_protocol] == "extended-remote" } {
> +    untested "not supported on gdbserver"
> +    return
> +}

I see that this relies on "run", so can't work with use_gdb_stub.
But why is this not supported with extended-remote gdbserver?

> +
> +standard_testfile
> +
> +if { [prepare_for_testing "failed to prepare" $testfile $srcfile debug] } {
> +    return -1
> +}
> +
> +# This is the expected output for each of the test combinations
> +# below.  The order here is important:
> +#
> +#    follow-fork: child; detach-on-fork: on; inferior-events: on
> +#    follow-fork: child; detach-on-fork: on; inferior-events: off
> +#    follow-fork: child; detach-on-fork: off; inferior-events: on
> +#    follow-fork: child; detach-on-fork: off; inferior-events: off
> +#    follow-fork: parent; detach-on-fork: on; inferior-events: on
> +#    follow-fork: parent; detach-on-fork: on; inferior-events: off
> +#    follow-fork: parent; detach-on-fork: off; inferior-events: on
> +#    follow-fork: parent; detach-on-fork: off; inferior-events: off
> +set expected_output [list \
> +    "\\\[Attaching after process $decimal fork to child process $decimal\\.\\\]\r\n\\\[New inferior $decimal\\\]\r\n\\\[Detaching after fork from child process $decimal\\.\\\]\r\n\\\[Inferior $decimal detached\\\]\r\n\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
> +    "\\\[Attaching after process $decimal fork to child process $decimal\\.\\\]\r\n\\\[New inferior $decimal\\\]\r\n\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
> +    "\\\[Detaching after fork from child process $decimal\\.\\\]\r\n\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
> +    "\\\[New inferior $decimal\\\]\r\n\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]"]
> +

I had a lot of trouble making sense of this big blurb of expected output.
I didn't know exactly what to suggest, so I played with it locally, and
I think putting the individual messages in variables helps a lot.
And then, I noticed that all the cases end up with 

  \\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]

so we can factor it out.

And then, if we iterate over print_inferior_events first, then
it's super clear that the "set print-inferior-events off"
case is always "no output".  See attached patch on top of yours.

The infrun.c hunk is there in my patch because while playing with
this, I noticed that gdb says that it's detaching the child
(and uses the child's pid), when in fact it is detaching the
parent!

I.e., currently, "set follow-fork child", "set detach-on-fork on":

 [Attaching after process 12069 fork to child process 12069.]
 [New inferior 2 12073]
 [Detaching after fork from child process 12073.]   <<< nope, it's detaching 12069 / the parent
 [Inferior 12069 detached]                          <<< see?
 [Inferior 2 (process 12073) exited normally]

after that fix:

 [Attaching after process 18500 fork to child process 18500.]
 [New inferior 18504]
 [Detaching after fork from parent process 18500.]
 [Inferior 18500 detached]
 [Inferior 2 (process 18504) exited normally]

Thanks,
Pedro Alves
  

On Thursday, February 01 2018, Pedro Alves wrote:

> On 01/31/2018 04:57 PM, Sergio Durigan Junior wrote:
>> This is a followup of Pedro's suggestion to turn 'set print
>> inferior-events' always on, and do some cleanup on the messages
>> printed by GDB when attaching/detaching a inferior, or when it exits.
>> 
>> To make sure that the patch is correct, I've tested it with a handful
>> of combinations of 'set follow-fork-mode', 'set detach-on-fork' and
>> 'set print inferior-events'.  In the end, I decided to make my
>> hand-made test into an official testcase.  More on that below.
>> 
>> I've also made a few modifications to messages that are printed when
>> 'set print inferior-events' is on.  For example, a few of the messages
>> did not contain the '[' and ']' as prefix/suffix, which led to a few
>> inconsistencies like:
>> 
>>   Attaching after process 22995 fork to child process 22995.
>>   [New inferior 22999]
>>   Detaching after fork from child process 22999.
>>   [Inferior 22995 detached]
>>   [Inferior 2 (process 22999) exited normally]
>> 
>> So I took the opportunity and included the square brackets where
>> applicable.
>> 
>> As suggested by Pedro, the "[Inferior %d exited]" message from
>> 'exit_inferior' has been removed, because it got duplicated when
>> 'inferior-events' is on.  I'm also using the
>> 'add_{thread,inferior}_silent' versions (instead of their verbose
>> counterparts) on some locations, also to avoid duplicated messages.
>
> Can you give examples of the latter?  (what led to 'add_{thread,inferior}_silent')

[ Resurrecting the thread... ]

Yes.

Using add_thread, set print inferior-events on, set follow-fork-mode
child, and set detach-on-fork on, I see:

  (gdb) run
  Starting program: a.out
  [Attaching after process 25088 fork to child process 25088.]
  [New inferior 25092]   <--- duplicated
  [Detaching after fork from child process 25092.]
  [Inferior 25088 detached]
  [New process 25092]    <--- duplicated
  [Inferior 2 (process 25092) exited normally]

But using add_thread_silent (with the same configuration as before):

  (gdb) run
  Starting program: a.out
  [Attaching after process 26807 fork to child process 26807.]
  [New inferior 26811]
  [Detaching after fork from child process 26811.]
  [Inferior 26807 detached]
  [Inferior 2 (process 26811) exited normally]

So we get rid of one duplicated line, produced by add_thread.

As for the add_inferior_silent case (on
inferiors.c:initialize_inferiors), it's useful to get rid of the:

  [New inferior 0]

message that happens when initializing GDB.

>> As for the tests, the configuration options being exercised are:
>> 
>> - follow-fork-mode: child/parent
>> - detach-on-fork: on/off
>> - print inferior-events: on/off
>> 
>> Built and regtested on BuildBot, without regressions.
>
> Can you update the log to include examples of what the new
> output looks like?  Both "set inferior-events on/off".
> That makes it much easier to review/discuss/evaluate.

Yes, that's a good idea.  Sorry for not doing that earlier.

> Can you say what happens to the output with
> "set print inferior-events off" compared to current master?
> Does output change in that case compared to today?  Not changing
> output is not the goal, but it'd be good to be clear.

Based on a test using an inferior that just forks:

  #include <unistd.h>
  int main () { fork (); return 0; }

And with set follow-fork-mode child, current master does:

  (gdb) r                                        
  Starting program: a.out
  [New process 5702]
  [Inferior 2 (process 5702) exited normally]

And my patch does:

  (gdb) r
  Starting program: a.out
  [Inferior 2 (process 5993) exited normally]

So yeah, we end up losing the notification of "[New process %d]" there,
which comes from thread.c:add_thread_with_info.

Pedantically, the "[Inferior 2 ... exited normally]" message should also
be considered an inferior event, and maybe should not be printed.

> I'm experimenting a bit, and I'm seeing some inconsistencies
> that I wonder whether we should consider revising.
>
> For example, with "set print inferior-events on/off", we see,
> for detach:
>
>  (gdb) detach
>  Detaching from program: /home/pedro/gdb/build/gdb/testsuite/outputs/gdb.base/foll-fork/foll-fork, process 2685
>  [Inferior 2685 detached]
>  (gdb) 
>
> But for kill, we see:
>
>  (gdb) k
>  Kill the program being debugged? (y or n) y
>  (gdb) 
>
> Should detach vs kill be consistent?  I'd think so off hand.

Hm, alright.  I can modify kill_command and print the message.  WDYT:

  (gdb) kill 
  Kill the program being debugged? (y or n) y
  [Inferior 14161 has been killed]

?

> Another thing is related to what I was proposing in the other
> thread.  With the patch, we say:
>
>  (gdb) c
>  Continuing.
>  [New inferior 3239]
>  [Inferior 5 (process 3236) exited normally]
>
> The "New inferior 3239" one is showing the target process ID,
> which is confusing.  I think we should tweak to mention the
> inferior ID, like:
>
>  (gdb) c
>  Continuing.
>  [New inferior 5 (process 3236)]
>  [Inferior 5 (process 3236) exited normally]

This looks a bit redundant to me, but I think it's the best way (at
least I couldn't think of a better one).

Consider it done.

> Looking at follow-fork child, detach-on-fork on, we see:
>
>  [Attaching after process 12069 fork to child process 12069.]
>  [New inferior 12073]
>  [Detaching after fork from child process 12073.]
>  [Inferior 12069 detached]
>  [Inferior 2 (process 12073) exited normally]
>
> That could use some normalization to make messages consistent
> with one another.
>
>  [Attaching after process 12069 fork to child process 12069.]
>  [New inferior 2 (process 12073)]
>  [Detaching after fork from child process 12073.]
>  [Inferior 1 (process 12069) detached]
>  [Inferior 2 (process 12073) exited normally]
>
> (see more about this case below)
>
>>  
>>  	      target_terminal::ours_for_output ();
>>  	      fprintf_filtered (gdb_stdlog,
>> -				_("Detaching after %s from child %s.\n"),
>> +				_("[Detaching after %s from child %s.]\n"),
>>  				has_vforked ? "vfork" : "fork",
>>  				target_pid_to_str (process_ptid));
>
> I also noticed that this ends up with a period at the end, while
> other [] notices don't, like (playing with "set detach-on-fork on"):
>
>  [Detaching after fork from child process 3417.]
>  [Inferior 5 (process 3416) exited normally]

Good point, I'll remove the periods.

>
>> diff --git a/gdb/testsuite/gdb.base/fork-detach-info.exp b/gdb/testsuite/gdb.base/fork-detach-info.exp
>> new file mode 100644
>> index 0000000000..aa9a85c0d5
>> --- /dev/null
>> +++ b/gdb/testsuite/gdb.base/fork-detach-info.exp
>
> Maybe this could use a different name, since this isn't
> just about _detach_ info?
>
> fork-print-inferior-events.exp, maybe.

Renamed.

>> @@ -0,0 +1,68 @@
>> +# This testcase is part of GDB, the GNU debugger.
>> +
>> +# Copyright 2007-2018 Free Software Foundation, Inc.
>> +
>> +# This program is free software; you can redistribute it and/or modify
>> +# it under the terms of the GNU General Public License as published by
>> +# the Free Software Foundation; either version 3 of the License, or
>> +# (at your option) any later version.
>> +#
>> +# This program is distributed in the hope that it will be useful,
>> +# but WITHOUT ANY WARRANTY; without even the implied warranty of
>> +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
>> +# GNU General Public License for more details.
>> +#
>> +# You should have received a copy of the GNU General Public License
>> +# along with this program.  If not, see <http://www.gnu.org/licenses/>.
>> +
>
> Please add an intro comment mentioning what the testcase is about.

Done.

>> +if { [use_gdb_stub] || [target_info gdb_protocol] == "extended-remote" } {
>> +    untested "not supported on gdbserver"
>> +    return
>> +}
>
> I see that this relies on "run", so can't work with use_gdb_stub.
> But why is this not supported with extended-remote gdbserver?

Just because, for extended-remote, the messages are a bit different:

  [Attaching after Thread 7738.7738 fork to child Thread 7738.7738]
  [New inferior 2 (process 7739)]
  [Detaching after fork from parent process 7738]
  [Inferior 7738 detached]
  [Inferior 2 (process 7739) exited normally]

This case is easy, it would just require an adjustment to the first line
(instead of "process $decimal" we'd expect "Thread
$decimal\.$decimal").  There are more annoying cases, like:

  Reading /lib64/ld-linux-x86-64.so.2 from remote target...
  Reading /lib64/ld-2.26.so.debug from remote target...
  Reading /lib64/.debug/ld-2.26.so.debug from remote target...
  Reading /lib64/libm.so.6 from remote target...
  Reading /lib64/libc.so.6 from remote target...
  Reading /lib64/libm-2.26.so.debug from remote target...
  Reading /lib64/.debug/libm-2.26.so.debug from remote target...
  Reading /lib64/libc-2.26.so.debug from remote target...
  Reading /lib64/.debug/libc-2.26.so.debug from remote target...
  [Attaching after Thread 7762.7762 fork to child Thread 7762.7762]
  [New inferior 2 (process 7763)]
  Reading /lib64/libm.so.6 from remote target...
  Reading /lib64/libc.so.6 from remote target...
  Reading /lib64/ld-linux-x86-64.so.2 from remote target...
  Reading /lib64/libm-2.26.so.debug from remote target...
  Reading /lib64/.debug/libm-2.26.so.debug from remote target...
  Reading /lib64/libc-2.26.so.debug from remote target...
  Reading /lib64/.debug/libc-2.26.so.debug from remote target...
  Reading /lib64/ld-2.26.so.debug from remote target...
  Reading /lib64/.debug/ld-2.26.so.debug from remote target...
  Reading /lib64/ld-linux-x86-64.so.2 from remote target...
  [Inferior 2 (process 7763) exited normally]

In this case, we'd have all the "Reading ..." messages to ignore, which
makes it hard to match the consecutive lines we expect.  Therefore, I
thought it made sense to make this test local.

Maybe a better solution for this would be to provide a similar test
under gdb.server.  Or just tweak the regexps.

>> +
>> +standard_testfile
>> +
>> +if { [prepare_for_testing "failed to prepare" $testfile $srcfile debug] } {
>> +    return -1
>> +}
>> +
>> +# This is the expected output for each of the test combinations
>> +# below.  The order here is important:
>> +#
>> +#    follow-fork: child; detach-on-fork: on; inferior-events: on
>> +#    follow-fork: child; detach-on-fork: on; inferior-events: off
>> +#    follow-fork: child; detach-on-fork: off; inferior-events: on
>> +#    follow-fork: child; detach-on-fork: off; inferior-events: off
>> +#    follow-fork: parent; detach-on-fork: on; inferior-events: on
>> +#    follow-fork: parent; detach-on-fork: on; inferior-events: off
>> +#    follow-fork: parent; detach-on-fork: off; inferior-events: on
>> +#    follow-fork: parent; detach-on-fork: off; inferior-events: off
>> +set expected_output [list \
>> + "\\\[Attaching after process $decimal fork to child process
>> $decimal\\.\\\]\r\n\\\[New inferior $decimal\\\]\r\n\\\[Detaching
>> after fork from child process $decimal\\.\\\]\r\n\\\[Inferior
>> $decimal detached\\\]\r\n\\\[Inferior $decimal \\(process
>> $decimal\\) exited normally\\\]" \
>> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
>> +    "\\\[Attaching after process $decimal fork to child process $decimal\\.\\\]\r\n\\\[New inferior $decimal\\\]\r\n\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
>> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
>> +    "\\\[Detaching after fork from child process $decimal\\.\\\]\r\n\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
>> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
>> +    "\\\[New inferior $decimal\\\]\r\n\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]" \
>> +    "\\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]"]
>> +
>
> I had a lot of trouble making sense of this big blurb of expected output.
> I didn't know exactly what to suggest, so I played with it locally, and
> I think putting the individual messages in variables helps a lot.
> And then, I noticed that all the cases end up with 
>
>   \\\[Inferior $decimal \\(process $decimal\\) exited normally\\\]
>
> so we can factor it out.
>
> And then, if we iterate over print_inferior_events first, then
> it's super clear that the "set print-inferior-events off"
> case is always "no output".  See attached patch on top of yours.

Thanks for the patch, I applied it on top of what I have here.

> The infrun.c hunk is there in my patch because while playing with
> this, I noticed that gdb says that it's detaching the child
> (and uses the child's pid), when in fact it is detaching the
> parent!
>
> I.e., currently, "set follow-fork child", "set detach-on-fork on":
>
>  [Attaching after process 12069 fork to child process 12069.]
>  [New inferior 2 12073]
>  [Detaching after fork from child process 12073.]   <<< nope, it's detaching 12069 / the parent
>  [Inferior 12069 detached]                          <<< see?
>  [Inferior 2 (process 12073) exited normally]
>
> after that fix:
>
>  [Attaching after process 18500 fork to child process 18500.]
>  [New inferior 18504]
>  [Detaching after fork from parent process 18500.]
>  [Inferior 18500 detached]
>  [Inferior 2 (process 18504) exited normally]

Ah, good catch.  ISTR having a strange feeling when examining these
outputs, but couldn't tell why.

I'll send a new version soon.

Thanks,