Saving pubspec.yaml does not run analysis server and unable to import new package.

[2shrestha22]

Describe the bug
After adding a package in pubspec.yaml and saving the file analysis server do not analyze changes and we can not import newly added package.

To Reproduce
Steps to reproduce the behavior:

1. Add new package in pubspec.yaml
2. Save the file with ctrl+s
3. It will download the library but does not load new files/packages so we need to manually restart analysis server or restart vs code.

Expected behavior
After saving and downloading package we should be able to import newly added package without needing to restart vs code or analysis server.

Screenshots
I will provide if needed.

Versions (please complete the following information):

• VS Code:

    Commit: 054a9295330880ed74ceaedda236253b4f39a335
    Date: 2021-06-18T02:30:22.835Z 
    Electron: 12.0.12
    Chrome: 89.0.4389.128
    Node.js: 14.16.0
    V8: 8.9.255.25-electron.0
    OS: Linux x64 5.12.13-arch1-2

• Flutter:

[✓] Flutter (Channel stable, 2.2.2, on Linux, locale en_US.UTF-8)
   • Flutter version 2.2.2 at /opt/flutter
   • Framework revision d79295af24 (3 weeks ago), 2021-06-11 08:56:01 -0700
   • Engine revision 91c9fc8fe0
   • Dart version 2.13.3

[✓] Android toolchain - develop for Android devices (Android SDK version 30.0.3)
   • Android SDK at /home/hatman/Android/Sdk
   • Platform android-30, build-tools 30.0.3
   • Java binary at: /opt/android-studio/jre/bin/java
   • Java version OpenJDK Runtime Environment (build 1.8.0_242-release-1644-b3-6222593)
   • All Android licenses accepted.

[✓] Chrome - develop for the web
   • CHROME_EXECUTABLE = /usr/bin/google-chrome-stable

[✓] Android Studio (version 4.1)
   • Android Studio at /opt/android-studio
   • Flutter plugin version 57.0.2
   • Dart plugin version 202.8531
   • Java version OpenJDK Runtime Environment (build 1.8.0_242-release-1644-b3-6222593)

[✓] Connected device (2 available)
   • POCO F1 (mobile) • c7ca2666 • android-arm64  • Android 11 (API 30)
   • Chrome (web)     • chrome   • web-javascript • Google Chrome 91.0.4472.114

• No issues found!

[DanTup]

Can you give a concrete example of how you're reproducing this? I've tried, but been unsuccessful. Here's what I did:

• Create a new console-simple project with Dart: New Project
• Uncomment the path dependency in pubspec.yaml and click Save
• Wait for package fetch to complete
• Try to import package:path into the Dart file

If you follow these same steps, do you see the same?

[2shrestha22]

@DanTup Sorry I missed the notification about this issue and today I did a look and found your reply.

I have attached a gif which explains my problem. It is not happening to me only but one of my friend is facing this problem too.

At last a step is skipped in the gif. What I did in the last step is: commented the package and saved, then again umcommented and saved. And finally I got it working.

[pranavo72bex]

This problem sucks

[DanTup]

Can you reproduce this? If so, could you try clicking View -> Output in VS Code and then selected flutter from the dropdown on the right of the output window to see if there are any errors shown when it wasn't working?

It might take a few moments for the analysis server to re-analyze after the packages are fetched. Usually you'd see "Analyzing..." in the status bar while this is happening, although I couldn't see that in your GIF, it might be collapsed due to the other items visible on the status bar.

[2shrestha22]

@DanTup Yes this happens every single time and it is just very very annoying. This is the output

[postaam] flutter pub get
Running "flutter pub get" in postaam...                            19.5s
exit code 0

Analyzer runs when flutter pub get runs but also stops before flutter pub get finishes. So after pub get is finished no "Analyzing.." is seen.
You can also see in the gif when I save for the first time, analyzer ran and stopped before completion of pub get. Then after it does not run and that is the problem.

May be it is due to long time it takes to fetch package? Mine took 19s while yours 915ms.

[DanTup]

It's possible, but the analyzer is triggered by the .dart_tool/package_config.json file being updated, so I would expect everything t be ready by the time the analyzer re-analyzes. I'm not sure why Pub appears to continue past that.

It would be useful to capture an instrumentation log:

https://dartcode.org/docs/logging/#analyzer-instrumentation

Note: This will will include parts of your source code, so it is best to reproduce this on a newly created project for this purpose. The log will get quite large over time (since it logs all communication with the analysis server) and you'll want to disable it once you're done testing.

[DanTup]

