DDEV integration entered unknown state by timeout #83

graham73may · 2022-07-04T17:58:17Z

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

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

Additional context

No response

The text was updated successfully, but these errors were encountered:

nico-loeber · 2022-07-04T19:12:41Z

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 · 2022-07-04T19:32:00Z

Also include the ddev version, ddev --version.

graham73may · 2022-07-04T21:24:09Z

@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 · 2022-07-04T22:18:22Z

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

rfay · 2022-07-04T22:19:58Z

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

nico-loeber · 2022-07-05T07:25:09Z

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 · 2022-07-05T08:49:20Z

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

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

graham73may · 2022-07-05T09:09:49Z

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

nico-loeber · 2022-07-05T09:26:03Z

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 · 2022-07-05T09:35:16Z

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 · 2022-07-06T17:53:48Z

@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 · 2022-07-06T18:05:13Z

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.

graham73may · 2022-07-07T13:11:46Z

Well ddev list took ages to execute.

ddev list 0.51s user 0.38s system 6% cpu 14.256 total

Can I send you a DM on discord with the output of that list? It contains a lot of client URLs as I'm sure you can imagine!

Trying ddev debug test... Wow didn't realise I'm nearly maxing out my docker's allowed storage.

Output below

➜  ~ ddev debug test
Running bash [-c /var/folders/j9/1kvm9h7s7sn5tlsjwfmnwvt80000gn/T/test_ddev.sh] 
OS Information: Darwin Grahams-MacBook-Pro.local 21.5.0 Darwin Kernel Version 21.5.0: Tue Apr 26 21:08:22 PDT 2022; root:xnu-8020.121.3~4/RELEASE_X86_64 x86_64
User information: uid=501(graham) gid=20(staff) groups=20(staff),12(everyone),61(localaccounts),79(_appserverusr),80(admin),81(_appserveradm),98(_lpadmin),701(com.apple.sharepoint.group.1),33(_appstore),100(_lpoperator),204(_developer),250(_analyticsusers),395(com.apple.access_ftp),398(com.apple.access_screensharing),399(com.apple.access_ssh),400(com.apple.access_remote_ae)
DDEV version:  ITEM             VALUE                                   
 DDEV version     v1.19.3                                 
 architecture     amd64                                   
 db               drud/ddev-dbserver-mariadb-10.3:v1.19.3 
 dba              phpmyadmin:5                            
 ddev-ssh-agent   drud/ddev-ssh-agent:v1.19.0             
 docker           20.10.16                                
 docker-compose   v2.5.1                                  
 docker-platform  docker-desktop                          
 mutagen          0.14.0                                  
 os               darwin                                  
 router           drud/ddev-router:v1.19.3                
 web              drud/ddev-webserver:v1.19.3-1           
======= DDEV global info =========
Global configuration:
instrumentation-opt-in=true
omit-containers=[]
mutagen-enabled=false
nfs-mount-enabled=false
router-bind-all-interfaces=false
internet-detection-timeout-ms=750
disable-http2=false
use-letsencrypt=false
letsencrypt-email=
table-style=default
simple-formatting=false
auto-restart-containers=false
use-hardened-images=false
fail-on-hook-fail=false
required-docker-compose-version=
use-docker-compose-from-path=false
no-bind-mounts=false

======= DOCKER info =========
docker location: lrwxr-xr-x  1 root  admin  54 10 Jul  2020 /usr/local/bin/docker -> /Applications/Docker.app/Contents/Resources/bin/docker
Docker Desktop Version: Docker Desktop for Mac 4.9.1 build 81317
docker version: 
Client:
 Cloud integration: v1.0.25
 Version:           20.10.16
 API version:       1.41
 Go version:        go1.17.10
 Git commit:        aa7e414
 Built:             Thu May 12 09:20:34 2022
 OS/Arch:           darwin/amd64
 Context:           default
 Experimental:      true

Server: Docker Desktop 4.9.1 (81317)
 Engine:
  Version:          20.10.16
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.17.10
  Git commit:       f756502
  Built:            Thu May 12 09:15:42 2022
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.4
  GitCommit:        212e8b6fa2f44b9c21b2798135fc6fb7c53efc16
 runc:
  Version:          1.1.1
  GitCommit:        v1.1.1-0-g52de29d
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0
======= Mutagen Info =========
Mutagen is installed in ddev, version=0.14.0
--------------------------------------------------------------------------------
Name: CLIENT-drupal
Identifier: sync_VKm0hbfP0NV91xpON6A3AufmRcpHMZu6tyiLPN6IU7j
Labels: None
Alpha:
        URL: /Users/graham/sites/theCLIENT.org-drupal
        Connection state: Connected
