Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

lib/errorlogger.cpp: Improve conversion from InternalError to ErrorMessage #5804

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

mvds00
Copy link
Contributor

@mvds00 mvds00 commented Dec 23, 2023

ErrorMessage::setmsg() assumes that the supplied message string is a combination of a short message and a verbose message, separated by a newline.

However, InternalError does not use that format; when converting from InternalError to ErrorMessage, the short message will receive the first line, and the verbose message will receive the lines that follow.

This approach may lead to obscure messages during verbose logging since the informative first line is lost.

This is solved by setting the verbose message to the complete original error string.

A concrete example is the failure of an addon to produce output starting with '{', which is reported as an InternalError. The clarity of this message is also improved with this patch, as the "Failure to execute" criterion was not clear from the message.

@danmar
Copy link
Owner

danmar commented Dec 23, 2023

EDIT: Removed, I misunderstood what the changes could do..

@danmar
Copy link
Owner

danmar commented Dec 23, 2023

I am confused why CI accepted this.

hmm.. somehow it would be nice with a test for this.. I would assume a unit test can test ErrorMessage::fromInternalError directly and check the result..

@mvds00
Copy link
Contributor Author

mvds00 commented Dec 24, 2023

I am confused why CI accepted this.

hmm.. somehow it would be nice with a test for this.. I would assume a unit test can test ErrorMessage::fromInternalError directly and check the result..

The unit test does not cover multi-line scenarios. The offending line (part of this commit) throws InternalError(nullptr, "Failed to execute ..." + result); where result is not trusted, and may contain newlines.

I added a test case InternalError internalError(nullptr, "message\nmultiline1\nmultiline2"); under ErrorMessageFromInternalError() with the following output:

test/testerrorlogger.cpp:193(TestErrorLogger::ErrorMessageFromInternalError): Assertion failed. 
Expected: 
msg: message: details

Actual: 
multiline1\n
multiline2

Here the string "message" is indeed lost.

I think there are two problems to fix. First, the error should not contain a newline in the first place, so I could push:

throw InternalError(nullptr, "Failed to execute '" + pythonExe + " " + args + "'. Expected '{' but got '" + line[0] + "' as first character.",
   "Output was: '" + result + "'");

This would make sense, as the output of the command is the detailed context of the reported issue.

Second, if the error does contain a newline, the first line should not get lost. This is already addressed by the current commit.

The following test cases succeed with the patch as it is:

        {
            InternalError internalError(nullptr, "message","details1\ndetails2");
            const auto msg = ErrorMessage::fromInternalError(internalError, nullptr, "file.cpp", "msg");
            ASSERT_EQUALS(1, msg.callStack.size());
            const auto &loc = *msg.callStack.cbegin();
            ASSERT_EQUALS(0, loc.fileIndex);
            ASSERT_EQUALS(0, loc.line);
            ASSERT_EQUALS(0, loc.column);
            ASSERT_EQUALS("msg: message", msg.shortMessage());
            ASSERT_EQUALS("msg: message: details1\ndetails2", msg.verboseMessage());
            ASSERT_EQUALS("[file.cpp:0]: (error) msg: message", msg.toString(false));
            ASSERT_EQUALS("[file.cpp:0]: (error) msg: message: details1\ndetails2", msg.toString(true));
        }
        {
            InternalError internalError(nullptr, "message1\nmessage2","details");
            const auto msg = ErrorMessage::fromInternalError(internalError, nullptr, "file.cpp", "msg");
            ASSERT_EQUALS(1, msg.callStack.size());
            const auto &loc = *msg.callStack.cbegin();
            ASSERT_EQUALS(0, loc.fileIndex);
            ASSERT_EQUALS(0, loc.line);
            ASSERT_EQUALS(0, loc.column);
            ASSERT_EQUALS("msg: message1", msg.shortMessage());
            ASSERT_EQUALS("msg: message1\nmessage2: details", msg.verboseMessage());
            ASSERT_EQUALS("[file.cpp:0]: (error) msg: message1", msg.toString(false));
            ASSERT_EQUALS("[file.cpp:0]: (error) msg: message1\nmessage2: details", msg.toString(true));
        }

Is this acceptable?

There may be a few more places where newlines may accidentally end up in the message, e.g. Tokenizer::syntaxError().

@danmar
Copy link
Owner

danmar commented Dec 25, 2023

I think at least the assertions in the first {} is OK.

In the second {} it is a bit more questionable.. but as you say it's more likely that it's unintended bugs in cppcheck. I have the feeling that such newlines are a mistake rather than intentional.. I wonder if we can even assert that the message does not contain a newline.

@mvds00
Copy link
Contributor Author

mvds00 commented Dec 25, 2023

