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

[Sergio Durigan Junior <sergiodj at redhat dot com>]

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,

-- 
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF  31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/