Beta:
        URL: docker://0921a69562182dc0f68db588599912a4470e1371493abdb0c076367fa08eed4d/var/www/html
                DOCKER_HOST=unix:///var/run/docker.sock
        Connection state: Connected
Status: Watching for changes
--------------------------------------------------------------------------------
Name: CLIENT
Identifier: sync_wzZsWGnXsP6GWExktWTUNNRQS9yZXI3DS6lvZj6E5Gb
Labels: None
Alpha:
        URL: /Users/graham/sites/CLIENT
        Connection state: Connected
Beta:
        URL: docker://9f00b5329020b24fb91e26997d9a91c9a1f96570de37b0379d1ea71544ffd820/var/www/html
                DOCKER_HOST=unix:///var/run/docker.sock
        Connection state: Connected
Status: Watching for changes
--------------------------------------------------------------------------------
mutagen is running on this system:
  501  3557     1   0 Mon07am ??        84:00.59 mutagen daemon run
  501 20758  3557   0 Wed08am ??         0:04.40 /usr/local/bin/docker exec --interactive --workdir /home/graham 9f00b5329020b24fb91e26997d9a91c9a1f96570de37b0379d1ea71544ffd820 .mutagen/agents/0.14.0/mutagen-agent synchronizer --log-level=info
  501 20759 20758   0 Wed08am ??         0:06.15 /usr/local/bin/com.docker.cli exec --interactive --workdir /home/graham 9f00b5329020b24fb91e26997d9a91c9a1f96570de37b0379d1ea71544ffd820 .mutagen/agents/0.14.0/mutagen-agent synchronizer --log-level=info
  501 60022  3557   0 Tue01pm ??         0:05.86 /usr/local/bin/docker exec --interactive --workdir /home/graham 0921a69562182dc0f68db588599912a4470e1371493abdb0c076367fa08eed4d .mutagen/agents/0.14.0/mutagen-agent synchronizer --log-level=info
  501 60023 60022   0 Tue01pm ??         0:07.76 /usr/local/bin/com.docker.cli exec --interactive --workdir /home/graham 0921a69562182dc0f68db588599912a4470e1371493abdb0c076367fa08eed4d .mutagen/agents/0.14.0/mutagen-agent synchronizer --log-level=info
  501 40631 40605   0  2:08pm ttys001    0:00.00 grep mutagen
======= Docker Info =========
Docker platform: docker-desktop 
Using docker context: default (unix:///var/run/docker.sock) 
docker-compose: v2.5.1 
Using DOCKER_HOST=unix:///var/run/docker.sock 
Docker version: 20.10.16 
Able to run simple container that mounts a volume. 
Able to use internet inside container. 
Docker disk space:
Filesystem                Size      Used Available Use% Mounted on
overlay                 102.1G     89.6G      7.3G  92% /

Container ddev-CLIENT-dba  Removed 
Container ddev-CLIENT-web  Removed 
Container ddev-CLIENT-db  Removed 
Network ddev-CLIENT_default  Removed 
Project CLIENT has been stopped. 
Container ddev-CLIENT-drupal-dba  Removed 
Container ddev-CLIENT-drupal-web  Removed 
Container ddev-CLIENT-drupal-db  Removed 
Network ddev-CLIENT-drupal_default  Removed 
Project CLIENT-drupal has been stopped. 
The ddev-ssh-agent container has been removed. When you start it again you will have to use 'ddev auth ssh' to provide key authentication again. 
Existing docker containers: 
CONTAINER ID   IMAGE                           COMMAND                  CREATED       STATUS                   PORTS     NAMES
4f0f9edb3584   busybox:stable                  "sh -c 'rm -f /mnt/d…"   2 weeks ago   Created                            busy_banach
5e598a1059d6   drud/ddev-webserver:v1.19.3-1   "sh -c 'df / | awk '…"   2 weeks ago   Exited (0) 2 weeks ago             intelligent_mahavira
c49b1aea23f0   a32c68b3f94b                    "/bin/sh"                2 weeks ago   Created                            phpstorm_helpers_PS-221.5787.33
Creating a new ddev project config in the current directory (/Users/graham/tmp/tryddevproject-1556) 
Once completed, your configuration will be written to /Users/graham/tmp/tryddevproject-1556/.ddev/config.yaml
 
Found a php codebase at /Users/graham/tmp/tryddevproject-1556 
Project type has no settings paths configured, so not creating settings file. 
Configuration complete. You may now run 'ddev start'. 
Network ddev_default created 
Starting tryddevproject-1556... 
Container ddev-ssh-agent  Started 
ssh-agent container is running: If you want to add authentication to the ssh-agent container, run 'ddev auth ssh' to enable your keys. 
Pushed mkcert rootca certs to ddev-global-cache/mkcert 
Network ddev-tryddevproject-1556_default  Created 
Container ddev-tryddevproject-1556-dba  Started 
Container ddev-tryddevproject-1556-db  Started 
Container ddev-tryddevproject-1556-db  Healthy 
Container ddev-tryddevproject-1556-web  Started 
Container ddev-router  Started 
Project type has no settings paths configured, so not creating settings file. 
Project type has no settings paths configured, so not creating settings file. 
Successfully started tryddevproject-1556 
Project can be reached at https://tryddevproject-1556.ddev.site https://127.0.0.1:63343 
+ curl --fail -I http://tryddevproject-1556.ddev.site
HTTP/1.1 200 OK
Server: nginx/1.20.1
Date: Thu, 07 Jul 2022 13:09:42 GMT
Content-Type: text/html; charset=UTF-8
Connection: keep-alive
Vary: Accept-Encoding

+ '[' 0 -ne 0 ']'
+ curl --fail http://tryddevproject-1556.ddev.site
Success accessing database... db via TCP/IP
ddev is working. You will want to delete this project with "ddev delete -Oy tryddevproject-1556"+ '[' 0 -ne 0 ']'
+ set +x
Thanks for running the diagnostic. It was successful.
Please provide the output of this script in a new gist at gist.github.com
Running ddev launch in 5 seconds

Please delete this project after debugging with 'ddev delete -Oy tryddevproject-1556'

graham73may · 2022-07-07T13:12:26Z

@rfay Sure thing, very happy to! Let me know if anything stands out in the debug info, if not I'll contact you on Discord :)

rfay · 2022-07-07T13:42:44Z

Discord is fine, a gist is the best place for large blocks of text, thanks.

rfay · 2022-07-07T13:46:17Z

You will want to increase the disk allocated in Docker Desktop and probably clean up also. ddev delete images, or probably just kill everything with docker rm -f $(docker ps -aq) && docker rmi -f $(docker images -q) (does no harm, just kills images). And... you don't have a bunch of projects running at the same time do you?

graham73may · 2022-07-07T14:28:25Z

Both commands executed! I've sent you a Discord with the output of ddev list.

RE number of projects running, no I only have 2 or 3 ddev sites running at once. I'll have a full project cull to bring the storage down and see how that goes!

graham73may · 2022-07-07T18:53:58Z

Thanks for the help debugging rfay! Some interesting results... swapped from Docker Desktop to Colima.

Colima responsiveness:

/usr/local/bin/ddev list  0.13s user 0.13s system 27% cpu 0.923 total
/usr/local/bin/ddev list  0.13s user 0.12s system 28% cpu 0.891 total
/usr/local/bin/ddev list  0.14s user 0.13s system 29% cpu 0.926 total
/usr/local/bin/ddev list  0.15s user 0.13s system 26% cpu 1.042 total
/usr/local/bin/ddev list  0.13s user 0.13s system 28% cpu 0.921 total

After that, I've factory reset docker desktop.

/usr/local/bin/ddev list  0.16s user 0.16s system 14% cpu 2.123 total
/usr/local/bin/ddev list  0.17s user 0.16s system 16% cpu 2.038 total
/usr/local/bin/ddev list  0.15s user 0.13s system 14% cpu 1.932 total
/usr/local/bin/ddev list  0.15s user 0.13s system 13% cpu 2.076 total
/usr/local/bin/ddev list  0.15s user 0.13s system 14% cpu 2.016 total

I'll be moving over to Colima now.... Which will probably resolve this issue!

nico-loeber · 2022-07-08T20:18:21Z

Great that you found a solution @graham73may. Thanks for your support @rfay!

graham73may · 2022-07-11T13:01:52Z

Even with Colima I'm still occasionally getting the error.

The cause seems to be PHPStorm indexing causing such a performance hit.

Is it possible to pause the sync if Indexing is running?

nico-loeber · 2022-07-11T16:46:25Z

Sad to hear...
The watch task runs in a seperate thread. It doesn't know if PHPStorm is indexing or not and I don't think pausing it will help much.
I can just offer to icrease the timeout slightly to 8 seconds in the next release.

I would still love to understand why the ddev command is that slow for you, @graham73may . Could you maybe give some information about your hardware, CPU, HDD/SSD, Memory?
I have only 6 projects in ddev list but ddev describe does never take longer than 1 second for me. Mostly about 200-300ms.

graham73may · 2022-07-11T17:53:17Z

System:

Hard drive:

time ddev list is taking around 0.9-1.0 seconds whenever I run it now, but if PHPStorm is doing a lenghty index then things seem slow down. After the swap to Colima everything's been reset so I only have 8 projects inside ddev list at the moment.

What is your PHPStorm heap size set to? (https://www.jetbrains.com/help/phpstorm/increasing-memory-heap.html) Mine's currently 2048.

Would really appreciate if you can change it to 8 seconds and see if that helps 😅 .

Thanks!

rfay · 2022-07-11T18:00:28Z

Normally PhpStorm doesn't have to index all the time. What's up with it doing that all the time @graham73may ? I normally only see a big index when I open a project for the first time.

rfay · 2023-05-11T15:06:58Z

Didn't understand you were asking for an edit to the comment. Edited.

alexbogias · 2023-05-16T09:22:30Z

I keep getting it again after raised timeout to 20000ms. de.php_perfect.intellij.ddev still timeouts after 8 seconds.

de.php_perfect.intellij.ddev.cmd.CommandFailedException: Command timed out after **8 seconds**: C:\WINDOWS\system32\wsl.exe --distribution Ubuntu --exec /bin/bash -c "export DDEV_NONINTERACTIVE=true && /usr/bin/ddev describe --json-output" in \\wsl$\Ubuntu\home\alex\Projects\xxxx.com 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.checkChanged(DdevStateManagerImpl.java:90) at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.updateDescription(DdevStateManagerImpl.java:74) at de.php_perfect.intellij.ddev.actions.SyncStateAction.lambda$actionPerformed$0(SyncStateAction.java:19) at com.intellij.openapi.application.impl.ApplicationImpl$1.run(ApplicationImpl.java:252) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:702) at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:699) at java.base/java.security.AccessController.doPrivileged(AccessController.java:399) at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(Executors.java:699) at java.base/java.lang.Thread.run(Thread.java:833)

alexbogias · 2023-06-16T08:41:14Z

kind reminder

nico-loeber · 2023-07-28T12:55:12Z

Hey @alexbogias, the timeout you encounter is the one set in the plugin for executing this command. You can not change it.
This timeout is set, as the plugin is polling the state of the container every 10 seconds. The ddev describe command is not expected to take longer than a second, but after 8 seconds it is aborted to not run it in parallel in background.

This bug is very hard to fix as I can no reproduce it.
If anyone who can reproduce this on their system, please let me know. I would be very interested in a shared screen session!

alexbogias · 2023-07-28T13:45:02Z

OK I ll let you know when it come up again

alexbogias · 2023-08-01T19:59:50Z

@nico-loeber Send you an email yesterday if you were available to work on it with a screen share. Maybe my mail is in you SPAM or something :(

nico-loeber · 2023-08-01T21:33:12Z

Thanks for your email @alexbogias and the information in it!
I got it yesterday and it was not in spam but sadly I didn't had any time for a screenshare.

It looks to me like this is a WSL issue in your case. I had this kind of error in the past as well, sometimes I tried to restart phpstorm and got different other errors as well, for example that my git version is out of date or even that there is no git installed.
This was caused by the git --version command that timed out / failed in the WSL.

You can try to restart WSL by running wsl --shutdown in a powershell. You might need to restart docker desktop, as it will get in trouble when its linux backend is gone. ;)

Please try this the next time and give feedback.

rositis · 2023-08-09T18:51:05Z