In the second {} it is a bit more questionable.. but as you say it's more likely that it's unintended bugs in cppcheck. I have the feeling that such newlines are a mistake rather than intentional.. I wonder if we can even assert that the message does not contain a newline.

A lot of InternalError construction is done using concatenated strings, so anything can happen. One option is to replace \n with spaces in the constructor, but that does not necessarily make things more understandable in practice.

My thinking is: newlines should not occur there, but if they do, the error reporting code should not make matters more confusing than they already are, for someone stumbling on an InternalError. The second {} asserts that at least the first line will always be visible, which is the line that contains the explanation for the internal error. My experience making namingng.py suitable for --cli would have been better if it had worked this way.

…ssage

ErrorMessage::setmsg() assumes that the supplied message string is a
combination of a short message and a verbose message, separated by a newline.

However, InternalError does not use that format, and the errorMessage of
InternalError may contain an unintentional newline. Then, when converting from
InternalError to ErrorMessage, the short message will receive the first line,
and the verbose message will receive the lines that follow.

This approach may lead to obscure messages during verbose logging since the
informative first, often explaining the reason for the InternalError line is
lost.

This is solved by setting the verbose message to the complete original error
string.

A concrete example is the failure of an addon to produce output starting with
'{', which is reported as an InternalError. The clarity of this message is
also improved with this patch, as the "Failure to execute" criterion was not
clear from the message. Also, the failing output in this case is moved to the
details field of InternalError.

Unit tests were added for multi-line InternalError conversions.
@@ -310,7 +310,7 @@ static std::vector<picojson::value> executeAddon(const AddonInfo &addonInfo,
//std::cout << "addon '" << addonInfo.name << "' result is not a JSON" << std::endl;

result.erase(result.find_last_not_of('\n') + 1, std::string::npos); // Remove trailing newlines
throw InternalError(nullptr, "Failed to execute '" + pythonExe + " " + args + "'. " + result);
throw InternalError(nullptr, "Failed to execute '" + pythonExe + " " + args + "'. Expected '{' but got '" + line[0] + "' as first character.", "Output was: '" + result + "'");
Copy link
Owner

@danmar danmar Dec 27, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay so we should have written "line" instead of "result" here. I understand the output was cryptic!

Could we fix the bug here and replace the result with line. I am not against that we add a verbose output that contains all results but it would be good to point out the bad line..

Something like:

short message:

Failed to execute '...'. Invalid line: abcd

verbose message:

Failed to execute '...'. Expected '{' but got 'a' as first character. Invalid line: abcd
Results:
 ....

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good to not include all of the result but just the offending line. However in line with the InternalError logic I would suggest the following:

The throwing:

throw InternalError(nullptr,
   "Unexpected output from '" + pythonExe + " " + args + "'. Invalid line '"+line+"'",
   "Expected '{' but got '" + line[0] + "' as first character."
);

(I changed "failed to execute" because it actually did execute - we just don't like what it produced.)

The resulting short message:

Unexpected output from '...'. Invalid line 'abcd'

The resulting verbose message:

Unexpected output from '...'. Invalid line 'abcd': Expected '{' but got 'a' as first character. 

Still then, the question is what to do with InternalError messages containing \n? Or can we be confident that they never occur again..?

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Still then, the question is what to do with InternalError messages containing \n? Or can we be confident that they never occur again..?

maybe your approach is fine.. however I do feel that there should really not be newlines.. ideally I would like to see some assertion error or internal error message that just complains that there is a newline..

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(I changed "failed to execute" because it actually did execute - we just don't like what it produced.)

I like that.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Still then, the question is what to do with InternalError messages containing \n? Or can we be confident that they never occur again..?

maybe your approach is fine.. however I do feel that there should really not be newlines.. ideally I would like to see some assertion error or internal error message that just complains that there is a newline..

I kind of agree, but imagine getting "an internal error occurred processing an internal error" - technically very accurate, but helpful... not really. Not for a new user, not for the bug report they will submit. Compile-time options seem very limited, short from enforce the short message of InternalError to be a string literal, and putting all dynamic/formatted/concatenated stuff in the details/verbose field. Can we simply take the first N characters while replacing \n with spaces?

Copy link
Owner

@danmar danmar Dec 31, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if a developer is debugging cppcheck I think a assertion error that terminates would be good.. but:

  1. we don't currently have assertions that only terminates during debugging.. I guess we would need to update the build scripts to set the NDEBUG macro or something..
  2. what if the user runs into the problem instead. we need a solution that is acceptable for the user.

so well I think ignore the assertion for now.. feel free to look into that later..

Can we simply take the first N characters while replacing \n with spaces?

sure

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants