search

openrewrite / rewrite-logging-frameworks

OpenRewrite recipes for assisting with Java logging migration tasks.
Apache License 2.0
25 stars 20 forks source link

Bug : java.lang.NullPointerException while trying to run individual recipe org.openrewrite.java.logging.ParameterizedLogging #60

Closed yeikel closed 2 years ago

yeikel commented 2 years ago

Command : mvn rewrite:run -Drewrite.activeRecipes=org.openrewrite.java.logging.ParameterizedLogging

[ERROR] Failed to execute goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run (default-cli) on project module1: Execution default-cli of goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run failed: java.lang.NullPointerException -> [Help 1]
org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run (default-cli) on project module1: Execution default-cli of goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run failed: java.lang.NullPointerException

Simplified logs : 

[INFO] --- rewrite-maven-plugin:4.22.2:run (default-cli) @ module1 ---
[INFO] Using active recipe(s) [org.openrewrite.java.logging.ParameterizedLogging]
[INFO] Using active styles(s) []
[INFO] Validating active recipes...
[WARNING] Unable to initialize RocksdbMavenPomCache, falling back to InMemoryMavenPomCache
[INFO] Parsing Java main files...
[INFO] Parsing Java test files...
[INFO] Running recipe(s)...
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary for module1 0.0.0-SNAPSHOT:
[INFO] 
[INFO] module1 ........................................... FAILURE [ 16.122 s]
[INFO] module2.......................................... SKIPPED
[INFO] module2.......................................... SKIPPED

[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  16.477 s (Wall Clock)
[INFO] Finished at: 2022-04-08T00:43:18-04:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run (default-cli) on project module1: Execution default-cli of goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run failed: java.lang.NullPointerException -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/PluginExecutionException
➜  module1 git:(main)

Stacktrace : 

[ERROR] Failed to execute goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run (default-cli)
: Execution default-cli of goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run failed: java.lang.NullPointerException -> [Help 1]
org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run (default-cli) on project module1: Execution default-cli of goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run failed: java.lang.NullPointerException
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:215)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:186)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: org.apache.maven.plugin.PluginExecutionException: Execution default-cli of goal org.openrewrite.maven:rewrite-maven-plugin:4.22.2:run failed: java.lang.NullPointerException
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:148)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:186)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: java.util.concurrent.CompletionException: java.lang.NullPointerException
    at java.util.concurrent.CompletableFuture.encodeThrowable (CompletableFuture.java:331)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1452)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.andTree (CompletableFuture.java:1442)
    at java.util.concurrent.CompletableFuture.allOf (CompletableFuture.java:2337)
    at org.openrewrite.RecipeScheduler.mapAsync (RecipeScheduler.java:54)
    at org.openrewrite.RecipeScheduler.scheduleVisit (RecipeScheduler.java:192)
    at org.openrewrite.RecipeScheduler.scheduleVisit (RecipeScheduler.java:297)
    at org.openrewrite.RecipeScheduler.scheduleRun (RecipeScheduler.java:87)
    at org.openrewrite.Recipe.run (Recipe.java:248)
    at org.openrewrite.Recipe.run (Recipe.java:239)
    at org.openrewrite.Recipe.run (Recipe.java:235)
    at org.openrewrite.maven.AbstractRewriteMojo.listResults (AbstractRewriteMojo.java:179)
    at org.openrewrite.maven.RewriteRunMojo.execute (RewriteRunMojo.java:41)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:186)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: java.lang.NullPointerException
    at org.antlr.v4.runtime.CharStreams.fromString (CharStreams.java:222)
    at org.antlr.v4.runtime.CharStreams.fromString (CharStreams.java:212)
    at org.openrewrite.java.MethodMatcher.<init> (MethodMatcher.java:84)
    at org.openrewrite.java.MethodMatcher.<init> (MethodMatcher.java:105)
    at org.openrewrite.java.search.UsesMethod.<init> (UsesMethod.java:28)
    at org.openrewrite.java.logging.ParameterizedLogging.getSingleSourceApplicableTest (ParameterizedLogging.java:65)
    at org.openrewrite.RecipeScheduler.lambda$scheduleVisit$5 (RecipeScheduler.java:196)
    at org.openrewrite.RecipeScheduler.lambda$mapAsync$0 (RecipeScheduler.java:50)
    at org.openrewrite.scheduling.ForkJoinScheduler.lambda$schedule$0 (ForkJoinScheduler.java:41)
    at java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec (ForkJoinTask.java:1407)
    at java.util.concurrent.ForkJoinTask.doExec (ForkJoinTask.java:290)
    at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec (ForkJoinPool.java:1020)
    at java.util.concurrent.ForkJoinPool.scan (ForkJoinPool.java:1656)
    at java.util.concurrent.ForkJoinPool.runWorker (ForkJoinPool.java:1594)
    at java.util.concurrent.ForkJoinWorkerThread.run (ForkJoinWorkerThread.java:183)

