Quarkus: Test failures not clear on root causes

[galderz]

While testing Mandrel 20.2, we discovered the following test failure:

2020-08-20T14:15:21.5852034Z [ERROR] Failures: 
2020-08-20T14:15:21.5852333Z [ERROR]   ServletITCase>ServletTestCase.testStaticResource:32 1 expectation failed.
2020-08-20T14:15:21.5853201Z Response body doesn't match expectation.
2020-08-20T14:15:21.5856642Z Expected: a string containing "A HTML page"
2020-08-20T14:15:21.5859431Z   Actual: 
2020-08-20T14:15:21.5859984Z 
2020-08-20T14:15:21.5860194Z [ERROR]   ServletITCase>ServletTestCase.testStaticResourceSubdir:38 1 expectation failed.
2020-08-20T14:15:21.5863287Z Response body doesn't match expectation.
2020-08-20T14:15:21.5863521Z Expected: a string containing "A HTML page"
2020-08-20T14:15:21.5863684Z   Actual: 
2020-08-20T14:15:21.5863752Z 
2020-08-20T14:15:21.5866046Z [ERROR]   ServletITCase>ServletTestCase.testWebjars:66 1 expectation failed.
2020-08-20T14:15:21.5866290Z Expected status code <200> but was <500>.
2020-08-20T14:15:21.5868913Z 
2020-08-20T14:15:21.5869068Z [ERROR]   ServletITCase>ServletTestCase.testWelcomeFile:44 1 expectation failed.
2020-08-20T14:15:21.5869828Z Response body doesn't match expectation.
2020-08-20T14:15:21.5873368Z Expected: a string containing "A HTML page"
2020-08-20T14:15:21.5873568Z   Actual: 
2020-08-20T14:15:21.5873684Z 
2020-08-20T14:15:21.5873797Z [INFO] 
2020-08-20T14:15:21.5877460Z [ERROR] Tests run: 141, Failures: 4, Errors: 0, Skipped: 2

Looking closely we discovered that the issue was this error message printed in json format (??):