This error occurred with me this morning when waking my computer. It had been in sleep mode overnight, but the error did not trigger until many hours later, around 6:00am this morning.

Clicking on the 'Sync DDEV State' has no visual effect or recovery and the message remains.

rfay · 2023-08-09T18:59:39Z

I have found this as well. I can ignore the error, but it's not clear what happens when you "Sync DDEV state".

IMO this mostly happens when you open a DDEV project and DDEV is not running.

nico-loeber · 2023-08-14T09:14:05Z

I have found this as well. I can ignore the error, but it's not clear what happens when you "Sync DDEV state".

This message informs you, that ddev describe failed to execute for some reason. It should happen together with an error you can report, that gives you more detail why it failed.

If ddev describe fails, ddev features like the start / restart / poweroff buttons will be disabled, since the plugin does not know the current state of ddev. By clicking "Sync DDEV State" the state of the plugin gets reset and the ddev describe is executed again. If everything works fine the status, shown on the lower right corner, will switch from "Unkown" to "Running".

vpermits · 2023-09-02T14:25:45Z

Happens when I do a ddev snapshot restore. PHPStorm 2023.2

langlers · 2023-09-16T14:53:34Z

I just switched from laravel valet to ddev and am getting this error constantly. Running Colima with qemu on an M2 mac.

Is there a way to keep the ddev plugin enabled in phpstorm but stop the popup notifications when this happens? You can clearly tell when it occurs by the ddev status indicator.

nico-loeber · 2023-09-18T09:43:39Z

Is there a way to keep the ddev plugin enabled in phpstorm but stop the popup notifications when this happens? You can clearly tell when it occurs by the ddev status indicator.

This shouldn't happen at all, that's why I added the notification so I get feedback on this.
Sadly it seems quite inpredictable and hard to debug, at least on my hardware so this is an issue that exists for quite a long time, even there were alreadys some improvements on this.
I can maybe add something like an "Accept and Don't show again" option. What do you think about it @langlers?

nico-loeber · 2023-09-18T09:45:44Z

Happens when I do a ddev snapshot restore. PHPStorm 2023.2

@vpermits, thanks for your feedback! I will check if this is reproducible for me.

langlers · 2023-09-18T17:26:02Z

Is there a way to keep the ddev plugin enabled in phpstorm but stop the popup notifications when this happens?

I can maybe add something like an "Accept and Don't show again" option. What do you think about it @langlers?

@nico-loeber I think an option to stop the notifications would be useful for anyone who keeps getting the error.

Following up, I've stopped getting the errors on my M2. I'm not sure why, but here's everything that changed that could possibly be related to the issue:

it was a fresh MacOS install, and there were several background tasks running, file indexing, etc. They may have been slowing the system down enough to cause the ddev timeouts.
PhpStorm was also running a lot of background indexing tasks at first.
I increased the RAM allocation in Colima from 2GB to 6GB. I was only running a single ddev project, but 2GB might not have been enough.
I changed the DNS configuration in Colima to use 1.1.1.1 because a lot of DNS lookups were failing.

I hope that helps.

rfay · 2023-09-18T18:39:47Z

I'm pretty surprised you could ever have done 2GB with Colima... And DNS is consistently a problem with Colima.

@nico-loeber Orbstack is trending really strongly as an alternative to Colima. Not open-source, but really well maintained and super fast. You'll see it showing up in your world here.

langlers · 2023-09-18T20:44:55Z

@rfay Thanks for the suggestion! Switching to orbstack took less than 10 minutes, and ALL of the issues I was having while using colima are gone--including this one.

mandrasch · 2023-09-22T08:35:31Z

Seeing this too on frequently on

colima version 0.5.5
ddev version v1.22.1
PhpStorm 2023.2.1
OSX Ventura / Intel

Colima was installed with recommended settings from DDEV docs (colima start --cpu 4 --memory 6 --disk 100 --vm-type=qemu --mount-type=sshfs --dns=1.1.1.1, only switched network driver to slirp).

If I can assist in debugging this somehow, happy to provide logs, etc. :)