It's also worth running flutter pub get from a terminal and seeing whether it's similarly slow there, or if that's only in VS Code?

[2shrestha22]

I will give the log tomorrow maybe and will also see how much time flutter pub get takes. But I have tried flutter pub get from terminal also and it has same issue.

[2shrestha22]

@DanTup I have sent you email (logs@dartcode.org) with the instrumentation log file and link to this github issue.

[DanTup]

Thanks for the log - I can see the change to pubspec.yaml in there, but not a change to .dart_tool/package_config.json which I'd also expect to see. Could you try reproducing this again (and capturing logs), but then also run this command afterwards to get the modification timestamps of both files? (run it inside your project folder)

ls -l --time-style=full-iso pubspec.yaml; ls -l --time-style=full-iso .dart_tool/package_config.json

I'm wondering if this is related to #3438 (although that's flutter_gen, I wonder if the timing might also result here in the pusbpec.yaml rebuild is causing the original package_config.json modification to be missed 🤔).

Thanks!

[2shrestha22]

Hi @DanTup
Here is the time stamp:

-rw-r--r-- 1 hatman hatman 3057 2021-07-28 17:24:01.870950755 +0545 pubspec.yaml
-rw-r--r-- 1 hatman hatman 22431 2021-07-28 17:24:10.654421642 +0545 .dart_tool/package_config.json

also after flutter pub get

-rw-r--r-- 1 hatman hatman 3057 2021-07-28 17:24:01.870950755 +0545 pubspec.yaml
-rw-r--r-- 1 hatman hatman 22431 2021-07-28 17:26:34.806659544 +0545 .dart_tool/package_config.json

timestamps are different

[DanTup]

@2shrestha22 did you also grab the log when you captured those timestamps? I'd like to see exactly what the language server was doing around the time the package_config file is changing (after the pubspec was modified). Thanks!

[2shrestha22]

@DanTup I have sent you email with the log and this is the time stamp for that log.

-rw-r--r-- 1 hatman hatman 1044 2021-07-28 19:45:38.958518726 +0545 pubspec.yaml
-rw-r--r-- 1 hatman hatman 30795 2021-07-28 19:45:56.672149387 +0545 .dart_tool/package_config.json

[DanTup]

@2shrestha22 thanks! From the log you sent, I don't see any file watcher event for the modification of the .dart_tool/package_config.json file - which could be related.

In the log there is this at the same time the pubspec.yaml was modified:

# 1627480839 is 19:45:38.978
1627480838978:Watch:<unknown>:/home/hatman/flutter_projects/cloned/postaam/pubspec.yaml:modify

And then around the time of the timestamp of your .dart_tool/package_config.json, there's nothing in the logs (there should be a Watch event for that file), just a big gap between the server finishing previous analysis and then the editor sending a request:

# 1627480846057 is 19:45:46.057
1627480846057:Noti:{"event"::"server.status","params"::{"analysis"::{"isAnalyzing"::false}}}
# 1627480879589 is 19:46:19.589
1627480879589:Req:{"id"::"14","method"::"analysis.setSubscriptions","params"::{"subscriptions"::{"CLOSING_LABELS"::[

Can you reproduce this on a new project created with flutter create, or does it only occur for this one project?

If you modify the pubspec.yaml twice (eg. add the new dependency, then after the pub get completes, modify a comment or something else in the file and save again), does the new package then resolve correctly? (I would assume so, as the second modification to the pubspec.yaml would presumably trigger re-analyzing).

@bwilkerson @scheglov FYI - I'm not sure what's happening here, but it seems like the package_config.json modification might not be triggering watcher events. I have the full instrumentation log from before the pubspec.yaml timestamp going to way after the package_config.json timestamp above and there's only a single watch event (which is for the pubspec.yaml). The time difference between them is quite large (it's taking pub get a long time to run after the pubspec.yaml is modified) so I don't think it's related to the 200ms delay being discussed elsewhere (the analysis triggered by pubspec.yaml modification appears to complete 10 seconds before the package_config.json is then modified).

Do we know of any other reasons why watch events might be missed? I wondered if it could be related to the discussion in dart-lang/sdk#14373 (comment) about watcher events not being particularly reliable, but that says

the file system events daemon also coalesces multiple notifications on a given directory if they occur in a short period of time. You will always receive at least one notification after the last change is made.

But this doesn't match up - since we had no events after the pubspec.yaml was modified, and that suggests any dropped events would always be followed by some emitted event.

[DanTup]

@2shrestha22 can you also confirm your platform - is this Linux? The other issue I linked above was macOS, so this might be a different watcher implementation.

[2shrestha22]

@DanTup

If you modify the pubspec.yaml twice (eg. add the new dependency, then after the pub get completes, modify a comment or something else in the file and save again), does the new package then resolve correctly? (I would assume so, as the second modification to the pubspec.yaml would presumably trigger re-analyzing).

Yes if I comment the newly added package >> save >> uncomment again >> save then it appears.

@2shrestha22 can you also confirm your platform - is this Linux? The other issue I linked above was macOS, so this might be a different watcher implementation.

I am using Linux and @pranavo72bex is also using Linux.

[bwilkerson]

@devoncarew and @scheglov have more context than I do. Unfortunately @scheglov will be out for the next several days so he might not be able to reply to this question quickly.

But no, I'm not aware of any other reported issues with the watcher package.

... it seems like the package_config.json modification might not be triggering watcher events.

... the analysis triggered by pubspec.yaml modification appears to complete 10 seconds before the package_config.json is then modified ...

I'm not sure why we're re-analyzing after a change to the pubspec.yaml file (because we don't do analysis based on the content of that file), but it might have been an attempt to get around the lack of a watch event for the package_config.json file. Perhaps in some cases the package_config.json file has also been updated before the watch event for the pubspec.yaml file has been processed, but clearly not in all cases.

I wonder whether we're filtering out the watch events before logging them (based on something like the file being inside a dot directory).

[DanTup]

I'm not sure why we're re-analyzing after a change to the pubspec.yaml file

I was wondering the same. I haven't seen any watch events from package_config.json in my logs todaywhile testing this and #3438 which I'm confused by (I couldn't find any filtering).It's possible it's that timing issue (since it always happens in < 200ms after pubspec for me).

I have a possible fix for #3438 but it requires some refactoring, so maybe once that's done I can look at why (or whether we can remove) rebuilding from pubspec. It does seem silly if moments later .dart_tool/package_config.json will change and that's really what we care about.

[bwilkerson]

Konstantin will probably know why we're rebuilding after changes to the pubspec.yaml file.

[2shrestha22]

@DanTup It is only in Linux, I have tried in Windows today and I didn't encounter any problem.

[github-actions]

This issue has been marked stale because it is tagged awaiting-info for 20 days with no activity. Remove the stale label or comment to prevent the issue being closed in 10 days.

[2shrestha22]

This comment is for removing the stale label.

[2shrestha22]

Any update on this?

[DanTup]

Sorry for the delay. I'd been investigating a similar issue on macOS which I think has the same cause (a race condition if the package_config is modified while the analyzer is rebuilding because of another change), but my simple fix doesn't solve the whole problem so needs further work. It's still on my list and I hope to get back to it soon.

[JCKodel]

@DanTup Windows has issues as well. For me, import doesn't work at first (specially when using the Dart: Add Dependency). I have to open pubspec.yaml and hit Ctrl+S (even without changing anything). After this, it will show the Import library ... on the context menu.

Also, Dart: Add Dependency doesn't work very well if the pubspec.yaml isn't saved. It seems it changes directly in the disk and then when I try to save the unsaved file on VSCode, it conflicts (and then saves without the Dart: Add Dependency changes.

Those two problems can be related.

NOTE: Doesn't matter if using new LSP or not.

[DanTup]

@JCKodel please file a new issue about the unsaved-pubspec issue, as that's unrelated to whether pub get runs or the analysis server is picking up the new packages (I'm not sure we can do in that case, since it's pub add that's modifying the file, but at worst we can ask if you want to save the file before running it).

The first issue you describe does sound like the other race I mentioned. If pub add is modifying the pubspec.yaml file and then the .dart_tool/package_config.json very close together, the first one may trigger some work but it reads the old package_config, but does not get a file change event for package_config (because the file watcher initialization is asynchronous). I'm currently working on a fix for this one.

[DanTup]

I believe this issue is the same cause as #3438 which is that the server starts rebuilding contexts after the pubspec.yaml change and during the rebuild (which rebuilds file watchers) it misses the package_config.json change (having read the previous contents).

That issue is fixed by dart-lang/sdk@650b962 which is in the SDK so will show up in a future SDK release.

If you continue to see this after that change goes out and you've upgraded, please let me know!

[pranavo72bex]

I think this problem stay with us forever 😄

[DanTup]

@pranavo72bex this was recently fixed (see my comment above yours) but likely has not made a stable release yet. If you still see the issue after the next stable (non-hotfix) releases, please let me know.