IssueTracker

Added screenshot showing multiple toolbars alongside 10+ concurrent Gradle tasks on IDE startup (Koala 2024.1.1 Canary 6).

From the logs, I see

2024-04-09 11:44:41,182 [  18522]   INFO - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Requesting Gradle sync (Not enough information to link all modules from: :<modulename1>).
2024-04-09 11:44:41,192 [  18532]   INFO - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Requesting Gradle sync (Not enough information to link all modules from: :<modulename2>).
2024-04-09 11:44:41,192 [  18532]   INFO - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Requesting Gradle sync (Not enough information to link all modules from: :<modulename3>).

once per module, followed finally by

2024-04-09 11:44:41,228 [  18568]   INFO - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Requesting Gradle sync DataNode<ProjectData> not found for /<path>/<to>/workspace.

So this explains the multiple background tasks: we should have stopped trying to link models as soon as we knew that we were going to fail, rather than requesting sync but then continuing on. I have a fix for this, hopefully available in Koala 1 Canary 7 (but not yet submitted, so dependent on reviews and infrastructure cooperating).

I hope that the multiple toolbars is a symptom caused by this fault. I can't immediately see a mechanism for it happening, but on the other hand if in your experience the multiple toolbars only happen when there are also multiple "Importing 'workspace' Gradle Project" tasks on startup... maybe that will go away once my change is submitted too.

Thank you for looking into it. I would not be surprised the multiple toolbar issue is linked to the multiple gradle sync issue. The number of multiple gradle tasks and toolbars is not identical: I've seen anything between 2-7 toolbars. The screenshot I posted is an extreme case. I will definitely check Canary 7 when it is out.

Also, the number of modules for which a "Requesting Gradle sync (Not enough information to link all modules from <module>" line is appearing in the log file seems a bit random. Here's the number of such lines for 4 successive cold starts and exit of AS, (letting AS finish the multiple gradle tasks before cleanly exiting, which can take up to 3 minutes):

start #1: 11 lines

start #2: 3 lines

start #3: 12 lines

start #4: 8 lines

The modules mentioned in these lines are also not always the same, although some of them are common.

I'm also wondering why AS is systematically triggering a gradle sync for these modules. Why on each startup it does not have "enough information to link all modules from <module>" for a few modules that makes up the app ?

I want also to mention that after the more or less long AS startup, AS is working properly.

I'm also wondering why AS is systematically triggering a gradle sync for these modules.

That is a very good question! My current working hypothesis is that there's an issue somewhere in the "Workspace Model", where something that should be concurrent-safe ends up not being so. The introduction of the failure mode that you're seeing was a response to an actual crash, where the process of importing the project in Android Studio appears to have the information it needs to import the modules, only to discover very late that that information is not consistent.

I think we've previously only been able to reproduce this when the JVM doesn't shut down cleanly, but it might be that other recent changes have made this more likely to happen in normal operation.

I've now submitted the fix, so it should be available in Canary 7. Please update here either way on whether that solves both issues... :-)

Hi,

I have tested Canary 7 and pleased to report that the multiple Gradle Sync task issue is fixed. However:

• the multiple toolbar issue is not fixed: AS starts with 1 toolbar immediately displayed and a few seconds later (around the time the 'Importing Gradle Project' task appear) the other toolbars are added
• every AS start systematically triggers a Gradle sync. With your explanation, I understand this is a separate issue

Since I can reproduce both these issues easily, if you need my help to understand/troubleshoot it (with test builds or more logging), let me know.

the multiple toolbar issue is not fixed

Well, that's slightly unexpected, but I guess not completely so. There might be some similar mechanism to the one that I fixed that is failing to stop after adding one toolbar -- getting part-way through and then failing? I will try to have a look at this, but I don't really have any bright ideas at the moment.

every AS start systematically triggers a Gradle sync. With your explanation, I understand this is a separate issue

Well, this seems to suggest that there is something corrupt about the state of your project, and this corruption does not go away after resyncing. At the moment I don't have any idea what that might be.

Could you take a log of the project startup and sync from Canary 7? I think that would be useful to have.

If this is getting in the way of you doing your work, a couple of things to try:

