Analysis driver returns cached results from a previous session after an exception occurs during analysis

[DanTup]

Given this file:

class Person2 {
  final int? age; // 1

  const Person2({this.age}); // 2
}

void f() {
  Person2(age: 1); // 3
  Person2(age: 1); // 4
}

If I invoke Go-to-Definition on Person2 at the end (4), it doesn't work:

However if I add var a = in front of the call, it then works,

If I then remove var a = again, the original reference works.

[DanTup]

Actually, it's unrelated to the assignment, it fails when the file is not modified (there's no overlay). If I update the code like:

f() {
  A();
}

class A {
  var a = A();
}

This still fails as long as the file is saved and has no overlay (note: in VS Code/LSP we no longer create overlays until their contents is different to what's on disk).

@scheglov I'm failing to reproduce this in a test (by creating a file with the contents above, then initializing the server, then testing Go-to-Definition). Any ideas what could be triggering it? (I wondered if there was some different between loading the cached data from disk versus when it's analyzed in memory but I feel like I'm doing the same thing in a test).

[scheglov]

Works for me, I can navigate from A() both inside f() and var a.
Also works on Person2.
In IntelliJ.

[bwilkerson]

It also works for me using VSCode with an SDK built yesterday.

[DanTup]

Ok, this is weird :-)

• I made a new project and pasted that code in - everything worked fine.
• I cloned my standard test project where I saw the issue originally - everything worked fine
• Assuming something in .dartServer must account for the difference, I deleted that folder
• My original test project still shows the issue
• My copy of the original test project now shows the issue
• My new project does not show the issue

So deleting everything in .dartServer seems to have caused it to start happening in one project but not another with the same code.

I'll do some more investigation.. there's definitely some bug here!

[DanTup]

Ok, I tracked this down. It seems to happen when I have another file in my project with the contents from another bug I had repro'd:

enum MyEnum {
  enumValue(["text"].map((x) => x));

  const MyEnum(this.strings);
  final Iterable<String> strings;
}

When I have that file, my instrumentation log has this error for that other file (#53793):

1698229933402:Ex:Analysis failed:: C::\Dev\Test Projects\dart_sample2\bin\dc4755.dart context:: exception_20231025_113213_402
type 'Null' is not a subtype of type 'InterfaceType' in type cast
#0      ConstantVerifier.visitListLiteral (package::analyzer/src/dart/constant/constant_verifier.dart::296::38)
#1      ListLiteralImpl.accept (package::analyzer/src/dart/ast/ast.dart::11403::50)

And when that occurs, it seems to prevent this Go-to-Definition from working (in the original file, not the one failing analysis). I don't know why it stops that from working but doesn't stop other things from working.

So my project contains the two files above looking like this, and both files are saved, and then I run Developer: Reload Window so that they have not been modified (and don't have overlays). Then Go-to-Definition on Person2 fails.

My theory is that when initial analysis fails for a file, maybe it's not fully analyzing the rest of the project. Modifying the file triggers new analysis of that file that fills in some missing data?

[bwilkerson]

Just to confirm, are you using a recent build?

@kallentu In case you have context.

[DanTup]

I can repro running from current source. I'm struggling to repro in a test, however I found some new information... it only happens if I already have the file open when I open the project (eg. VS Code restores the open file).

If I open the project with no open files, then open the file, it doesn't reproduce. If I run Developer: Reload Window it then repros. I feel like it should be easy to reproduce this at least in an integration test, I'll review the log and see if I'm missing something different in my test.

[DanTup]

I should have reviewed the log more closely earlier. The server isn't returning no definitions, it's returning an error:

1698249516556:Req:{"jsonrpc"::"2.0","id"::14,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dart_sample2/lib/main.dart"},"position"::{"line"::7,"character"::5}},"clientRequestTime"::1698249516554}
1698249516561:Res:{"id"::14,"jsonrpc"::"2.0","error"::{"code"::-32801,"message"::"Document was modified before operation completed"}}

This is not a timing issue, because I can wait 5 minutes and then try to invoke /definition again and it fails with the same error. I feel like something has gotten out of sync here (LSP-specific). I'll debug further, sorry for the noise 🙃

[DanTup]

I still haven't been able to trigger this in a test (I think it's quite timing dependent), but I did strip down the VS Code impl to a clearer log.. It happens because when we're getting definitions, we end up getting a resolved unit that has an older session than the one the driver has and then the consistency check fails.

Log here:

https://gist.githubusercontent.com/DanTup/40baa9e8e5b72cf2ec521a36ee75e51b/raw/6a847848b1b96e781e3369fdb1369e0de1eb92ec/log.txt

It seems that during the definition request we try to get a LineInfo but end up reading the file content and triggering a new session to be created (id: 4). Then in the consistency check, the session we had (id: 3) is stale so we throw.

I'll continue digging tomorrow. My feeling is that this only occurs when there is an analysis exception during initial analysis, but it seems to also rely on specific timing of when we open the file (at least, that's the only real difference between this and my integration test that I can see).

[DanTup]

I was able to get a repro for this in an integration test. It requires LocationLinks to be enabled which is why I was failing previously. I have not been able to reproduce it in an in-process test though which makes debugging more difficult.

The issue seems to be that (after there was an exception analyzing the other file during initialisation), when we need to get LineInfos (which we may if we need to produce LocationLinks), fetching the LineInfo creates a new analysis session. However when we later ask for a resolved unit, we get one pointing at the previous session:

// Client sends definition request
1698324106171:Req:{"id"::1,"jsonrpc"::"2.0","method"::"textDocument/definition","params"::{"position"::{"character"::6,"line"::7},"textDocument"::{"uri"::"file::///C::/Users/danny/AppData/Local/Temp/analysisServerf0231fec/lib/main.dart"}}}
1698324106171:Info:

// We fetch a LineInfo which triggers creation of a new session
Creating session with ID 4
#0      new AnalysisSessionImpl (package::analyzer/src/dart/analysis/session.dart::37::61)
#1      AnalysisDriver.libraryContext (package::analyzer/src/dart/analysis/driver.dart::353::24)
#2      AnalysisDriver.currentSession (package::analyzer/src/dart/analysis/driver.dart::325::12)
#3      AnalysisDriver.getFileSync (package::analyzer/src/dart/analysis/driver.dart::735::16)
#4      AnalysisServer.getLineInfo (package::analysis_server/src/analysis_server.dart::556::47)
#5      DefinitionHandler.handle.<anonymous closure> (package::analysis_server/src/lsp/handlers/handler_definition.dart::96::31)
#6      ErrorOr.mapResult (package::language_server_protocol/protocol_special.dart::247::12)
#7      DefinitionHandler.handle (package::analysis_server/src/lsp/handlers/handler_definition.dart::95::17)


// We then fetch the resolved unit but get the original session
1698324106171:Info:Getting resolved unit for C::\Users\danny\AppData\Local\Temp\analysisServerf0231fec\lib\main.dart
1698324106171:Info:Got result from session with ID  3

// This results in an InconsistentAnalysisException
1698324106171:Res:{"id"::1,"jsonrpc"::"2.0","error"::{"code"::-32801,"message"::"Document was modified before operation completed2:: InconsistentAnalysisException:: Requested result might be inconsistent with previously returned results:: sessions do not match:: 4 vs 3\n, #0      AnalysisSessionImpl.checkConsistency (package::analyzer/src/dart/analysis/session.dart::66::7)\n#1      AnalysisSessionImpl.getParsedLibrary (package::analyzer/src/dart/analysis/session.dart::100::5)\n#2      DefinitionHandler._parsedDeclaration (package::analysis_server/src/lsp/handlers/handler_definition.dart::273::33)"}}

A change that adds a failing test and some debugging info (note: it has hard-coded paths) is here:

branch: https://github.com/DanTup/sdk/tree/bad-definition-issue
commit: DanTup@3bd06b4

I'm not sure whether the bug here is a) creating a new session when fetching the LineInfo or b) later getting a resolved unit with an older session. My feeling is that it's the former, but I'm not certain. This might need some input from someone with a better understanding of this than I have.

[bwilkerson]

The intent is that we should create a new session whenever something has changed in a way that might make new results incompatible with old results. I'm not sure why getting an exception while attempting to analyze a file would cause us to create a new session, so (a) might be a bug. But once we've created a new session we ought to fail any attempt to use an older session. So if that's what's causing the exception in (b), then that's expected.

[DanTup]

I'm not sure why getting an exception while attempting to analyze a file would cause us to create a new session,

To clarify, we're not creating a new session when the exception occurs - the new session is created when we're trying to create the LineInfo (we call getFileSync() and that triggers a new session).

But once we've created a new session we ought to fail any attempt to use an older session. So if that's what's causing the exception in (b), then that's expected.

Yep, that makes sense. But it seems odd that we create a new session (ID 4 in my log above, triggered by getFileSync()), and then a subsequent call to getResolvedUnit receives a result with the already-expired session (ID 3 in my log above).

[bwilkerson]

That sounds like a bug. If the getResolvedUnit was sent to the expired session (3) then it should have thrown an exception, and if it was sent to the new session (4) then the result ought to have been associated with the new session.

The only hole I could think of is if we asked the old session (3) for a result before it was obsolete but didn't get a result back until after it was obsolete. I suspect we only check the state of the session on entry and not on exit from each method. But given the nature of async code I don't think that checking on exit would completely protect against such an event anyway.

[DanTup]

I feel like something is definitely wrong here then. I added this code into the definition handler:

{
  final log = AnalysisEngine.instance.instrumentationService.logInfo;
  log('##### START #####');

  var driver = server.getAnalysisDriver(path)!;
  log('Driver session ID is ${driver.currentSession.thisId}');

  final result = await driver.getResult(path) as ResolvedUnitResult;
  log('Result has session ID  ${(result.session as AnalysisSessionImpl).thisId}');

  log('##### END #####');
}

And this is what's in the log:

1698335057261:Info:##### START #####
1698335057261:Info:Driver session ID is 4
1698335057262:Info:Result has session ID  3
1698335057262:Info:##### END #####

As far as I can tell, no other code was running at the same time as this. The code to get a LineInfo (which created session 4) ran and completed before this code.

I'll try to debug more to understand what's going on. I thought it was worth posting my findings here in case it rang any bells for those more familiar with this code than I. Seems like this behaviour might be as surprising to you as me though :-)

[bwilkerson]

@scheglov In case you have ideas.

[DanTup]

Ok, I think I understand what's happening. Whenever there is an analysis exception, we call _clearLibraryContextAfterException. This clears the library context which results in a new session being created the next time somethings tries to access it:

# Exception occurs analyzing another file, which clears the library context
1698664054528:Info:clearing library context
1698664054530:Ex:Analysis failed:: C::\Users\danny\AppData\Local\Temp\analysisServer37dcf1cc\lib\broken.dart context:: exception_20231030_110734_526
type 'Null' is not a subtype of type 'InterfaceType' in type cast
#0      ConstantVerifier.visitListLiteral (package::analyzer/src/dart/constant/constant_verifier.dart::296::38)
# ...


# The next request accesses currentSession which triggers creation of a new session
Creating session with ID 4
#0      new AnalysisSessionImpl (package::analyzer/src/dart/analysis/session.dart::37::61)
#1      AnalysisDriver.libraryContext (package::analyzer/src/dart/analysis/driver.dart::353::24)
#2      AnalysisDriver.currentSession (package::analyzer/src/dart/analysis/driver.dart::325::12)
#3      AnalysisDriver.getFileSync (package::analyzer/src/dart/analysis/driver.dart::741::16)
#4      AnalysisServer.getLineInfo (package::analysis_server/src/analysis_server.dart::557::47)
#5      DefinitionHandler.handle.<anonymous closure> (package::analysis_server/src/lsp/handlers/handler_definition.dart::107::31)

However, there are cached (priority) results that are still hanging around referencing the previous session:

1698664054914:Info:Driver session ID is 4
1698664054914:Info:Using cached result
1698664054914:Info:Result has session ID  3

That means Driver with Session X can still serve up cached results with session X-1.

I'm not too familiar with this code so this is probably one for @scheglov, but I wonder if _clearLibraryContextAfterException should be clearing priority results too?

Note: Because #53793 is fixed, it'll be harder to repro this. I'm still using a branch that doesn't include that change:

https://github.com/DanTup/sdk/tree/bad-definition-issue
DanTup@fa8d013

[scheglov]

I think you are right, and we should clear everything, including cached resolved units, on exception.

[scheglov]

https://dart-review.googlesource.com/c/sdk/+/332747

[DanTup]

Thanks! :)