(I'll consider trying orbstack as well in future)

mandrasch · 2023-10-02T08:21:21Z

I also switched to orbstack via https://docs.orbstack.dev/install#colima, works so far. 👍

But PhpStorm is still looking for colima for eslint. Could not find the setting for this (yet) 🤔

rfay · 2023-10-02T09:39:57Z

You may want to open an issue with Jetbrains in their PhpStorm queue to ask for Orbstack, if it hasn't already been requested.

mandrasch · 2023-10-10T16:39:55Z

Good news: I asked the support, but it turned out I just needed to hit "reset" here

After resetting, eslint it worked fine. 🥳

alexbogias · 2023-11-19T18:22:32Z

This error still exists in latest wsl / ddev / phpstorm and ddev phpstorm plugin :(

richarddewit · 2024-02-08T12:14:58Z

The timeout of 8 seconds is too short IMO. When I run ddev --version it consistently runs for 15 seconds

rfay · 2024-02-08T14:24:39Z

@richarddewit I'd be very happy to take a look with you. ddev --version should never take 15 seconds. Could you please show the output of time ddev --version ? And also please do a ddev debug test and put the output in a gist on gist.github.com and give a link here? (a text file attached would be OK also).

Here's what I see, the first time did take a second, the second time 0.1 seconds.

$ time ddev --version
ddev version v1.22.6

real	0m1.331s
user	0m0.028s
sys	0m0.054s
rfay@rfay-tag1-m1:~/workspace/ddev$ time ddev --version
ddev version v1.22.6

real	0m0.122s
user	0m0.020s
sys	0m0.040s

richarddewit · 2024-02-08T14:40:11Z

@rfay - I'm on MacOS btw (M2 Pro, Sonoma 14.1.1 (23B81))

$ time ddev --version
ddev version v1.22.6
ddev --version  0.07s user 0.09s system 1% cpu 15.494 total

ddev-debug-test.txt

rfay · 2024-02-08T14:43:47Z

@richarddewit I have no idea how you can get that, but I imagine it's because you have that misconfigured Fritzbox router. Would you mind reconfiguring it so that *.ddev.site works and maybe that will be the issue? See https://ddev.readthedocs.io/en/latest/users/usage/troubleshooting/#dns-rebinding-prohibited-mostly-on-fritzbox-routers

richarddewit · 2024-02-08T15:48:28Z

@rfay - ok apparently it only takes this long if I haven't run ddev start yet. Afterwards it's nearly instant.

rfay · 2024-02-08T15:54:26Z

With internet disabled (should be similar to your router problem) and ddev poweroff I see

$ time ddev --version
ddev version v1.22.6

real	0m0.208s
user	0m0.035s
sys	0m0.076s

I do think you'd be much happier if you do the simple reconfiguration of your Fritzbox router so DDEV doesn't have to add entries to your /etc/hosts file all the time :)

svrhovac · 2024-06-28T09:45:41Z

Using versions:

DDev version v1.23.1
PhpStorm 2024.1.4.
However, this issue was happening with previous versions as well.

In the IDE there is popup info with the following text:

The DDEV Integration Plugin has lost track of the DDEV status. This most likely occurs together with another related error message. Please report this issue if it occurs repeatedly.

Info pannel reports this error:
java.lang.IllegalStateException: There is no ProgressIndicator or Job in this thread, the current job is not cancellable.
at com.intellij.openapi.progress.CoroutinesKt$runBlockingCancellable$1.invoke(coroutines.kt:128)
at com.intellij.openapi.progress.CoroutinesKt$runBlockingCancellable$1.invoke(coroutines.kt:126)
at com.intellij.openapi.progress.ContextKt.prepareThreadContext(context.kt:83)
at com.intellij.openapi.progress.CoroutinesKt.runBlockingCancellable(coroutines.kt:126)
at com.intellij.openapi.progress.CoroutinesKt.runBlockingCancellable(coroutines.kt:121)
at com.intellij.execution.wsl.WslIjentUtil.runProcessBlocking(WslIjentUtil.kt:63)
at com.intellij.execution.wsl.WSLDistribution.lambda$patchCommandLine$2(WSLDistribution.java:239)
at com.intellij.execution.configurations.GeneralCommandLine.createProcess(GeneralCommandLine.java:491)
at com.intellij.execution.configurations.GeneralCommandLine.startProcess(GeneralCommandLine.java:464)
at com.intellij.execution.configurations.GeneralCommandLine.createProcess(GeneralCommandLine.java:357)
at com.intellij.execution.process.OSProcessHandler.startProcess(OSProcessHandler.java:86)
at com.intellij.execution.process.OSProcessHandler.(OSProcessHandler.java:46)
at com.intellij.execution.process.CapturingProcessHandler.(CapturingProcessHandler.java:20)
at de.php_perfect.intellij.ddev.cmd.ProcessExecutorImpl.executeCommandLine(ProcessExecutorImpl.java:16)
at de.php_perfect.intellij.ddev.cmd.DockerImpl.isRunning(DockerImpl.java:11)
at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.initialize(DdevStateManagerImpl.java:42)
at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.initialize(DdevStateManagerImpl.java:33)
at de.php_perfect.intellij.ddev.InitPluginActivity.lambda$execute$0(InitPluginActivity.java:19)
at com.intellij.openapi.application.impl.RwLockHolder$executeOnPooledThread$1.run(RwLockHolder.kt:154)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:702)
at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:699)
at java.base/java.security.AccessController.doPrivileged(AccessController.java:399)
at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(Executors.java:699)
at java.base/java.lang.Thread.run(Thread.java:840)

