Re: [PATCH 5/5] Eliminate make_cleanup_ui_file_delete / make ui_file a class hierarchy

[Simon Marchi <simon.marchi@polymtl.ca>]

On 2017-01-23 11:58, Pedro Alves wrote:
>> I'm not sure about the implications, but instinctively I would've made
>> rewind in the base class throw an exception by default, instead of
>> making the derived types throw one if they don't support rewind.
>> Actually, except for the null_file, I don't really see when you would
>> want rewind to be a no-op.  If the rewind call returns but does not
>> actually rewind, isn't it lying to the client code?
> 
> Yes, indeed it's a lie, but it's not really a new lie.  :-)  It's 
> similar to
> how the existing code works.  Before the patch, write_buffer_on doesn't
> exist, but what it replaces, the "put" callback, behaved similarly -- 
> only
> mem_fileopen, TUI and guile ui-files implement the put method,
> all others leave it set to null_file_put (the default).
> "write/write_buffer_on", like "put" were only meant for
> locally buffered files (like mem_fileopen/tui_sfileopen).
> ioscm_file_port might have only implemented put because the
> method was there in ui_file to implement.
> It's a bit of a bogus design, but it didn't seem easy to fix.
> The asserts were me trying to figure out where are the calls to
> write_buffer_on / rewind coming from.  I meant to come back to this
> before posting, but then ended up posting this sooner than I
> thought, and forgot to remove the asserts.  Anyway, I took another
> look at all this today, and I have a proposal.
> 
> After my patch, the ui_file::write_buffer_on method is only
> used here, in the MI's ui_out:
> 
> void
> mi_ui_out::put (ui_file *stream)
> {
>   ui_file *outstream = m_streams.back ();
> 
>   outstream->write_buffer_on (*stream);
>   outstream->rewind ();
> }
> 
> When I was originally writing this series a couple months ago, I tried
> to come up with a way to get here with the m_streams vector containing
> some ui_file at the top of the stack that is not the ui_out's original
> stream_file.  And I think I had found some, around enabling
> MI logging, and so to preserve behavior, I was planning on leaving
> both the write_buffer_on and rewind methods as no-ops for
> most ui_files, thinking that to fix this we're need a larger
> redesign to the CLI/MI logging code (which looks kind of horrible)
> that would be better done on top.

I have looked at the MI logging code and I am not sure I understand it.  
Here's what I think I got, tell me if I'm completely lost:

In the normal case, mi_ui_out accumulates the output bytes in a 
string_file. Only when the command execution is complete does 
captured_mi_execute_command dump the accumulated output in the real 
output stream with:

   mi_out_put (uiout, mi->raw_stdout);

Presumably, this is so that we don't send part of an MI response in case 
of errors.  If mi_ui_out wrote directly in the real output stream, it 
wouldn't be able to cancel/rewind it if there's an error.  Hence the 
need for a rewind/clear method on string_file.

When we turn basic logging on (-gdb-set logging on), handle_redirections 
prepares a nice little tee ui_file to redirect the output stream to an 
on-disk file, and passes it to current_interp_set_logging.  However, 
that doesn't work for MI, as it would break the buffering scheme that 
allows it to cancel some previous output.  So it deletes that tee file 
and creates its own, with which it overrides raw_stdout, which is the 
output stream used to dump the response once the command execution is 
complete.  So it's when the command response is dumped, that it goes 
through the tee.

"-gdb-set logging redirect on", would be similar, but it just installs 
the log file in raw_stdout instead of a tee.

> I redid the experiment / investigation here, and it looks
> the only way to reach that method with 'outstream' being something
> other than the ui_out's original string_file, is with this
> this sequence of MI commands:
> 
>  -gdb-set logging on
>  -gdb-set logging redirect on

Indeed, at the end of set_logging_redirect, it uses uiout->redirect 
directly, which puts either a tee_file or stdio_file in mi_ui_out's 
streams, and breaks all of MI's assumption to find a string_file there 
when executing a command.

Your follow-up patch prevents changing logging settings while logging is 
active.  And it allows to simply delete that code/case.  Did I get it 
somewhat right?  It's still very fuzzy in my head, I can tell that the 
new code seems saner than what was there.

