Build: Building more than one target causes `InconsistentAnalysisException`

[eernstg]

Working on package reflectable, I performed a pub upgrade which changed versions of build related packages as follows:

  build 1.2.2
> build_config 0.4.2 (was 0.4.1+1)
  build_daemon 2.1.3
> build_resolvers 1.3.3 (was 1.3.1)
> build_runner 1.7.4 (was 1.7.3)
> build_runner_core 4.4.0 (was 4.3.0)
> build_test 0.10.12+1 (was 0.10.12)

The package test_reflectable contains a set of tests that are used to test reflectable. After the above changes they are all failing, for instance:

[SEVERE] reflectable:reflectable on test/invoke_test.dart.vm_test.dart:

InconsistentAnalysisException: Requested result might be inconsistent with previously returned results

However, if I edit the file build.yaml such that it only specifies a generate_for: property matching a single entry point library then code generation succeeds, and the test runs as expected.

This behavior might be associated with AnalysisDriver.changeFile being invoked by the getter BuildStepImpl.inputLibrary that the Builder in reflectable is using to get access to the input library, and subsequently to all other entities from the analyzer.

Did one of the build packages change recently (build_runner?) in such a way that it is not possible to build more than one target? Or in such a way that it is now required to do something extra in the case where multiple targets are given, in order to avoid InconsistentAnalysisException?

Here is a scenario that gives rise to the failures:

> git clone 'https://github.com/dart-lang/test_reflectable.git'
> cd test_reflectable
> cd tool
> make

The make command runs pub get, pub run build_runner build test, as make -n shows.

[jakemac53]

cc @natebosch I think we got another report of this recently as well.

also cc @scheglov for analyzer perspective here.

[scheglov]

From the analyzer POV, when AnalysisDriver.changeFile() is called, this invalidates any existing AnalysisSession(s). If analysis results consistency is necessary, avoid updating files. If analysis results consistency is not necessary, ask for a new analysis session, or call AnalysisDriver (in which case you will get results from a new analysis session).

[natebosch]

Yes, this also came up in gitter, also about package:reflectable

https://gitter.im/dart-lang/build?at=5e555d19fa9f20553b4e7e02

[jakemac53]

Interesting, I wonder why we are only seeing this for reflectable?

[eernstg]

Simon Binder mentioned getResolvedLibraryByElement here: https://gitter.im/dart-lang/build?at=5e56443bef8d646099d1fa06.

So I tried to change the reflectable code generator such that it awaits getResolvedLibraryByElement with each library immediately after getting all libraries with await resolver.libraries.toList() (which occurs at the very beginning), and use only these cached ResolvedLibraryResults during code generation (so getResolvedLibraryByElement is never called again). This does not eliminate the InconsistentAnalysisExceptions.

[atreeon]

any update on the InconsistentAnalysisException problem @eernstg? Would rolling back to an older version of source_gen or build work, if so what version could I try? My CI keeps failing! Thank you

[atreeon]

one strange thing is that if I rename the file then it sometimes works again, the exception mentions the word cache in the output so possibly there might be a way of clearing something to get it to work???

[eernstg]

@atreeon wrote:

any update on the InconsistentAnalysisException problem

