DDEV integration entered unknown state by timeout

[graham73may]

Is there an existing issue for this?

• I have searched the existing issues

Are you sure that this bug is related to this DDEV Integration Plugin?

• I am sure

Enter your error report ID (If available)

No response

Describe the bug

This notification triggers a lot.

Example from just doing general debug work on a project, loading a drupal site in the browser etc.

I can't work out what's causing it, I'm not interacting with any ddev commands or the plugin. My main suspicion was ddev xdebug on/off but I can run that pretty harmlessly.

Thought maybe Drupal was quite heavy... so tried a plain php mini site I have. Same behaviour:

Steps to reproduce

1. Enable the plugin
2. Use the website in the browser, the notification just passively goes off every so often.

Additional context

No response

[nico-loeber]

This notification appears if the ddev describe -j fails in any way - timeout, non zero exit code, invalid output.
Normally this happens together with an internal error. There should be a blinking red exclamation mark in the lower right corner.
Please submit the error report and provide the generated report id.
Otherwise please provide information about your OS and Setup, please also include the default shell.

[rfay]

Also include the ddev version, ddev --version.

[graham73may]

@nico-loeber

No little red exclamation mark since my message on Discord, but plenty of these unknown state notifications. Still haven't got the full error to send you the ID of, I have been pressing the report button so I'm not sure where those go? Is there any other way to track them down?

• Mac OS Monterey 12.4
• ddev version v1.19.3
• Docker desktop 4.9.1 (81317)
• default shell is ZSH, can use Terminal but my main daily app is Hyper

I found my idea.log file and managed to track this down

2022-06-17 10:43:14,102 [  70714]   INFO - #c.i.c.CloudConfigManager - === End.Update: [/Users/graham/Library/Application Support/JetBrains/PhpStorm2022.1/jba_config/installed_plugins.txt] ===
2022-06-17 10:43:14,729 [  71341]   INFO - #c.i.a.o.PathMacrosImpl - Saved path macros: {}
2022-06-17 10:43:15,048 [  71660]   INFO - #c.i.c.ComponentStoreImpl - Saving appActionsLocalSummary took 11 ms, EditorSettings took 34 ms, ExportableFileTemplateSettings took 59 ms, FileTypeManager took 26 ms, GeneralSettings took 64 ms, PluginAdvertiserExtensions took 11 ms, PluginFeatureCacheService took 23 ms, RemoteServers took 12 ms, ScratchFileService took 65 ms, TemplateSettings took 11 ms, editorConfigEncodings took 128 ms
2022-06-17 10:43:15,216 [  71828]   INFO - #c.i.u.i.UnindexedFilesUpdater - Scanning completed for website.url.com. Number of scanned files: 2401; Number of files for indexing: 0 took 1403ms; general responsiveness: ok; EDT responsiveness: 1/2 sluggish
2022-06-17 10:43:15,216 [  71828]   INFO - #c.i.u.i.UnindexedFilesUpdater - Finished for website.url.com. No files to index with loading content.
2022-06-17 10:43:17,414 [  74026]   INFO - STDOUT - []
2022-06-17 10:43:17,440 [  74052]   INFO - STDOUT - []
2022-06-17 10:43:17,461 [  74073]   INFO - STDOUT - []
2022-06-17 10:43:17,471 [  74083]   INFO - #c.i.o.c.i.s.StoreUtil - saveProjectsAndApp took 3171 ms
2022-06-17 10:43:17,525 [  74137]   INFO - STDOUT - []
2022-06-17 10:43:19,223 [  75835]   INFO - STDOUT - []
2022-06-17 10:43:19,236 [  75848]   INFO - STDOUT - []
2022-06-17 10:43:19,244 [  75856]   INFO - STDOUT - []
2022-06-17 10:43:19,247 [  75859]   INFO - STDOUT - []
2022-06-17 10:43:19,252 [  75864]   INFO - STDOUT - []
2022-06-17 10:43:19,255 [  75867]   INFO - STDOUT - []
2022-06-17 10:43:19,260 [  75872]   INFO - STDOUT - []
2022-06-17 10:43:21,503 [  78115]   INFO - #c.i.d.c.DockerComposeIntegrationService - Populate shared volume phpstorm_helpers_PS-221.5787.33
2022-06-17 10:43:21,901 [  78513]   WARN - #c.i.d.c.DockerComposeIntegrationService - Populating shared volume with using command /usr/local/bin/docker-compose -f /Users/graham/sites/website.url.com/.ddev/.ddev-docker-compose-full.yaml -f /Users/graham/Library/Caches/JetBrains/PhpStorm2022.1/tmp/docker-compose.override.yml run --rm phpstorm_helpers returned 1 exit code
2022-06-17 10:43:22,244 [  78856]   INFO - STDOUT - []
2022-06-17 10:43:22,251 [  78863]   INFO - STDOUT - []
2022-06-17 10:43:22,252 [  78864]   INFO - STDOUT - []
2022-06-17 10:43:22,290 [  78902]   INFO - STDERR - [Fatal Error] :-1:-1: Premature end of file.
2022-06-17 10:43:22,292 [  78904]   WARN - #c.j.p.c.p.PhpInfoUtil - Failed to parse validation output: 
2022-06-17 10:43:22,314 [  78926]   INFO - #d.p.i.d.s.StateWatcherImpl - DDEV state watcher stopped
2022-06-17 10:43:22,316 [  78928]   INFO - #d.p.i.d.s.StateWatcherImpl - DDEV state watcher started
2022-06-17 10:43:22,367 [  78979]   INFO - #d.p.i.d.v.GithubClient - Loading latest DDEV release meta data from GitHub
2022-06-17 10:43:26,610 [  83222]   INFO - STDOUT - []
2022-06-17 10:43:27,869 [  84481]   INFO - STDOUT - []
2022-06-17 10:43:27,910 [  84522]   INFO - #c.i.u.i.FileBasedIndexProjectHandler - Reindexing refreshed files of website.url.com : 46 to update, calculated in 4ms
2022-06-17 10:43:27,911 [  84523]   INFO - #c.i.u.i.FileBasedIndexProjectHandler - Using 4 threads for indexing
2022-06-17 10:43:28,168 [  84780]   INFO - #c.i.d.PerformanceWatcherImpl - Reindexing refreshed files of website.url.com took 258ms; general responsiveness: ok; EDT responsiveness: ok
2022-06-17 10:43:32,838 [  89450]   INFO - STDOUT - []
2022-06-17 10:43:33,335 [  89947]   INFO - #c.j.r.f.FollowMeManager - Unregister user 0:'graham' with ClientId=ClientId(value=Host)
2022-06-17 10:43:33,375 [  89987]   INFO - #d.p.i.d.s.StateWatcherImpl - DDEV state watcher stopped
2022-06-17 10:43:33,465 [  90077] SEVERE - #d.p.i.d.s.DdevStateManagerImpl - Command timed out after 5 seconds: /usr/local/bin/ddev describe --json-output
de.php_perfect.intellij.ddev.cmd.CommandFailedException: Command timed out after 5 seconds: /usr/local/bin/ddev describe --json-output
	at de.php_perfect.intellij.ddev.cmd.DdevImpl.execute(DdevImpl.java:33)
	at de.php_perfect.intellij.ddev.cmd.DdevImpl.describe(DdevImpl.java:22)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.checkDescription(DdevStateManagerImpl.java:155)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.lambda$updateConfiguration$1(DdevStateManagerImpl.java:67)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.checkChanged(DdevStateManagerImpl.java:90)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.updateConfiguration(DdevStateManagerImpl.java:65)
	at de.php_perfect.intellij.ddev.state.StateWatcherImpl.lambda$startWatching$0(StateWatcherImpl.java:30)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at com.intellij.util.concurrency.SchedulingWrapper$MyScheduledFutureTask.run(SchedulingWrapper.java:226)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:668)
	at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:665)
	at java.base/java.security.AccessController.doPrivileged(Native Method)
	at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(Executors.java:665)
	at java.base/java.lang.Thread.run(Thread.java:829)
2022-06-17 10:43:33,468 [  90080] SEVERE - #d.p.i.d.s.DdevStateManagerImpl - PhpStorm 2022.1.2  Build #PS-221.5787.33
2022-06-17 10:43:33,468 [  90080] SEVERE - #d.p.i.d.s.DdevStateManagerImpl - JDK: 11.0.15; VM: OpenJDK 64-Bit Server VM; Vendor: JetBrains s.r.o.
2022-06-17 10:43:33,468 [  90080] SEVERE - #d.p.i.d.s.DdevStateManagerImpl - OS: Mac OS X
2022-06-17 10:43:33,469 [  90081] SEVERE - #d.p.i.d.s.DdevStateManagerImpl - Plugin to blame: DDEV Integration version: 1.0.0-beta1

Some things I'm taking from this

• EDT responsiveness: 1/2 sluggish

• Command timed out after 5 seconds: /usr/local/bin/ddev describe --json-output

• Plugin to blame: DDEV Integration version: 1.0.0-beta1

Edit: Adding more logging from earlier in the file.

[rfay]

Have you restarted docker? What docker provider are you using?

[rfay]

Sorry, I see it's docker desktop. do try restarting it.

[nico-loeber]

Hey @graham73may,

Thanks for adding these information!

2022-06-17 10:43:33,469 [ 90081] SEVERE - #d.p.i.d.s.DdevStateManagerImpl - Plugin to blame: DDEV Integration version: 1.0.0-beta1

Please install the stable 1.0.0 release of the plugin.

2022-06-17 10:43:33,465 [ 90077] SEVERE - #d.p.i.d.s.DdevStateManagerImpl - Command timed out after 5 seconds: /usr/local/bin/ddev describe --json-output
de.php_perfect.intellij.ddev.cmd.CommandFailedException: Command timed out after 5 seconds: /usr/local/bin/ddev describe --json-output

Executing ddev describe takes more than 5 seconds, this causes the error for you.
Could you please try to switch to bash as default shell just to check if the issue is still reproducable?
We already had problems with ZSH Plugins that increased the startup time of the shell alot and reduced performance.

[graham73may]

Looking in PHPStorm - plugin looks like it's updated since yesterday.

Disabled ZSH, will see how the plugin behaves today and report back.

[graham73may]

Still occurring with ZSH disabled. Shell is showing as /bin/bash.

[nico-loeber]

Does this error occur right from the start? Does it allways timeout, or only sometimes? You can easily check by clicking "Sync DDEV State". This will retrigger the ddev describe --json-output command and you should see the error again after 5 seconds, or if it did work nothing.
Please also try to execute time ddev describe --json-output multiple times in your project root and provide an average of the execution time and any peaks.

Thanks!

[graham73may]

It's not just at project start, it's going off constantly.

I never really need to click the Sync DDEV State button as it eventually does connect, this is what my notifications look like in the project:

Timings:

 0.13s user 0.11s system 11% cpu 1.978 total
 0.12s user 0.11s system 7% cpu 3.031 total
 0.15s user 0.12s system 8% cpu 3.213 total
 0.12s user 0.11s system 11% cpu 1.914 total
 0.15s user 0.12s system 7% cpu 3.756 total
 0.12s user 0.12s system 12% cpu 1.855 total

EDIT:

I saw the notification triggering again so I ran some more timings

 0.13s user 0.12s system 8% cpu 2.943 total
 0.15s user 0.12s system 4% cpu 5.638 total
 0.14s user 0.12s system 10% cpu 2.575 total

EDIT 2:
Using the terminal in PHPStorm, it's still showing as ZSH. (I fully quit PHPStorm after making the chsh change...),

> echo $SHELL
/bin/zsh

Anyway I'm at a point where I quite like having ZSH enabled so I'm going to turn off the status polling for now.

[nico-loeber]

@graham73may, thanks for your feedback!

I am using ZSH too and like it quite much. ;)

0.15s user 0.12s system 4% cpu 5.638 total

As you can see the command takes longer than 5 seconds this is causing the timeout. So this is not a problem with the plugin but with a generally slow execution of the ddev describe -j command.
The plugin should bypass your shell and should directly execute the ddev binary. But I am not 100% aware how this behaved on Mac. I would love to understand why you got such a bad performance.

@rfay just told me that the output of ddev list and ddev debug test could help us to find out what is happening here.

[rfay]

I'll be happy to hop on a call with you ask well @graham73may - It would be interesting to see what ddev describe shows you at times when this is happening.