Env details : 

 mvn --version
Apache Maven 3.8.4 (9b656c72d54e5bacbed989b64718c159fe39b537)
Maven home: /Users/yeikel/.sdkman/candidates/maven/current
Java version: 11.0.13, vendor: Amazon.com Inc., runtime: /Users/yeikel/.sdkman/candidates/java/11.0.13.8.1-amzn
Default locale: en_US, platform encoding: UTF-8
OS name: "mac os x", version: "11.5.1", arch: "x86_64", family: "mac"
yeikel commented 2 years ago

Note : I am able to run individual recipes. For example mvn rewrite:run -Drewrite.activeRecipes=org.openrewrite.java.cleanup.FinalClass works as expected

yeikel commented 2 years ago

Is this just an outdated log/configuration within OpenRewrite?

it seems that mvn rewrite:run -Drewrite.activeRecipes=org.openrewrite.java.logging.slf4j.ParameterizedLogging works as expected, but the logs show :

Changes have been made to JsonUtilsTest.java by: [WARNING] org.openrewrite.java.logging.ParameterizedLogging

Which seems to be the source of my error

pway99 commented 2 years ago

Thanks @yeikel. You are correct #49 and #50 modified org.openrewrite.java.logging.ParameterizedLogging such that methodPattern should be a required argument which would prevent the NPE and provide guidance on how to run the recipe.

yeikel commented 2 years ago

Thanks @yeikel. You are correct #49 and #50 modified org.openrewrite.java.logging.ParameterizedLogging such that methodPattern should be a required argument which would prevent the NPE and provide guidance on how to run the recipe.

Can we update the log of applied recipes as well? Not sure if your fix did it

As the current message is misleading

pway99 commented 2 years ago

Can we update the log of applied recipes as well? Not sure if your fix did it As the current message is misleading

Are you referring to this? https://github.com/openrewrite/rewrite-maven-plugin/issues/326

yeikel commented 2 years ago

Can we update the log of applied recipes as well? Not sure if your fix did it As the current message is misleading

Are you referring to this? openrewrite/rewrite-maven-plugin#326

No

I am referring to the fact that it prints : 

[WARNING] Changes have been made to Hello.java by:
[WARNING]     org.openrewrite.java.logging.ParameterizedLogging

When what it applied is org.openrewrite.java.logging.slf4j.ParameterizedLogging

pway99 commented 2 years ago

Ok. That is a case where the org.openrewrite.java.logging.slf4j.ParameterizedLogging is a declarative recipe having org.openrewrite.java.logging.slf4j.ParameterizedLogging. ParameterizedLogging is logged as a recipe that made changes because is the actual recipe that actually modified the AST. I am not sure how that is related to the NPE defined in this ussue.

yeikel commented 2 years ago

Ok. That is a case where the org.openrewrite.java.logging.slf4j.ParameterizedLogging is a declarative recipe having org.openrewrite.java.logging.slf4j.ParameterizedLogging. ParameterizedLogging is logged as a recipe that made changes because is the actual recipe that actually modified the AST. I am not sure how that is related to the NPE defined in this ussue.

It is related because I encounter the NPE when tried to apply the recipe directly following what the log said

mvn rewrite:run -Drewrite.activeRecipes=org.openrewrite.java.logging.ParameterizedLogging

My assumption was that I should be able to apply any recipe printed in the logs but that's not the case. Is my assumption incorrect?

pway99 commented 2 years ago

