Re: [lmi] Error reporting

[Greg Chicares]

On 2014-12-05 17:04Z, Vadim Zeitlin wrote:
> On Fri, 05 Dec 2014 02:18:45 +0000 Greg Chicares <address@hidden> wrote:
> 
> GC> On 2014-12-04 21:22Z, Vadim Zeitlin wrote:
> GC> > 
> GC> >  Sorry to return to this, but
[...]
> GC> Because this was wrong once, let's start by figuring out how to test
> GC> it, so that we can be certain it's right after we fix it.
[...]
> GC> I did run this test with the original r6007 change:
> GC> 
> GC> /opt/lmi/bin[0]$./lmi_wx_shared --ash_nazg --data_path=/opt/lmi/data
> GC>   Test | Test system command
> GC>   x
> GC>   OK
> GC> 
> GC> and observed these effects, which I guessed were exactly correct:
> GC> 
> GC> Messagebox:
> GC>   Error | Command 'x' not recognized.
> GC> and in the terminal:
> GC>   01:52:19: Error: Execution of command 'x' failed (error 2: the system 
> cannot find the file specified.)
> 
>  I don't think this is really the best behaviour. Information shown in the
> terminal should really be shown to the user, it contains information
> potentially valuable for diagnosing the problem. Currently, the message box
> doesn't show the real reason for which the program execution failed, it
> just assumes it was because the program wasn't found. Granted, this is what
> happens in 99% of cases, but it's not the only possibility. For example, I
> just removed "Read and execute" access right from "ls.exe" on my system for
> my account and the message box now says that "ls is not recognized" while
> the wxWidgets error message on the console does show the real problem:
> 
> Error: Execution of command 'f:\ull\path\to\cygwin\bin\xgettext.exe' failed 
> (error 5: access is denied.)
> 
>  So for me the behaviour pre-r6007, which would have shown the exact error
> to the user, was preferable (although not ideal because it would actually
> show two message boxes and just one would be better).

I had seen it as an improvement. Before r6007, two messages appeared
in the GUI, and end users would see both:
  Command 'x' not recognized.
  Execution of command 'x' failed (error 2: the system cannot find the file 
specified.)
After r6007, end users see only the first message; developers see it
too--and also see the second message, but on stderr instead of in a
messagebox.

Here's the operative code:

    else if(-1L == exit_code)
        {
        fatal_error()
            << "Command '"
            << command_line
            << "' not recognized."
            << std::flush
            ;
        }

To me, that means I called wxExecute(), checked its error code, and
issued a diagnostic that I thought appropriate. I'm guessing now
(incorrectly?) that I could have retrieved more information from
the 'errors' argument:
  wxExecute(command_line, output, errors, wxEXEC_NODISABLE);
but it looks like I chose to discard any such extra information.
So the behavior in HEAD still looks perfectly correct to me.

> GC> Should the outcome of these tests be different?
> 
>  Yes, I think they should be, because the first one is an error in
> executing the program, while the latter is an error while executing it. The
> important difference is that in the former case the application (lmi)
> doesn't have all the information about the error, which is why wxWidgets
> logs the error message itself. In the latter case wxWidgets doesn't have
> any more information than the application, so it doesn't do it.

Ah, good: we have different ideas about an objective fact, so
we're in the happy position where Leibniz said "calculemus".
In 'system_command_wx.cpp', I try this change, to inhibit the
"Command '...' not recognized" handler:
-    else if(-1L == exit_code)
+    else if(-1999L == exit_code)
and repeat the test.

So my guess above was wrong: 'errors' here:
  wxExecute(command_line, output, errors, wxEXEC_NODISABLE);
doesn't give the reason for failure. Therefore, it's not that I
had the information available and chose not to display it.
Instead, wx had the information...which couldn't be passed into
'errors' because there was an "error in executing" the command,
whereas 'errors' can reflect only an "error while executing"...
and therefore wx itself normally prints the more informative
diagnostic...unless we've blocked it, as we unintentionally
have in r6007.

And that matters greatly in other cases. As a hypothetical example,
suppose I try to save a file in lmi, and the disk is full. I just
send a command from the menu, which passes a message; there's no
return code for me to check, so I just assume it always works. Now,
suppose wx notices the failure and wants to issue an informative
diagnostic. Normally it would pop up a messagebox, and the user
would receive vital information. But we've blocked that line of
communication, so the user's command silently fails. And that is
really a problem that we must fix.

Do I understand this correctly now?

> GC> Do we need a different test? And is there a way to automate a test for
> GC> whatever GUI phenomena would be correct?
> 
>  Yes, there is, we can check that the expected dialog is shown or, simpler,
> that the expected error message is logged.

I just spent a lot more time trying to understand that problem
than I did writing about it. Could I prevail upon you to write
an automated test for this? I guess this calls for a new
'wx_test_whatever.cpp' files, but that's certainly okay; or
perhaps it fits nicely into some other file you were already
going to add--it's your choice.

> GC> >  I.e. the goal was to see the diagnostic messages not shown by default.
> GC> 
> GC> Let me try to express it myself. End users start lmi from an msw 
> "shortcut";
> GC> they should continue to see the most severe errors, in messageboxes, as
> GC> always. Kim, Wendy, and I normally start lmi from zsh in a mintty 
> terminal;
> GC> we want to see what end users see, and in addition we want the less-severe
> GC> wx diagnostics (that end users do not see) to display for us on stderr.
> 
>  This is the problem: for me the "less severe wx diagnostics" were messages
> logged with wxLogDebug(). They are, indeed, not meant for the end users and
> shouldn't be shown to them and typically are even disabled completely in
> the "release" build of the application -- but in lmi case we decided to
> keep them enabled and only show them on the console. This is still correct.
> 
>  However this is not the only kind of messages. There are also warnings
> (generated with wxLogWarning(), of which there are very few) and errors
> (wxLogError(), many). And the errors, such as the one logged from
> wxExecute() when it fails to launch the program, are definitely meant to be
> shown to the users and should not be suppressed without a very good reason.
> And they were not until r6007, even if you typically didn't see them
> because errors didn't occur, you would have seen them if they did. Now you
> never see them at all as a normal user.

This brings to mind the shortest chapter in any English novel
(_Through the Looking-Glass_, XI): "...and I really *do*
understand this now, after all". Thanks for your patience.

> GC> Of course, I'm assuming that stderr is effectively /dev/null for end users
> GC> because they have no console. I certainly wouldn't want the OS to create a
> GC> console for them to display the less-severe messages that we don't want to
> GC> bother them with.
> 
>  Yes, I agree with everything in this paragraph.
> 
> GC> > However the effects of the change of r6007 are almost exactly the 
> converse:
> GC> > by setting the active log target to wxLogStderr, it ensures that the end
> GC> > users do not see even the severe messages any more!
> GC> 
> GC> Please tell me how to reproduce this so that I can see it for myself.
> 
>  It's difficult to reproduce because it's difficult to trigger an error.
> But wxExecute() example above does show the difference in the behaviour
> between pre-r6007 and current versions. And if something bad, e.g. failure
> to create a window, copy to clipboard or anything like this, happens, an
> error signalling this would have been visible before but is not any longer.

Yes!

> GC> If your analysis of the behavior is correct, then I suppose I should
> GC> want to fix it. But that's still hypothetical for me, because I can't
> GC> see what's wrong.
> 
>  Not showing wxWidgets errors to the users is wrong IMNSHO. And it
> definitely was not done before.
> 
>  I hope things are slightly more clear now, sorry for the initial
> confusion,

I will gladly commit a patch that fixes this and a test that proves it.