> This reaches mi_ui_out::put with 'outstream' being a
> stdio_file, and triggers the new assertion in stdio_file:
> 
>    void rewind () override
>    { gdb_assert_not_reached ("can't rewind a stdio file"); }
> 
>  #0  0x00000000007ad1b4 in internal_error(char const*, int, char
> const*, ...) (file=0x1145b50
> "/home/pedro/gdb/mygit/cxx-convertion/src/gdb/ui-file.h", line=190,
> fmt=0x1145b44 "%s: %s") at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/common/errors.c:54
>  #1  0x0000000000639b77 in stdio_file::rewind() (this=0x335d7e0) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/ui-file.h:190
>  #2  0x0000000000634ee4 in mi_ui_out::put(ui_file*) (this=0x2a010e0,
> stream=0x335d7e0)
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/mi/mi-out.c:255
>  #3  0x000000000063519f in mi_out_put(ui_out*, ui_file*)
> (uiout=0x2a010e0, stream=0x335d7e0)
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/mi/mi-out.c:314
>  #4  0x0000000000631b45 in captured_mi_execute_command(ui_out*,
> mi_parse*) (uiout=0x2a010e0, context=0x335d2e0)
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/mi/mi-main.c:2007
>  #5  0x000000000063203d in mi_execute_command(char const*, int)
> (cmd=0x335d370 "-gdb-set logging redirect on", from_tty=1)
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/mi/mi-main.c:2157
>  #6  0x000000000062b0f4 in mi_execute_command_wrapper(char const*)
> (cmd=0x335d370 "-gdb-set logging redirect on")
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/mi/mi-interp.c:289
>  #7  0x000000000062b180 in mi_execute_command_input_handler(char*)
> (cmd=0x335d370 "-gdb-set logging redirect on")
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/mi/mi-interp.c:319
>  #8  0x00000000007b8e37 in gdb_readline_no_editing_callback(void*)
> (client_data=0x2366b10)
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-top.c:855
>  #9  0x00000000007b87a7 in stdin_event_handler(int, void*) (error=0,
> client_data=0x2366b10)
>      at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-top.c:518
>  #10 0x00000000007b6dcc in handle_file_event(file_handler*, int)
> (file_ptr=0x2e4fc90, ready_mask=1)
>     at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-loop.c:733
>  #11 0x00000000007b736f in gdb_wait_for_event(int) (block=1) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-loop.c:859
>  #12 0x00000000007b61ec in gdb_do_one_event() () at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-loop.c:347
>  #13 0x00000000007b6224 in start_event_loop() () at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-loop.c:371
>  #14 0x0000000000827f16 in captured_command_loop(void*) (data=0x0) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/main.c:325
>  #15 0x00000000007b9c8e in catch_errors(int (*)(void*), void*, char*,
> return_mask) (func=0x827ed4 <captured_command_loop(void*)>,
> func_args=0x0, errstring=0x11df891 "", mask=RETURN_MASK_ALL) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/exceptions.c:236
>  #16 0x000000000082928b in captured_main(void*) (data=0x7fffffffd820)
> at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/main.c:1148
> During symbol reading, cannot get low and high bounds for subprogram
> DIE at 24065.
>  #17 0x00000000008292b4 in gdb_main(captured_main_args*)
> (args=0x7fffffffd820) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/main.c:1158
>  #18 0x0000000000412d4d in main(int, char**) (argc=4,
> argv=0x7fffffffd928) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/gdb.c:32
> 
> Now, looking again with fresh eyes, I now believe that the
> only reason this assert triggers, is because the implementation
> of that sequence of commands for MI is plain buggy.  If
> you do it with current master, GDB crashes!
> 
>  Program received signal SIGSEGV, Segmentation fault.
>  0x00000000008dd7bc in gdb_flush (file=0x2a097f0) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/ui-file.c:194
>  194       file->to_flush (file);
>  (top-gdb) bt
>  #0  0x00000000008dd7bc in gdb_flush(ui_file*) (file=0x2a097f0) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/ui-file.c:194
>  #1  0x00000000007b5f34 in gdb_wait_for_event(int) (block=0) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-loop.c:752
>  #2  0x00000000007b52b6 in gdb_do_one_event() () at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-loop.c:322
>  #3  0x00000000007b5362 in start_event_loop() () at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/event-loop.c:371
>  #4  0x000000000082704a in captured_command_loop(void*) (data=0x0) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/main.c:325
>  #5  0x00000000007b8d7c in catch_errors(int (*)(void*), void*, char*,
> return_mask) (func=0x827008 <captured_command_loop(void*)>,
> func_args=0x0, errstring=0x11dee51 "", mask=RETURN_MASK_ALL) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/exceptions.c:236
>  #6  0x000000000082839b in captured_main(void*) (data=0x7fffffffd820)
> at /home/pedro/gdb/mygit/cxx-convertion/src/gdb/main.c:1148
>  During symbol reading, cannot get low and high bounds for subprogram
> DIE at 24065.
>  #7  0x00000000008283c4 in gdb_main(captured_main_args*)
> (args=0x7fffffffd820) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/main.c:1158
>  #8  0x0000000000412d4d in main(int, char**) (argc=4,
> argv=0x7fffffffd928) at
> /home/pedro/gdb/mygit/cxx-convertion/src/gdb/gdb.c:32
> 
> So it looks like the assert is catching a problem earlier.
> Without the assert, gdb continues on with bogus state
> and eventually crashes.
> 
> Going back to my patch, in the bad case, we get to:
> 
>  void
>  mi_ui_out::put (ui_file *stream)
>  {
>    ui_file *outstream = m_streams.back ();
> 
>    outstream->write_buffer_on (*stream);
>    outstream->rewind ();
>  }
> 
> with STREAM and OUTSTREAM pointing to the same thing...
> 
> This happens because we try to handle "set logging
> redirect on" while logging is enabled:
> 
>  https://sourceware.org/ml/gdb-patches/2010-08/msg00202.html
> 
> but get it wrong for MI.  (Strictly speaking, MI logging support
> was added after that patch, so it was the MI logging patch
> that missed this.)
> I find that code to handle on-the-fly redirect quite hard to
> follow and reason about, along with the interp set_logging mechanism
> and how CLI and MI hook into all this.  I think the fix here should
> simply be to stop trying to handle changing logging redirect on the 
> fly,
> and require turning logging off and on, like Jan's original patch
> was proposing.  I'll post a patch for that as follow up, to make
> it clearer what I mean.
> 
> With that out of the way, it looks to me that we can assume
> that mi_ui_put (and thus mi_ui_out::put) is only ever meant to
> be called with output _not_ redirected, and thus we can simplify
> things a bit further, by eliminating the ui_file
> write_buffer_on / rewind methods, keeping it contained in
> the MI code.

Right, mi_ui_put is only used when printing/dumping responses to 
commands.  For async events, the MI output is redirected to raw_stdout 
(through the event_channel, but still).  So when printing an async 
event, a call to ui_out::field_int will write directly to raw_stdout, 
whereas when printing the response to a command, ui_out::field_int will 
write to mi_ui_out's internal string_file.

In the end, I like that you were able to remove rewind and 
write_buffer_on.  My mind really couldn't get past the fact that you 
could call ->rewind() on an stdio_file.

Thanks,

Simon