DDEV integration entered unknown state by timeout

graham73may commented 2 years ago

Is there an existing issue for this?

[X] I have searched the existing issues

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

[X] 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

nico-loeber commented 2 years ago

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 commented 2 years ago

Also include the ddev version, ddev --version.

graham73may commented 2 years ago

@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 commented 2 years ago

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

rfay commented 2 years ago

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

nico-loeber commented 2 years ago

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 commented 2 years ago

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

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

graham73may commented 2 years ago

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

nico-loeber commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

@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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

@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 commented 2 years ago

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

rfay commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

graham73may commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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.

graham73may commented 2 years ago

It's not triggering all the time per project when I'm actively working on stuff. I work at an agency so it's not uncommon for me to have to open up a project after X weeks/months. Phpstorm seems to have a time limit on how long it trusts the index and it'll start to do a big reindex when I open a second instance (of a project I have previously opened).

Or a significant branch change will do the same. 🤷‍♂️

rfay commented 2 years ago

Definitely those things will cause an index build... but wow, do you have a slow disk or something? It should be a few seconds, not enough to affect your normal work. And it really shouldn't impact the extension's use of ddev, etc.

Remind me how much memory you have on your machine, and (you're using colima now right?) please tell me how much of that you have allocated to colima. And you're not low on disk space on the computer are you?

I think we should all band together and just get you a new computer.

graham73may commented 2 years ago

I am fine with your suggested fix Randy 😝.

It's a 2020 upgraded spec Macbook Pro! It shouldn't be slow!

Yes using Colima now, it's allocated 6GB memory. Machine has 32GB or memory. Hard drive is at about 50% full. (about 250GB free space)

It is so much more usable than when I was using Docker Desktop, as far as I'm concerned this issue is closed 😅 .

rfay commented 2 years ago

I encountered this in report 1c3d1ef3dcba40559612ee71c2fd1bde and it seems to be a result of slow internet detection.

I got this when doing ddev describe manually:

Internet connection not detected, DNS may not work, see https://ddev.readthedocs.io/en/stable/users/basics/faq/ for info. IsInternetActive DEBUG: err=lookup kvzhzvxmfu.ddev.site: no such host ctx.Err()=<nil> addrs=[] IsInternetactive==false, randomURL=kvzhzvxmfu.ddev.site internet_detection_timeout_ms=3000ms

I think perhaps the DDEV test is misguided and causes more trouble than it's worth. At the very least, DDEV doesn't need to check for every command. Maybe for ddev start only...

nico-loeber commented 2 years ago

Thanks for providing the report id @rfay!

How did you get this debug output? If I see this right there is a timeout of 3 seconds. Are you sure this can cause the 8 seconds timeout in the plugin to happen?

Update: Sadly I can not find any report for this ID. Probably the report wasn't submitted because of the internet connection error from the debug log? The report ID is generated on the client side and the data is submitted in the background, so the success message can be misleading.

rfay commented 2 years ago

Sure seemed like it was sent. But at least we have a potential culprit now. And DDEV can be improved to prevent this type of failure.

rfay commented 2 years ago

Note that I sent lots of reports @nico-loeber . Most were obvious reasons. If you didn't get any then something is probably wrong with the reporting system.

rfay commented 2 years ago

https://github.com/drud/ddev/pull/4134 went in, and may help with this. We can hope.

tklaas commented 1 year ago

I am getting this error, too, and can reproduce it really easy. It occurs every time when I send my MAC into hibernate (Ruhezustand). When coming back and having PHPStorm still open, I got this error. After waiting for a few seconds, DEVV state is set back to running.

I am using Docker Desktop

Error report ist submitted with id: 7060be40e0b941b0b7ceac513d7ac132

rfay commented 1 year ago

This is most likely because docker desktop doesn't recover immediately after you return from hibernation, so DDEV doesn't work immediately.

dahaupt commented 1 year ago

I also experience this issue often. Sometimes once or twice an hour, sometimes every couple minutes. I could reproduce the long execution time of the command ddev describe --json-output with a custom script, which executes the command every 3 seconds and outputs a result in case the execution took longer than 1 second.

Output:

Time for run 4: 31.70 seconds
Time for run 9: 155.58 seconds

So, I guess, there could be some kind of I/O or CPU blocking process. Unfortunately, I have no idea what could be the next step in analyzing.

nico-loeber commented 1 year ago

@dahaupt, thanks for that info! Could you please share your script with us so I can try if this is reproduceable on my device as well? This is more likely an issue with ddev than with the plugin so @rfay will be interested in this as well I guess.

dahaupt commented 1 year ago

Sure, here is a link to my script: https://gist.github.com/dahaupt/42a01df734347aca7b198c32005308a4

It is a rather simple bash script where you have to set the project name variable.

rfay commented 1 year ago

@dahaupt could you please add to your gist the output of ddev debug test so we'll know something about the environment you're running? You can add a second file there (or another gist is fine)

dahaupt commented 1 year ago

@rfay I have updated the gist with the output of the command.

rfay commented 1 year ago

Thanks, that helps a lot. When you have this problem, are there typically other projects running or just the one?

dahaupt commented 1 year ago

@rfay Actually just one project is running. I have the feeling that the problem does not occur when I "do nothing". The reproduction is really difficult.

rfay commented 1 year ago

I've been running the script for several minutes now on gitpod (Linux/amd64) without a hiccup.

When you're doing this are you often running other ddev commands at the same time as you're running the script?

Do you ever have trouble with network or internet connectivity? DDEV can try for 3 seconds (based on your settings) to determine whether the internet is available before offering to create an entry in /etc/hosts.

Could you try setting your internet_detection_timeout to something higher than the default, maybe 20000? ddev config global --internet-detection-timeout-ms=20000 and see if you get the problem?

alexbogias commented 1 year ago

@rfay Please raise timeout for the poor of us with the 10 year old pc's : :)

alexbogias commented 1 year ago

@rfay and update the command to your comment with "ddev config global --internet-detection-timeout-ms=20000"

rfay commented 1 year ago

@alexbogias I'm afraid it's not easy to design tools for people with current hardware and also 10-year-old hardware. And we'll always be more oriented toward the largest group. I see you've already discovered how to change the internet detection timeout. The current 3s is certainly good enough for most environments, but DDEV is also much more generous about this in current versions; it is just trying a DNS lookup, and it doesn't try a different one any more.

I'm not sure which timeout you're talking about in https://github.com/php-perfect/ddev-intellij-plugin/issues/83#issuecomment-1543657932

alexbogias commented 1 year ago

In your last comment, you missed the -ms at the end of the command

rfay commented 1 year ago

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

alexbogias commented 1 year ago

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 commented 1 year ago

kind reminder

nico-loeber commented 1 year ago

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 commented 1 year ago

OK I ll let you know when it come up again

php-perfect / ddev-intellij-plugin