Yes, your assumption is incorrect, the logs only print the name of the recipe that made changes not including its associated configuration parameters. The NPE was a result of incomplete recipe validation which allowed the recipe to run with an invalid configuration. Now when you invoke mvn rewrite:run -Drewrite.activeRecipes=org.openrewrite.java.logging.ParameterizedLogging the logs will inform you that the methodPattern is null and the recipe will be skipped.

yeikel commented 2 years ago

Yes, your assumption is incorrect, the logs only print the name of the recipe that made changes not including its associated configuration parameters. The NPE was a result of incomplete recipe validation which allowed the recipe to run with an invalid configuration. Now when you invoke mvn rewrite:run -Drewrite.activeRecipes=org.openrewrite.java.logging.ParameterizedLogging the logs will inform you that the methodPattern is null and the recipe will be skipped.

What I don't understand is that I do not have any explicit configuration for openrewrite.java.logging.ParameterizedLogging in my build. What I have is org.openrewrite.java.logging.slf4j.ParameterizedLogging.

My confusion is that the log says that the recipe openrewrite.java.logging.ParameterizedLogging is the one that applied the transformations when it was actually org.openrewrite.java.logging.slf4j.ParameterizedLogging

When I then tried to apply openrewrite.java.logging.ParameterizedLogging, it failed with the NPE as the one I was supposed to run is org.openrewrite.java.logging.slf4j.ParameterizedLogging instead

Shouldn't the log point out org.openrewrite.java.logging.slf4j.ParameterizedLogging instead of openrewrite.java.logging.ParameterizedLogging?

pway99 commented 2 years ago

Shouldn't the log point out org.openrewrite.java.logging.slf4j.ParameterizedLogging instead of openrewrite.java.logging.ParameterizedLogging?

That would be a rewrite-core issue related to how recipes that made changes are identified, it may not be identifying the parent declarative recipe.

yeikel commented 2 years ago

Shouldn't the log point out org.openrewrite.java.logging.slf4j.ParameterizedLogging instead of openrewrite.java.logging.ParameterizedLogging?

That would be a rewrite-core issue related to how recipes that made changes are identified, it may not be identifying the parent declarative recipe.

Should I create a new issue there instead?

pway99 commented 2 years ago

Should I create a new issue there instead?

Sure, it sounds like your request would be for an additional log message which identifies the active recipe to be logged along with the sub-recipes which actually made the change. Something like the following?

before: 

[INFO] Using active recipe(s) [org.openrewrite.java.logging.slf4j.ParameterizedLogging]
...
[WARNING] Changes have been made to VetService.java by:
[WARNING]     org.openrewrite.java.logging.ParameterizedLogging

after:

[INFO] Using active recipe(s) [org.openrewrite.java.logging.slf4j.ParameterizedLogging]
...
[WARNING] Changes have been made to VetService.java by:
[WARNING]     org.openrewrite.java.logging.slf4j.ParameterizedLogging
[WARNING]         org.openrewrite.java.logging.ParameterizedLogging
yeikel commented 2 years ago

Should I create a new issue there instead?

Sure, it sounds like your request would be for an additional log message which identifies the active recipe to be logged along with the sub-recipes which actually made the change. Something like the following?

before:

[INFO] Using active recipe(s) [org.openrewrite.java.logging.slf4j.ParameterizedLogging]
...
[WARNING] Changes have been made to VetService.java by:
[WARNING]     org.openrewrite.java.logging.ParameterizedLogging

after:

[INFO] Using active recipe(s) [org.openrewrite.java.logging.slf4j.ParameterizedLogging]
...
[WARNING] Changes have been made to VetService.java by:
[WARNING]     org.openrewrite.java.logging.slf4j.ParameterizedLogging
[WARNING]         org.openrewrite.java.logging.ParameterizedLogging

Would org.openrewrite.java.logging.ParameterizedLogging be needed in this case?

pway99 commented 2 years ago

I would say yes. It would be useful for a number of reasons one being the ability to identify which recipe actually modified the AST when debugging inaccurate results.

yeikel commented 2 years ago

I would say yes. It would be useful for a number of reasons one being the ability to identify which recipe actually modified the AST when debugging inaccurate results.

That makes sense

Where should I create the issue? You can probably word it better than me and that would be helpful

Thank you for your support

pway99 commented 2 years ago

Sure any time, I will be happy to create the issue. Thanks for your help also :)