• you could try importing a fresh copy of the project, somewhere else on the filesystem -- just to rule out the possibility that it's the project itself that is in some way strange: for example, starting again from a clean version control checkout, hopefully without any project .idea directories?
• you could try invalidating the IDE's caches, using File→Invalidate Caches.... Of course if this works, this will likely mean that you won't be in a position to debug the problem any further, but that's a price you might be willing to pay :-)

Thanks for letting me know!

Invalidate caches did not fix the problem.

Importing a fresh copy of the project is not practical.

I attached a new log file. The relevant lines are:

2024-05-01 18:19:23,726 [  16675]   INFO - #c.i.w.i.i.j.s.JpsProjectModelSynchronizer - Attempt 1: Changes were successfully applied
2024-05-01 18:19:23,733 [  16682]   INFO - #c.i.o.p.MergingQueueGuiExecutor - Running task: (dumb mode task) com.android.tools.idea.res.RootsChangedDumbModeTask@2f056c16
2024-05-01 18:19:23,733 [  16682]   INFO - #c.i.w.i.i.j.s.DelayedProjectSynchronizer$Util - Workspace model loaded from cache. Syncing real project state into workspace model in 974 ms. Thread[DefaultDispatcher-worker-51,5,main]
2024-05-01 18:19:23,735 [  16684]   INFO - #c.i.o.p.MergingQueueGuiExecutor - Task finished: (dumb mode task) com.android.tools.idea.res.RootsChangedDumbModeTask@2f056c16
2024-05-01 18:19:23,837 [  16786]   INFO - #c.i.o.p.DumbServiceImpl - exit dumb mode [workspace]
2024-05-01 18:19:23,895 [  16844]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.LiveSdk' which is empty, not registered with the external system and '/home/bobbie/workspac
e/.idea/modules/LiveSdk/workspace.LiveSdk.iml' does not exist.
2024-05-01 18:19:23,901 [  16850]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.acra' which is empty, not registered with the external system and '/home/bobbie/workspace/.
idea/modules/acra/workspace.acra.iml' does not exist.
2024-05-01 18:19:23,902 [  16851]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.UniversalImageLoader' which is empty, not registered with the external system and '/home/bo
bbie/workspace/.idea/modules/UniversalImageLoader/workspace.UniversalImageLoader.iml' does not exist.
2024-05-01 18:19:23,902 [  16851]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.BubbleUPnPUnlocker' which is empty, not registered with the external system and '/home/bobb
ie/workspace/.idea/modules/BubbleUPnPUnlocker/workspace.BubbleUPnPUnlocker.iml' does not exist.
2024-05-01 18:19:23,902 [  16851]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.android-iconify' which is empty, not registered with the external system and '/home/bobbie/
workspace/.idea/modules/android-iconify/workspace.android-iconify.iml' does not exist.
2024-05-01 18:19:23,902 [  16851]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.AndroidResampler' which is empty, not registered with the external system and '/home/bobbie
/workspace/.idea/modules/AndroidResampler/workspace.AndroidResampler.iml' does not exist.
2024-05-01 18:19:23,902 [  16851]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.BubbleUPnP_LVL' which is empty, not registered with the external system and '/home/bobbie/w
orkspace/.idea/modules/BubbleUPnP_LVL/workspace.BubbleUPnP_LVL.iml' does not exist.
2024-05-01 18:19:23,934 [  16883]   INFO - #c.i.o.p.DumbServiceImpl - enter dumb mode [workspace]
2024-05-01 18:19:23,937 [  16886]   INFO - #c.i.w.i.i.EntitiesOrphanageImpl - Update orphanage. 0 modules added
2024-05-01 18:19:23,937 [  16886]   INFO - #c.i.w.i.i.WorkspaceModelImpl - Project model updated to version 124 in 34 ms: Module model commit
2024-05-01 18:19:23,944 [  16893]   INFO - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Requesting Gradle sync (Not enough information to link all modules from: :acra).

The issue seems to be triggered from these Disposing module 'workspace.project' which is empty... lines. Have no idea why it says the .iml files do not exist while they do exist. Then there's the last line Not enough information to link all modules from: <modulename>, where <modulename> is randomly one of the module mentioned in the Disposing module lines.

On different AS startups, the modules listed are different. For example on another run:

2024-05-01 17:06:47,961 [  17454]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.BubbleUPnPServer-Android' which is empty, not registered with the external system and '/hom
e/bobbie/workspace/.idea/modules/BubbleUPnPServer-Android/workspace.BubbleUPnPServer-Android.iml' does not exist.
2024-05-01 17:06:47,967 [  17460]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.AmbilWarna' which is empty, not registered with the external system and '/home/bobbie/works
pace/.idea/modules/AmbilWarna/workspace.AmbilWarna.iml' does not exist.
2024-05-01 17:06:47,967 [  17460]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.msa-auth-for-android' which is empty, not registered with the external system and '/home/bo
bbie/workspace/.idea/modules/msa-auth-for-android/workspace.msa-auth-for-android.iml' does not exist.
2024-05-01 17:06:47,967 [  17460]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.JazzyViewPager' which is empty, not registered with the external system and '/home/bobbie/w
orkspace/.idea/modules/JazzyViewPager/workspace.JazzyViewPager.iml' does not exist.
2024-05-01 17:06:47,968 [  17461]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.ImageViewTouch' which is empty, not registered with the external system and '/home/bobbie/w
orkspace/.idea/modules/ImageViewTouch/workspace.ImageViewTouch.iml' does not exist.
2024-05-01 17:06:47,968 [  17461]   WARN - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Disposing module 'workspace.utilsandroid' which is empty, not registered with the external system and '/home/bobbie/wor
kspace/.idea/modules/utilsandroid/workspace.utilsandroid.iml' does not exist.
2024-05-01 17:06:47,995 [  17488]   INFO - #c.i.o.p.DumbServiceImpl - enter dumb mode [workspace]
2024-05-01 17:06:47,998 [  17491]   INFO - #c.i.w.i.i.EntitiesOrphanageImpl - Update orphanage. 0 modules added
2024-05-01 17:06:47,999 [  17492]   INFO - #c.i.w.i.i.WorkspaceModelImpl - Project model updated to version 124 in 31 ms: Module model commit
2024-05-01 17:06:48,006 [  17499]   INFO - #com.android.tools.idea.gradle.project.AndroidGradleProjectStartupActivity - Requesting Gradle sync (Not enough information to link all modules from: :AmbilWarna).

Also of note, the problematic modules listed are all Android Java modules. This project also has many pure Java modules.

After digging a bit more, some .iml files are indeed missing between AS runs (the ones mentioned in the log file). When AS starts, the missing .iml files are generated, but also some existing .iml are also removed ! Hence on the next AS startup the problem triggers again due to the removed .iml files (it regenerates them but also delete some other iml files).

Here's a diff of the output of find /home/bobbie/workspace/.idea/modules/ -name '*.iml' taken before starting AS and when AS is running after it has fully initialized:

diff before_start_as.txt during_as_running.txt 
3a4
> /home/bobbie/workspace/.idea/modules/acra/workspace.acra.iml
23a25
> /home/bobbie/workspace/.idea/modules/AndroidNativeUtils/workspace.AndroidNativeUtils.iml
27a30
> /home/bobbie/workspace/.idea/modules/AndroidResampler/workspace.AndroidResampler.iml
30a34
> /home/bobbie/workspace/.idea/modules/BoxAndroidLibraryV2/workspace.BoxAndroidLibraryV2.iml
79a84
> /home/bobbie/workspace/.idea/modules/ImageViewTouch/workspace.ImageViewTouch.iml
102a108
> /home/bobbie/workspace/.idea/modules/msa-auth-for-android/workspace.msa-auth-for-android.iml
112d117
< /home/bobbie/workspace/.idea/modules/poppyview-library/workspace.poppyview-library.iml
139d143
< /home/bobbie/workspace/.idea/modules/UniversalImageLoader/workspace.UniversalImageLoader.iml

So on startup, AS generated the missing iml files denoted with a line starting with > (6 files), and removed iml files with a line starting with < (2 files).

So the $$$ question is why AS removes some iml files on startup.