2020-08-20T14:15:16.6258004Z {"timestamp":"2020-08-20T14:15:16.293Z","sequence":1474,"loggerClassName":"io.undertow.UndertowLogger_$logger","loggerName":"io.undertow.request","level":"ERROR","message":"UT005071: Undertow request failed HttpServerExchange{ GET /index.html delegate io.undertow.vertx.VertxHttpExchange@7fa8ee239958}","threadName":"executor-thread-2","threadId":21,"mdc":{},"ndc":"","hostName":"fv-az71","processName":"NativeImageGeneratorRunner$JDK9Plus","processId":3286,"exception":{"refId":1,"exceptionType":"java.util.MissingResourceException","message":"Resource bundle not found sun.util.resources.TimeZoneNames. Register the resource bundle using the option -H:IncludeResourceBundles=sun.util.resources.TimeZoneNames.","frames":[{"class":"com.oracle.svm.core.jdk.LocalizationSupport","method":"getCached","line":66},{"class":"sun.util.resources.Bundles","method":"loadBundleOf","line":52},{"class":"sun.util.resources.Bundles","method":"of","line":106},{"class":"sun.util.resources.LocaleData$1","method":"run","line":185},{"class":"sun.util.resources.LocaleData$1","method":"run","line":182},{"class":"java.security.AccessController","method":"doPrivileged","line":83},{"class":"sun.util.resources.LocaleData","method":"getBundle","line":182},{"class":"sun.util.resources.LocaleData","method":"getTimeZoneNames","line":114},{"class":"sun.util.locale.provider.LocaleResources","method":"getTimeZoneNames","line":270},{"class":"sun.util.cldr.CLDRTimeZoneNameProviderImpl","method":"deriveFallbackName","line":170},{"class":"sun.util.cldr.CLDRTimeZoneNameProviderImpl","method":"getDisplayNameArray","line":93},{"class":"sun.util.locale.provider.TimeZoneNameProviderImpl","method":"getDisplayName","line":99},{"class":"sun.util.locale.provider.TimeZoneNameUtility$TimeZoneNameGetter","method":"getName","line":271},{"class":"sun.util.locale.provider.TimeZoneNameUtility$TimeZoneNameGetter","method":"getObject","line":229},{"class":"sun.util.locale.provider.TimeZoneNameUtility$TimeZoneNameGetter","method":"getObject","line":215},{"class":"sun.util.locale.provider.LocaleServiceProviderPool","method":"getLocalizedObjectImpl","line":150},{"class":"sun.util.locale.provider.LocaleServiceProviderPool","method":"getLocalizedObject","line":242},{"class":"sun.util.locale.provider.TimeZoneNameUtility","method":"retrieveDisplayNamesImpl","line":197},{"class":"sun.util.locale.provider.TimeZoneNameUtility","method":"retrieveDisplayName","line":150},{"class":"java.util.TimeZone","method":"getDisplayName","line":401},{"class":"java.text.SimpleDateFormat","method":"subFormat","line":1302},{"class":"java.text.SimpleDateFormat","method":"format","line":997},{"class":"java.text.SimpleDateFormat","method":"format","line":967},{"class":"java.text.DateFormat","method":"format","line":374},{"class":"io.undertow.util.DateUtils","method":"toDateString","line":109},{"class":"io.undertow.server.handlers.resource.CachedResource","method":"<init>","line":64},{"class":"io.undertow.server.handlers.resource.CachingResourceManager","method":"getResource","line":103},{"class":"io.undertow.server.handlers.resource.CachingResourceManager","method":"getResource","line":30},{"class":"io.undertow.servlet.handlers.ServletPathMatches","method":"getServletHandlerByPath","line":97},{"class":"io.undertow.servlet.handlers.ServletInitialHandler","method":"handleRequest","line":124},{"class":"io.undertow.server.handlers.HttpContinueReadHandler","method":"handleRequest","line":43},{"class":"io.quarkus.undertow.runtime.UndertowDeploymentRecorder$1","method":"handleRequest","line":114},{"class":"io.undertow.server.Connectors","method":"executeRootHandler","line":290},{"class":"io.undertow.server.DefaultExchangeHandler","method":"handle","line":18},{"class":"io.quarkus.undertow.runtime.UndertowDeploymentRecorder$6$1","method":"run","line":398},{"class":"java.util.concurrent.Executors$RunnableAdapter","method":"call","line":515},{"class":"java.util.concurrent.FutureTask","method":"run","line":264},{"class":"org.jboss.threads.ContextClassLoaderSavingRunnable","method":"run","line":35},{"class":"org.jboss.threads.EnhancedQueueExecutor","method":"safeRun","line":2046},{"class":"org.jboss.threads.EnhancedQueueExecutor$ThreadBody","method":"doRunTask","line":1578},{"class":"org.jboss.threads.EnhancedQueueExecutor$ThreadBody","method":"run","line":1452},{"class":"org.jboss.threads.DelegatingRunnable","method":"run","line":29},{"class":"org.jboss.threads.ThreadLocalResettingRunnable","method":"run","line":29},{"class":"java.lang.Thread","method":"run","line":834},{"class":"org.jboss.threads.JBossThread","method":"run","line":479},{"class":"com.oracle.svm.core.thread.JavaThreads","method":"threadStartRoutine","line":517},{"class":"com.oracle.svm.core.posix.thread.PosixJavaThreads","method":"pthreadStartRoutine","line":192}]}}

Full logs.

The issue is caused by https://github.com/graalvm/mandrel/issues/106, but the Quarkus test should log such errors better: the exception should be printed as is (no json) and the message sent back to the client should be appropiate (iow, not empty but say there's a server error and provide info?).

[jaikiran]

I think this should take care of it https://github.com/quarkusio/quarkus/pull/11787

[galderz]

Thx @jaikiran!! Your work really helps improve Quarkus!! :)