graham73may added the bug Something isn't working label Jul 4, 2022

nico-loeber self-assigned this Jul 5, 2022

nico-loeber changed the title ~~DDEV integration entered unknown state~~ DDEV integration entered unknown state by timeout Jul 5, 2022

nico-loeber closed this as completed Jul 8, 2022

nico-loeber mentioned this issue Jul 26, 2023

DDEV intetration entered unkonwn state #209

Closed

2 tasks

DDEV integration entered unknown state by timeout #83

DDEV integration entered unknown state by timeout #83

Comments

graham73may commented Jul 4, 2022

Is there an existing issue for this?

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

Enter your error report ID (If available)

Describe the bug

Steps to reproduce

Additional context

nico-loeber commented Jul 4, 2022

rfay commented Jul 4, 2022

graham73may commented Jul 4, 2022 • edited Loading

rfay commented Jul 4, 2022

rfay commented Jul 4, 2022

nico-loeber commented Jul 5, 2022

graham73may commented Jul 5, 2022

graham73may commented Jul 5, 2022

nico-loeber commented Jul 5, 2022

graham73may commented Jul 5, 2022 • edited Loading

nico-loeber commented Jul 6, 2022 • edited Loading

rfay commented Jul 6, 2022

graham73may commented Jul 7, 2022

graham73may commented Jul 7, 2022

rfay commented Jul 7, 2022

rfay commented Jul 7, 2022

graham73may commented Jul 7, 2022

graham73may commented Jul 7, 2022

nico-loeber commented Jul 8, 2022

graham73may commented Jul 11, 2022

nico-loeber commented Jul 11, 2022 • edited Loading

graham73may commented Jul 11, 2022

rfay commented Jul 11, 2022

rfay commented May 11, 2023

alexbogias commented May 16, 2023

alexbogias commented Jun 16, 2023

nico-loeber commented Jul 28, 2023

alexbogias commented Jul 28, 2023

alexbogias commented Aug 1, 2023

nico-loeber commented Aug 1, 2023 • edited Loading

rositis commented Aug 9, 2023

rfay commented Aug 9, 2023

nico-loeber commented Aug 14, 2023

vpermits commented Sep 2, 2023

langlers commented Sep 16, 2023

nico-loeber commented Sep 18, 2023

nico-loeber commented Sep 18, 2023

langlers commented Sep 18, 2023

rfay commented Sep 18, 2023

langlers commented Sep 18, 2023

mandrasch commented Sep 22, 2023

mandrasch commented Oct 2, 2023 • edited Loading

rfay commented Oct 2, 2023

mandrasch commented Oct 10, 2023

alexbogias commented Nov 19, 2023

richarddewit commented Feb 8, 2024

rfay commented Feb 8, 2024

richarddewit commented Feb 8, 2024

rfay commented Feb 8, 2024

richarddewit commented Feb 8, 2024

rfay commented Feb 8, 2024

svrhovac commented Jun 28, 2024

graham73may commented Jul 4, 2022 •

edited

Loading

graham73may commented Jul 5, 2022 •

edited

Loading

nico-loeber commented Jul 6, 2022 •

edited

Loading

nico-loeber commented Jul 11, 2022 •

edited

Loading

nico-loeber commented Aug 1, 2023 •

edited

Loading

mandrasch commented Oct 2, 2023 •

edited

Loading