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

Upgrade logback-steno version and simplify verticle launch logging. #8

Merged
merged 1 commit into from
Nov 24, 2016
Merged

Upgrade logback-steno version and simplify verticle launch logging. #8

merged 1 commit into from
Nov 24, 2016

Conversation

vjkoskela
Copy link
Contributor

The current logging drops important information out of the result chain and logs multiple error messages many of which are unimportant. This leads to more time spent finding the actual cause of verticle deployment failure and requires a deeper than desirable knowledge of the deployment code to find the useful information.

This pull request pushes all exceptions to the DeploymentMonitorHandler where they are all logged (if any). Some of the error messages along the way have been removed, in my opinion either rethrow (or in async pass on the cause) or log, but not both. In some cases debug log messages are emitted instead where additional information may aid with debugging the launcher itself.

I'm open to changing any of the messaging, levels, etc.. -- there are some parts that I did not have ideal answers for, so please let me know what works for you as well.

Below are snapshots of output for the same failure using 3.2.0 and 3.2.1-SNAPSHOT (this PR) for comparison. They used the KeyValueEncoder from Logback-Steno but the output would be reasonably similar under the StenoEncoder.

Old Logging:

2016-10-19 21:08:37,933 vert.x-eventloop-thread-0 [INFO] com.groupon.vertx.utils.deployment.VerticleDeployment : name="start", eventSource="verticleDeployment", method="deploy", instances="1", name="Session-TableManager", class="com.qualtrics.dynamodb.timeseries.TableManagerVerticle" 
2016-10-19 21:08:37,934 vert.x-eventloop-thread-2 [INFO] com.qualtrics.dynamodb.timeseries.TableManagerVerticle : name="start", message="tableManagerVerticle" 
2016-10-19 21:08:37,940 vert.x-eventloop-thread-2 [INFO] com.qualtrics.dynamodb.timeseries.TableManagerVerticle : name="log", message="Computed update tables interval.", updateTablesInterval="PT2898.178S" 
2016-10-19 21:08:39,947 vert.x-eventloop-thread-0 [ERROR] com.groupon.vertx.utils.deployment.VerticleDeployment : name="failure", eventSource="verticleDeployment", method="deploy", reason="Failed to deploy verticle Session-TableManager", instances="1", name="Session-TableManager", class="com.qualtrics.dynamodb.timeseries.TableManagerVerticle" com.amazonaws.AmazonClientException: Unable to load AWS credentials from any provider in the chain
    at com.amazonaws.auth.AWSCredentialsProviderChain.getCredentials(AWSCredentialsProviderChain.java:131)
    at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.invoke(DynamoDbAsyncClient.java:527)
    at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.listTablesAsync(DynamoDbAsyncClient.java:353)
    at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.listTablesAsync(DynamoDbAsyncClient.java:358)
    at com.qualtrics.dynamodb.timeseries.TableManagerVerticle.startUnsafe(TableManagerVerticle.java:118)
    at com.qualtrics.dynamodb.timeseries.TableManagerVerticle.start(TableManagerVerticle.java:76)
    at io.vertx.core.impl.DeploymentManager.lambda$doDeploy$8(DeploymentManager.java:434)
    at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:359)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:339)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:393)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    at java.lang.Thread.run(Thread.java:745)

2016-10-19 21:08:39,948 vert.x-eventloop-thread-0 [INFO] com.groupon.vertx.utils.deployment.MultiVerticleDeployment : name="deployNextVerticle", eventSource="multiVerticleDeployment", method="deploy" 
2016-10-19 21:08:39,948 vert.x-eventloop-thread-0 [ERROR] com.groupon.vertx.utils.deployment.DeploymentMonitorHandler : name="error", eventSource="verticleDeployHandler", method="handle", reason="Caught exception; failed to deploy verticle" java.lang.Exception: Failed to deploy verticle Session-TableManager
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:65)
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:56)
    at io.vertx.core.impl.DeploymentManager.lambda$reportResult$6(DeploymentManager.java:396)
    at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:359)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:339)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:393)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    at java.lang.Thread.run(Thread.java:745)
2016-10-19 21:08:40,502 vert.x-eventloop-thread-0 [ERROR] com.groupon.vertx.utils.deployment.DeploymentMonitorHandler : name="error", eventSource="verticleDeployHandler", method="handleCompletion", reason="Failed to deploy 2 of 3 verticle(s)" 
2016-10-19 21:08:40,502 vert.x-eventloop-thread-0 [ERROR] com.groupon.vertx.utils.deployment.MultiVerticleDeployment : name="failure", eventSource="multiVerticleDeployment", method="deploy", reason="Failed to deploy verticle: Failed to deploy 2 of 3 verticle(s)" java.lang.Exception: Failed to deploy 2 of 3 verticle(s)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.handleCompletion(DeploymentMonitorHandler.java:85)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.checkForCompletion(DeploymentMonitorHandler.java:74)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.handle(DeploymentMonitorHandler.java:59)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$2.handle(MultiVerticleDeployment.java:108)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$2.handle(MultiVerticleDeployment.java:100)
    at io.vertx.core.impl.FutureImpl.checkCallHandler(FutureImpl.java:158)
    at io.vertx.core.impl.FutureImpl.complete(FutureImpl.java:111)
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:60)
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:56)
    at io.vertx.core.impl.DeploymentManager.lambda$reportResult$6(DeploymentManager.java:396)
    at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:359)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:339)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:393)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    at java.lang.Thread.run(Thread.java:745)

2016-10-19 21:08:40,503 vert.x-eventloop-thread-0 [ERROR] com.groupon.vertx.utils.MainVerticle : name="abort", eventSource="mainVerticle", method="start", reason="Shutting down due to one or more errors" java.lang.Exception: Failed to deploy verticle: Failed to deploy 2 of 3 verticle(s)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$1.handle(MultiVerticleDeployment.java:93)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$1.handle(MultiVerticleDeployment.java:84)
    at io.vertx.core.impl.FutureImpl.checkCallHandler(FutureImpl.java:158)
    at io.vertx.core.impl.FutureImpl.fail(FutureImpl.java:148)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.handleCompletion(DeploymentMonitorHandler.java:85)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.checkForCompletion(DeploymentMonitorHandler.java:74)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.handle(DeploymentMonitorHandler.java:59)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$2.handle(MultiVerticleDeployment.java:108)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$2.handle(MultiVerticleDeployment.java:100)
    at io.vertx.core.impl.FutureImpl.checkCallHandler(FutureImpl.java:158)
    at io.vertx.core.impl.FutureImpl.complete(FutureImpl.java:111)
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:60)
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:56)
    at io.vertx.core.impl.DeploymentManager.lambda$reportResult$6(DeploymentManager.java:396)
    at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:359)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:339)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:393)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.Exception: Failed to deploy 2 of 3 verticle(s)
    ... 15 common frames omitted

2016-10-19 21:08:40,504 vert.x-eventloop-thread-0 [INFO] com.groupon.vertx.utils.deployment.VerticleDeployment : name="success", eventSource="verticleDeployment", method="deploy", id="1da1e311-e985-40a1-b9b0-eda8124a80ee", instances="8", name="HttpServerVerticle", class="com.qualtrics.core.common.http.HttpServerVerticle" 

You can see how far up the actual useful error is and how many useless stack traces are output after it (developer sees error + stack trace they expect to find something useful).

New Logging:

2016-10-19 21:04:55,920 vert.x-eventloop-thread-0 [INFO] com.groupon.vertx.utils.deployment.VerticleDeployment : name="start", eventSource="verticleDeployment", method="deploy", instances="1", name="Login-TableManager", class="com.qualtrics.dynamodb.timeseries.TableManagerVerticle" 
2016-10-19 21:04:55,920 vert.x-eventloop-thread-2 [INFO] com.qualtrics.dynamodb.timeseries.TableManagerVerticle : name="start", message="tableManagerVerticle" 
2016-10-19 21:04:55,922 vert.x-eventloop-thread-2 [INFO] com.qualtrics.dynamodb.timeseries.TableManagerVerticle : name="log", message="Computed update tables interval.", updateTablesInterval="PT2898.178S" 
2016-10-19 21:04:57,929 vert.x-eventloop-thread-0 [DEBUG] com.groupon.vertx.utils.deployment.VerticleDeployment : name="failure", eventSource="verticleDeployment", method="deploy", message="Failed to deploy verticle Login-TableManager" 
2016-10-19 21:04:57,932 vert.x-eventloop-thread-0 [ERROR] com.groupon.vertx.utils.deployment.DeploymentMonitorHandler : name="error", eventSource="verticleDeployHandler", method="handleCompletion", reason="Failed to deploy 2 of 3 verticle(s)" java.lang.Exception: Failed to deploy 2 of 3 verticle(s)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.handleCompletion(DeploymentMonitorHandler.java:84)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.checkForCompletion(DeploymentMonitorHandler.java:73)
    at com.groupon.vertx.utils.deployment.DeploymentMonitorHandler.handle(DeploymentMonitorHandler.java:60)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$2.handle(MultiVerticleDeployment.java:107)
    at com.groupon.vertx.utils.deployment.MultiVerticleDeployment$2.handle(MultiVerticleDeployment.java:98)
    at io.vertx.core.impl.FutureImpl.checkCallHandler(FutureImpl.java:158)
    at io.vertx.core.impl.FutureImpl.fail(FutureImpl.java:148)
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:65)
    at com.groupon.vertx.utils.deployment.VerticleDeployment$1.handle(VerticleDeployment.java:56)
    at io.vertx.core.impl.DeploymentManager.lambda$reportResult$6(DeploymentManager.java:396)
    at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:359)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:339)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:393)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    at java.lang.Thread.run(Thread.java:745)
    Suppressed: java.lang.Exception: Failed to deploy verticle Session-TableManager
        ... 8 common frames omitted
    Caused by: com.amazonaws.AmazonClientException: Unable to load AWS credentials from any provider in the chain
        at com.amazonaws.auth.AWSCredentialsProviderChain.getCredentials(AWSCredentialsProviderChain.java:131)
        at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.invoke(DynamoDbAsyncClient.java:527)
        at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.listTablesAsync(DynamoDbAsyncClient.java:353)
        at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.listTablesAsync(DynamoDbAsyncClient.java:358)
        at com.qualtrics.dynamodb.timeseries.TableManagerVerticle.startUnsafe(TableManagerVerticle.java:118)
        at com.qualtrics.dynamodb.timeseries.TableManagerVerticle.start(TableManagerVerticle.java:76)
        at io.vertx.core.impl.DeploymentManager.lambda$doDeploy$8(DeploymentManager.java:434)
        ... 5 common frames omitted
    Suppressed: java.lang.Exception: Failed to deploy verticle Login-TableManager
        ... 8 common frames omitted
    Caused by: com.amazonaws.AmazonClientException: Unable to load AWS credentials from any provider in the chain
        at com.amazonaws.auth.AWSCredentialsProviderChain.getCredentials(AWSCredentialsProviderChain.java:131)
        at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.invoke(DynamoDbAsyncClient.java:527)
        at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.listTablesAsync(DynamoDbAsyncClient.java:353)
        at com.qualtrics.vertx.dynamodb.DynamoDbAsyncClient.listTablesAsync(DynamoDbAsyncClient.java:358)
        at com.qualtrics.dynamodb.timeseries.TableManagerVerticle.startUnsafe(TableManagerVerticle.java:118)
        at com.qualtrics.dynamodb.timeseries.TableManagerVerticle.start(TableManagerVerticle.java:76)
        at io.vertx.core.impl.DeploymentManager.lambda$doDeploy$8(DeploymentManager.java:434)
        ... 5 common frames omitted

2016-10-19 21:04:57,933 vert.x-eventloop-thread-0 [WARN] com.groupon.vertx.utils.MainVerticle : name="abort", eventSource="mainVerticle", method="start", message="Shutting down due to one or more errors" 

Under the new logging code there is a single error message with all the necessary exceptions in one place and it's the second last line of output before the program exits.

Thanks!
Ville

@ddimensia ddimensia merged commit c99a85c into groupon:master Nov 24, 2016
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