NullPointerException from aquery with aspects and protobuf output

[cmcgee1024]

Description of the bug:

When running an aquery on a target that was previously built with an aspect ("—aspects" command-line) and the same daemon process the following NullPointerException (NPE) occurs.

java.lang.NullPointerException
	at com.google.devtools.build.lib.skyframe.actiongraph.v2.ActionGraphDump.dumpAspect(ActionGraphDump.java:247)
	at com.google.devtools.build.lib.query2.aquery.ActionGraphProtoOutputFormatterCallback.processOutput(ActionGraphProtoOutputFormatterCallback.java:104)
	at com.google.devtools.build.lib.query2.engine.OutputFormatterCallback.process(OutputFormatterCallback.java:54)
	at com.google.devtools.build.lib.buildtool.PostAnalysisQueryBuildTool.doPostAnalysisQuery(PostAnalysisQueryBuildTool.java:187)
	at com.google.devtools.build.lib.buildtool.PostAnalysisQueryBuildTool.postProcessAnalysisResult(PostAnalysisQueryBuildTool.java:78)
	at com.google.devtools.build.lib.buildtool.BuildTool.buildTargets(BuildTool.java:227)
	at com.google.devtools.build.lib.buildtool.BuildTool.processRequest(BuildTool.java:443)
	at com.google.devtools.build.lib.buildtool.BuildTool.processRequest(BuildTool.java:411)
	at com.google.devtools.build.lib.runtime.commands.AqueryCommand.exec(AqueryCommand.java:137)
	at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.execExclusively(BlazeCommandDispatcher.java:585)
	at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.exec(BlazeCommandDispatcher.java:231)
	at com.google.devtools.build.lib.server.GrpcServerImpl.executeCommand(GrpcServerImpl.java:550)
	at com.google.devtools.build.lib.server.GrpcServerImpl.lambda$run$1(GrpcServerImpl.java:614)
	at io.grpc.Context$1.run(Context.java:579)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)

What's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.

This bug is difficult to reproduce since it is intermittent and happens with a specific complex target in our environment. Here's a generalized template of the command that exhibits the problem in our environment.

bazel shutdown && bazel clean && bazel build --aspects=//tools:foo.bzl%foo_aspect //:help && bazel aquery --aspects=//tools:bar.bzl%bar_aspect —include_aspects=true 'deps(//:help)' --output=proto > /tmp/foo.proto

Note: the foo_aspect is added for the bazel build, but not for the bazel aquery, which uses the bar_aspect.

The NPE does not occur if the aspect is not added to the original build. The output of the aquery must be proto, and not the default text output. Also, the NPE does not occur if the daemon is shut down in between the two commands like this.

bazel shutdown && bazel clean && bazel build --aspects=//tools:foo.bzl%foo_aspect //:help && bazel shutdown && bazel aquery --aspects=//tools:bar.bzl%bar_aspect —include_aspects=true 'deps(//:help)' --output=proto > /tmp/foo.proto

Which operating system are you running Bazel on?

macOS 12.3

What is the output of bazel info release?

5.1.1-8-g30432e50c5

If bazel info release returns development version or (@non-git), tell us how you built Bazel.

No response

What's the output of git remote get-url origin; git rev-parse master; git rev-parse HEAD ?

No response

Have you found anything relevant by searching the web?

This particular NPE does not appear to show up in the typical places.

Any other information, logs, or outputs that you want to share?

WARNING: Targets were missing from graph: [ConfiguredTargetKey{label=@ext//:abc, config=BuildConfigurationValue.Key[deadbeef]}]
WARNING: Targets were missing from graph: [ConfiguredTargetKey{label=@ext//:abc, config=BuildConfigurationValue.Key[deadbeef]}, ConfiguredTargetKey{label=//bazel/tools/toolchain/foo:bar, config=BuildConfigurationValue.Key[deadbeef]}, ConfiguredTargetKey{label=//bazel/tools/toolchain/foo:bar, config=BuildConfigurationValue.Key[deadbeef]}]
WARNING: Targets were missing from graph: [ConfiguredTargetKey{label=@ext2//:def, config=BuildConfigurationValue.Key[deadbeef]}, ConfiguredTargetKey{label=@bazel_tools//tools/jdk:toolchain_java8, config=BuildConfigurationValue.Key[deadbeef]}]

[cmcgee1024]

After further investigation here are some observations.

ActionGraphProtoOutputFormatterCallback.processOutput() is calling accessor.getAspectValues(configuredTarget) but not checking whether the values are null, which causes the NPE around line 104. A similar class ActionGraphTextOutputFormatterCallback has a simple null check in its processOutput() that guards against this. There should probably be a null check in all OutputFormatterCallback classes, including ActionGraphSummaryOutputFormatterCallback. They all call ConfiguredTargetValueAccessor.getAspectValues(), which gets aspect values from walkableGraph.getValue() and this method is declared @nullable, so we can expect nulls to show up in the Collection in some cases.

More than just the NPE, there appears to be some kind of a caching problem as well. Of the two commands above, the first one exhibits this null pointer problem, but only with this specific target. The revDeps looks something like this in ConfiguredTargetValueAccessor:

[0] foo_aspect -> value = null
[1] TargetCompletionValue (not quite sure what this is)
[2] bar_aspect -> value not null

Since the foo_aspect's value is null, I checked walkableGraph.getException() and walkableGraph.isCycle(). Exception is null and cycle is false.

If I run the command above on a different, but similar target I sometimes get this with no NPE:

[0] foo_aspect -> value not null
[1] TargetCompletionValue
[2] bar_aspect -> value not null

However, if I put a shutdown command in between the build and aquery I get this.

[0] bar_aspect -> value not null

From my perspective, I find the last case to match better what I expect to happen here. Something about the build command remains in the daemon in memory and affects the aquery. These aspect values, as long as they are not null, get dumped to the output. So, it appears that depending on the state of the bazel daemon you get different output. I suspect that there's another bug here since the output can sometimes contain this extra aspect, and other times not. I'm not sure if this could affect tools that are interpreting the protocol buffer output.

[joeleba]

Thanks for filing the issue. The NPE shouldn't be allowed to happen, there's a fix coming out today. The inconsistency you described is actually a known limitation of aquery (#14156).

[brentleyjones]

@bazel-io flag

[keertk]

@bazel-io fork 6.2.0