Bad error reporting

[Vampire]

Describe the bug
Due to gradle/gradle#11795, there are problems with the used library versions, as much older versions needed by stuff in buildSrc win in the class path and then there are missing method exceptions.

This of course is not your fault and not what I report here.
But the output in this case is sometimes super unhelpful, which is what I do report here.

A good example is a too old commons-io (1.3.1) that causes the build to fail with

Execution failed for task ':dependencyCheckAnalyze'.
> org.owasp.dependencycheck.analyzer.Analyzer: Provider org.owasp.dependencycheck.analyzer.ArchiveAnalyzer could not be instantiated`

and if run with -s reveals the Caused by: java.lang.NoSuchMethodError: org.apache.commons.io.filefilter.SuffixFileFilter.<init>(Ljava/util/List;Lorg/apache/commons/io/IOCase;)V cause.

A bad example is a too old guava that causes the build to fail with

Execution failed for task ':dependencyCheckAnalyze'.
> Analysis failed.

and if run with -s only says

Caused by: org.owasp.dependencycheck.exception.ExceptionCollection: One or more exceptions occurred during analysis:
        Unexpected Exception

which is pretty meaningless.
After setting a breakpoint and assembling the stacktrace in Engine#analyzeDependencies I finally got the cause which is Caused by: java.lang.NoSuchMethodError: com.google.common.base.Preconditions.checkState(ZLjava/lang/String;Ljava/lang/Object;)V.

Version of dependency-check used
The problem occurs using version 5.2.4 of the gradle plugin

[jeremylong]

I'm not sure if this is a defect for dependency-check or Gradle itself. The error messages you are reporting are from the gradle build system. I'm not sure how my plugin could do better reporting if it can't load...

[Vampire]

I'm not complaining about Gradle only showing the top-most message unless you use -s, that is normal and ok.
I'm complaining about the stacktrace that you produce being totally unhelpful.
This is not even dependency-check-gradle related, but dependency-check-parent related.

I'd say in ExceptionCollection which just assembles the messages of the top-most exceptions it got and nowhere the causes and stacktraces.
The exception that came was with message Unexpected Exception and had as cause the NoSuchMethodError with the relevant information.
But in the output, you only get the stacktrace of the ExceptionCollection and the top-most messages of the contained exceptions which does not help in any way to find the problem.

[aikebah]

@Vampire The only occurrence I can find for the scenario of "Unexpected Exception" as the exception message is in

DependencyCheck/core/src/main/java/org/owasp/dependencycheck/Engine.java

Lines 793 to 802 in 60e74e8

	} catch (Throwable ex) {
	LOGGER.error("Unexpected exception occurred initializing {}.", analyzer.getName());
	LOGGER.debug("", ex);
	try {
	analyzer.close();
	} catch (Throwable ex1) {
	LOGGER.trace("", ex1);
	}
	throw new InitializationException("Unexpected Exception", ex);
	}

Which is throwing an exception including its cause. So my gut feel is that Gradle is limiting the depth of the printed stacktrace. Which appears to be consistent with their documentation of CLI-options.

I expect that you'll find the full traces when you run gradle -S / gradle --full-stacktrace instead of gradle -s / gradle --stacktrace

[jeremylong]

The InitializationException("Unexpected Exception") is then wrapped into the ExceptionCollection. The reason for the exception collection is that there may be multiple exceptions that occur - some fatal and some not that should be reported back. It's unfortunate that gradle limits the depth of the printed stack trace.

[Vampire]

The problem is not Gradle truncating stack traces and it is not fixable by -S.
If you would have read the command-line options descriptions properly, you would have understand that the difference between -s and -S is just that some frames are filtered out that do not carry meaningful information in 98% of the cases anyway like service loader internal stack frames or Groovy invocation stack frames.

That it manifests in Gradle is probably because it does not use printStackTrace, but uses getStackTrace(), then does the sanitizing and then prints the sanitized stack trace itself.
And with you overwriting printStackTrace you make it out of sync with getStackTrace().

[aikebah]

Which also means that it might not help to adopt the Throwable.addSuppressed, which are accounted for in the printStackTrace (of java.lang.Throwable), but which are not taken into account on the getStackTrace which is documented as being the runtime-retrievable result of a printStackTrace.
@Vampire do you know whether gradle takes the Throwable.getSuppressed() into account in its error-cause printing routines? If so I think the best approach would be to replace the current ExceptionCollection custom 'suppressed Exception' collector by the standard java Exception suppression mechanism.

I'm willing to work on refactoring the use of the custom ExceptionCollection as a solution to defer reporting the exceptions in the analysis into an Exception that handles handles them in the standard java mechanism of suppressed exceptions registered against the Throwable, but that effort would be wasted if it wouldn't offer a solution for this issue.

[jeremylong]

@aikebah a simpler solution might be to simply log any inner exceptions from the ExceptionCollection and then throw the first exception in the list...

[aikebah]

Simpler, but not necessarily more usefull. In my career I've seen plenty of bad/unclear exceptions thrown from libraries that require you to inspect the stacktrace. Exceptions with null or empty error message or useless messages that require you to have a look at the stacktrace and then digging through source code.
I don't suppose you mean logging the inner exceptions with full stacktraces.
Suppressed Exceptions (as far as I can see from the java.lang.Throwable sources) get fully accounted for with full stacktraces in the default printStackTrace and are available for API-based runtime investigation with the mentioned getSuppressed.
As we're essentially suppressing exceptions I think that the addSuppressed API usage would be a proper replacement (available from Java 7 onwards)

[aikebah]

Revisiting the addSuppressed documentation makes me reconsider... API contract of addSuppressed is for a different purpose - being able to swallow exceptions that happen after some initial exception that you intend to (re)throw at the end of error handling code.

So seems better to in some way improve current ExceptionCollection in order to ensure that full error information is retained and reported for all cases.

[aikebah]

I'm leaning towards a short-term mitigation along the lines of a verbose message for the Exception Collection that allows to review the Exception-cause-stack for each of the exceptions in the collection:

Build the exception message of the ExceptionCollection that would fully report the caused-by traces of each exception in the form
exceptionCollection.message\n
\t <exception.getClass()> : <exception.getMessage()>\n
\t\t caused by <exception.getCause().getClass()> : <exception.getCause().getMessage()>\n
\t\t ...
\t <exception.getClass()> : <exception.getMessage()>\n
\t\tcaused by <exception.getCause().getClass()> : <exception.getCause().getMessage()>\n
\t\t ...
...

In this way errors should become more easily traceable to their root cause for tools that don't use printStackTrace to show the stacktrace leading up to an exception.

For the long term my gut feel is that the exception handling needs re-architecting to get the (mutable!!!) ExceptionCollection Exception replaced. For the rationale see SonarQube's documentation for squid:S1165.
My current understanding of the codebase is still too limited to form a view on what would be the good architecture to retain the ability to temporarily swallow exceptions (and report all of them in one go at the end of all analysis attempts) and combine that with a good ability to deduce the reasons for failure from the information that gets reported.

For only one exception it could be accounted for by setting that exception as the cause for the thrown exception. But if the ExceptionCollection holds more than one fatal exception (e.g. from more than one analyzer) we would not be able to build a single cause-stack to show the errors encountered and we might as well just stop on the first exception as the others would be non-traceable for their root-cause and thus non-resolvable for the user until they become the first-in-line that gets reported in the exception-cause-stack.

@jeremylong would like to hear your thoughts on such a short-term approach, combined with an enhancement issue for a long-term solution. I would be willing to work on building a short-term mitigation and invest some time in trying to come up with a design of a new way of handling the exceptions that would fit the desired immutable state of the Java exception model and allow for the delayed reporting with full traceability of root causes for each of the reported exceptions - that design proposal could then be discussed in the context of that enhancement issue.

[hakanai]

Following on from my duplicate ticket, the line which was throwing away the cause was:

DependencyCheck/core/src/main/java/org/owasp/dependencycheck/exception/ExceptionCollection.java

Line 59 in dbaac07

super(MSG);

At a minimum, this code could include the first exception as the cause, which would be better than nothing. What we generally do at work in the same situation though is to include the first exception as the cause, and then chain the rest on with addSuppressed.

Then it's up to Gradle to format it properly. Which mostly it has been for us, but we do ask it to dump full stack traces on failure.

[aikebah]

@jeremylong I created the proposed short-term fix of an extended log message. In the gradle plugin with gradle -s the output of the sample build.gradle from #2909 now yields:

Caused by: org.owasp.dependencycheck.exception.ExceptionCollection: One or more exceptions occurred during analysis:
        InitializationException: Unexpected Exception
                caused by NoClassDefFoundError: org/apache/lucene/codecs/lucene41/Lucene41PostingsFormat
                caused by ClassNotFoundException: org.apache.lucene.codecs.lucene41.Lucene41PostingsFormat
        at org.owasp.dependencycheck.Engine.analyzeDependencies(Engine.java:644)
        at org.owasp.dependencycheck.Engine$analyzeDependencies$0.call(Unknown Source)
        at org.owasp.dependencycheck.gradle.tasks.AbstractAnalyze.analyze(AbstractAnalyze.groovy:89)
        ... 95 more

If you agree with the approach I can merge it into master

[jeremylong]

I think that is an okay quick fix for the issue. I also agree the overall exception handling may need to be re-worked.

[aikebah]

Quick-fix will be part of the next release. Structural improvement to the exception handling will be handled under the new enhancement issue.

[danberindei]

@jeremylong since this issue is closed, is there another issue for reworking the overall exception handling?

@aikebah you say

Revisiting the addSuppressed documentation makes me reconsider... API contract of addSuppressed is for a different purpose - being able to swallow exceptions that happen after some initial exception that you intend to (re)throw at the end of error handling code.

But the addSuppressed() javadoc explicitly states that reporting multiple sibling exceptions as a single exception is a valid use case:

Note that programmer written code is also able to take advantage of calling this method in situations where there are multiple sibling exceptions and only one can be propagated.