No. I suspect that it is caused by the build framework (perhaps the build_runner) running many code generation steps in an overlapping fashion (because it's asynchronous). The exception is then thrown when AnalysisDriver.changeFile has been invoked as part of the startup sequence for one code generation operation, and some other code generation operation is then blamed for using data which was obtained before that invocation of changeFile.

However, I've performed experiments where the reflectable code generator performs all invocations of getResolvedLibraryByElement at the very beginning (such that this special method which may cause a file to be re-read from disk is never invoked later during code generation), but that makes no difference. The reflectable code generator has no static members and no global variables are used, so each code generation step is exclusively working on data which has been obtained from the analyzer during that same code generation step.

The only thing that really works is to force code generation to run with exactly one target (one "program").

The latest version of reflectable before the one that needed to introduce all these asynchronous operations was v2.0.12. However, that version depends on analyzer version <0.35.0, so I'm afraid that won't fit in with today's projects.

[atreeon]

ah ok, thank you for the reply, yup, v0.35 won't work! I don't understand the internal workings of the code generator but renaming the files seems to overcome the problem...temporarily (but often it reappears when a new file is added or an existing file is changed).

[eernstg]

@atreeon wrote:

renaming the files seems to overcome the problem

OK, then I'd like to know: Which files are being renamed? Are you generating code for a single entry point, that is, does the end result contain exactly one file named *.reflectable.dart, or do you generate multiple such files? It does sound like you are seeing some behaviors that aren't exactly identical to the ones that I can see, and that might bring up something new.

[atreeon]

so I have something like lecture.dart which produces a lecture.g.dart file. So yes, I have one attribute against my lecture.dart file and it produces just one generated file. If I rename the lecture.dart file then sometimes the InconsistentAnalysisException error message goes away.

This is the error I get, and if I rename ex18_.dart it sometimes works again (it is not always that file though).

[SEVERE] value_t2_generator:value_t2 on test/ex18_.dart:
Error running ValueT2Generator
InconsistentAnalysisException: Requested result might be inconsistent with previously returned results

[jakemac53]

It looks like we never updated this issue - I am going to close it because there is nothing that we can do from our end, but I will describe the problem and workaround:

The problem

Calls to libraryFor and isLibrary can now invalidate the current session, because they may add new sources, which requires calling changeFile for those sources. Whenever changeFile is called, the current analyzer session is invalidated.

The workaround

Any direct usage of an AnalysisSession must make sure it grabs the _latest_ session. If grabbing the session off of a LibraryElement, you will need to first ensure you have the _latest_ library element, something like the following:

// where `resolver` came from something like `var resolver = await buildStep.resolver;`,
// and `existingLibraryElement` is some library element that you have and want to grab
// a session from.
var newLibraryElement =
      await resolver.libraryFor(await resolver.assetIdForElement(existingLibraryElement));
var session = newLibraryElement.session;

This is unfortunately verbose and slow but we don't have other solutions at this time. Note that in between any async calls that session could theoretically be invalidated, so you may even want to add some retry logic.

Generally, avoid using the analysis session at all if you can, and if you do use it you will have to be aware of these issues.

[rrousselGit]

:wave:
I am currently facing this issue.

Is there an easy way to know what is causing the invalidation? I am not calling libraryFor/isLibrary directly and my entire generator is synchronous, so I am very confused as to why I get this exception.

[natebosch]

and my entire generator is synchronous, so I am very confused as to why I get this exception.

That's pretty interesting. How reliably can you reproduce this?

What version of build_resolvers do you have? If it's an older one I do wonder whether https://github.com/dart-lang/build/pull/2866 makes any difference.

[rrousselGit]

How reliably can you reproduce this?

Locally I am unable to reproduce it, but the CI fails relatively often https://github.com/rrousselGit/river_pod/runs/1366244210?check_suite_focus=true

And many users of the code-generator have complained about this exception.

What version of build_resolvers do you have?

Latest, so 1.4.3

[rrousselGit]

I think I have pinpointed the issue.
It appears to be caused by calls to session.getParsedLibraryByElement

Is it expected? By understanding is that this method returns the already parse result, rather than parsing it again. So I am not sure why that would invalidate the analysis

I don't fully understand why I do not have this exception locally either. Since the code is synchronous, there shouldn't be concurrency issues.

[scheglov]

The method is called get, but actually it does parse files from their content on request.

Regardless of what the method does, InconsistentAnalysisException is thrown when somewhere, some code called AnalysisDriver.changeFile or addFile. Not necessary yours code. The exception is a signal that this happened, and new results that would be returned from the session might be not consistent with previously returned results. For example if a.dart imports b.dart, you asked for a.dart element model, the result will have elements from a.dart and b.dart. You you then change b.dart and ask for b.dart elements through the same session, you would get element model of b.dart that if potentially different than the one you got via a.dart element model.

[rrousselGit]

In that case, is there a way to access the AstNode of an Element without invalidating the previously obtained results in the process?

The only reason I have this exception is because I do:

AstNode astNodeForElement(Element element) {
  return element.session
      .getParsedLibraryByElement(element.library)
      ?.getElementDeclaration(element)?.node;
}

But this line forces me to use the workaround after every call to this function, which I run in a loop, so it's very unideal

[scheglov]

It is not the call to getParsedLibraryElement that invalidates the session.
It is a call to AnalysisDriver.changeFile(path) somewhere else.
If you can reproduce this locally, you could go into the pub cache, and _hack_ changeFile to write debug output to see from where it is called.

We don't have a way to check if it is safe to assume that none of the results which would be returned by a method of AnalysisSession is not affected by the change. It would be that exactly the file that we ask to parse was changed since the Element was created from it, and not you will not able to find it, because offsets are all off.

[jakemac53]

@rrousselGit I think the problem is likely that you are using the LibraryReader which you are given by the source_gen package. There is some async code between when that is actually created and when it is passed to you I believe.

You could do the trick I listed above to grab a new LibraryElement at the start of your synchronous code:

var newLibraryElement =
      await resolver.libraryFor(await resolver.assetIdForElement(libraryReader.element));

And you could create a new LibraryReader from that new element as well if you prefer that interface.

[rrousselGit]

You could do the trick I listed above to grab a new LibraryElement at the start of your synchronous code:

var newLibraryElement =
      await resolver.libraryFor(await resolver.assetIdForElement(libraryReader.element));

I did that, but that does not work either

Even if the generator start with this workaround and executes synchronously, I still have an InconsistentAnalysisException in the middle of the generation

The only difference is, the reproduction project I had that has an exception 100% of the time no-longer fails. But my different CIs still randomly fails

To be honest, I don't understand what is causing the exception, and the fact that it is random makes things worse.
I am unable to write a regression test, nor am I able to guarantee that I truly fixed the issue

[davidmorgan]

@rrousselGit I had the same with built_value; it worked to run the workaround in a loop w/the failing operation until it succeeds, code snippet here.

[escamoteur]

@eernstg why is this issue closed when people facing still problems?

[eernstg]

@jakemac53, you closed this issue here, but I suspect that the behavior may actually be associated with actions taken in build (probably in build_runner).

Here is an experiment that shows a fact that surprised me. The experiment is performed in a checkout of reflectable.dart.

> emacs reflectable/lib/reflectable_builder.dart # or `vi`, or whatever ;-)
# Add `print('>>> $inputLibrary');` as line 2 in the body of `ReflectableBuilder.build`.
> cd test_reflectable
> pub run build_runner clean
> pub run build_runner build | grep '^>>> '
>>> test_reflectable.test.new_instance_optional_arguments_test
>>> test_reflectable.test.reflect_type_void
>>> test_reflectable.test.parameter_test
>>> test_reflectable.test.corresponding_setter_test
>>> test_reflectable.test.use_prefix_test
>>> test_reflectable.test.unused_reflector_test
>>> test_reflectable.test.private_class_test
>>> test_reflectable.test.member_capability_test
>>> test_reflectable.test.invoker_operator_test
>>> test_reflectable.test.prefixed_reflector_test
>>> test_reflectable.test.superinterfaces_test
>>> test_reflectable.test.mixin_application_static_invoke_test
>>> 
>>> test_reflectable.test.type_variable_test
>>> test_reflectable.test.multi_field_test
>>> test_reflectable.test.meta_reflectors_test
>>> test_reflectable.test.annotated_classes_test
>>> test_reflectable.test.no_such_capability_test
>>> test_reflectable.test.proxy_test
>>> test_reflectable.test.meta_reflector_test
>>> test_reflectable.test.mixin_test
>>> test_reflectable.test.libraries_test
>>> 
>>> test_reflectable.test.serialize_test
>>> test_reflectable.test.dynamic_reflected_type_test
>>> test_reflectable.test.metadata_test
>>> test_reflectable.test.reflect_test
>>> test_reflectable.test.library_declarations_test
>>> test_reflectable.test.polymer_basic_needs_test
...
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 

It actually turns out that build is invoked 210 times with an inputLibrary that prints as the empty string. Printing buildStep.inputId as well and grepping for an arbitrary test parameter_test we get this:

>>> test_reflectable.test.parameter_test, test_reflectable|test/parameter_test.dart
>>> , test_reflectable|test/parameter_test.dart.vm_test.dart
>>> , test_reflectable|test/parameter_test.dart.node_test.dart
>>> , test_reflectable|test/parameter_test.dart.browser_test.dart

So why is build invoked multiple times with different inputIds apparently corresponding to the same inputLibrary, but with an input library that prints as the empty string on every non-first invocation?

If this causes a changeFile invocation on the same library (perhaps parameter_test.reflectable.dart?) each time, then that might explain why we see these changeFile invocations out of nowhere during code generation (because each invocation of build on the same input library is an asynchronous function invocation, so the 4 instances of build of a given library could overlap).

[natebosch]

So why is build invoked multiple times with different inputIds apparently corresponding to the same inputLibrary, but with an input library that prints as the empty string on every non-first invocation?

These are not the same inputLibrary, they are unique. If you looked at the source code for each you'd see different content. I'm guessing that LibraryElement.toString() is printing the library directive from your test while the other 3 files don't have a library directive.

The .vm_test.dart, .node_test.dart and .browser_test.dart files are created by package:build_test and correspond to the files that package:test would generate internally when running tests - we output them so that they can be precompiled by the build system rather than letting the test runner handle them.

If this causes a changeFile invocation on the same library (perhaps parameter_test.reflectable.dart?) each time, then that might explain why we see these changeFile invocations out of nowhere during code generation

It shouldn't. We only should call changeFile once for each library. I think we did have a bug where it could be called more than once for the same library, but it should have been fixed in https://github.com/dart-lang/build/pull/2866

[eernstg]

Thanks for the information, it's quite helpful!

If you looked at the source code

Interesting! I can't immediately look at the source code: The generated libraries (e.g., new_instance_optional_arguments_test.dart.{vm,node,browser}_test.reflectable.dart) are stored on disk, but the corresponding input library is not (new_instance_optional_arguments_test.dart.{vm,node,browser}_test.dart).

The generated {vm,node,browser}_test files are identical to each other, and identical to the main *.reflectable.dart file:

> md5sum new_instance_optional_arguments_test.*reflectable*
2f773c3bbbcca7524823cdb09bd3f447  new_instance_optional_arguments_test.dart.browser_test.reflectable.dart
2f773c3bbbcca7524823cdb09bd3f447  new_instance_optional_arguments_test.dart.node_test.reflectable.dart
2f773c3bbbcca7524823cdb09bd3f447  new_instance_optional_arguments_test.dart.vm_test.reflectable.dart
2f773c3bbbcca7524823cdb09bd3f447  new_instance_optional_arguments_test.reflectable.dart

I added a check in ReflectableBuilder.build to return immediately whenever the inputId contains .vm_test., .node_test., or .browser_test.. This does not seem to create any problems (the build step succeeds and all tests subsequently run successfully), but it does reduce the code generation process from 27.3 sec to 14.1 sec.

Why wouldn't I just do that? ;-)

However, even in the case where all those *_test.*_test.reflectable.dart files are not generated, the InconsistentAnalysisException still occurs if the workaround is eliminated (it's even enough to remove the while-loop around the original workaround). So it doesn't eliminate the unexpected changeFile invocations.

[rrousselGit]

As a comeback to this:

So I managed to fix the exception. But now, users have reported that they have their build take more than 20 minutes to complete because of this workaround

It does complete, it's just _very_ slow because the generator keeps catching InconsistentAnalysisExceptions and retry after applying the workaround, one case at a time.

To put things into perspective, I have to apply the workaround on every parameter of every constructor of all the classes annotated by a specific marker

Note that this is slow even when applying the workaround only _after_ I caught an InconsistentAnalysisException. Which means if no exception happened, the workaround would never be executed.
But the exception happens just that many times

[jakemac53]

@rrousselGit another workaround you could try is using package:pool to only run a single instance of your code generator at a time (basically create a pool of size 1, and grab the resource for it in your build method).

Note that this should probably be an _instance_ field, not a static or top level field. We generally create a single instance of your builder per _target_ (which corresponds to a build phase), so this should avoid any deadlocks that could arise from weird ordering.