CommandFailedException

[marcvangend]

Today, when starting PhpStorm, the IDE reported that this error occurred once:

de.php_perfect.intellij.ddev.cmd.CommandFailedException: Command returned non zero exit code ddev describe --json-output
	at de.php_perfect.intellij.ddev.cmd.DdevImpl.execute(DdevImpl.java:56)
	at de.php_perfect.intellij.ddev.cmd.DdevImpl.describe(DdevImpl.java:45)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.checkDescription(DdevStateManagerImpl.java:129)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.checkChanged(DdevStateManagerImpl.java:78)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.updateDescription(DdevStateManagerImpl.java:61)
	at de.php_perfect.intellij.ddev.state.StateWatcherImpl.lambda$startWatching$0(StateWatcherImpl.java:27)
	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)

This happened with a DDEV-enabled project, which had been opened with the DDEV-plugin before. At the moment I started PhpStorm, DDEV had already been started in a separate terminal.

I'm using the Alpha 2 release on PhpStorm build PS-221.5080.224 on MacOs.

[nico-loeber]

Thank you for reporting @marcvangend!
Can you reproduce this error, or does it occure randomly?

[marcvangend]

(Un)fortunately (depending how you look at it 😉) I was not able to reproduce the problem. Here's how I tried to reproduce it:

• Exit and start PhpStorm
• Exit PhpStorm, ddev restart, start PhpStorm
• Exit PhpStorm, ddev poweroff, ddev start, start PhpStorm

[nico-loeber]

Just had the same exception, just opening a non ddev project. This might be some type of race condition maybe... I will take a look at it. Thanks again for the infos!

[marcvangend]

I got the error again, this time not when starting PhpStorm, but when waking my laptop from sleep mode. Maybe that tells you something.

[nico-loeber]

Just as a note:

{"level":"fatal","msg":"\u001b[31mFailed to describe project(s): could not find a project in /home/nl/projects/****. Have you run 'ddev config'? Please specify a project name
or change directories: no .ddev/config.yaml file was found in this directory or any parent\u001b[0m","time":"2022-04-22T10:08:28+02:00"}

[nico-loeber]

@marcvangend, could you please tell me which default shell you are using?

I would guess its zsh with an enabled git plugin?

[marcvangend]

@nico-loeber pretty good guess! I use Fish with a git plugin.

[nico-loeber]

I was able to reproduce this issue. It's a timeout, since the ddev describe command took more than 5 seconds to load.

If you are using a shell with some plugin that does some haeavy work, like collecting git information this may affect performance of all executed commands.
The Problem is, that the common way to install DDEV is to use linuxbrew and to add the linux brew bin directory to your path by adding it to your .profile file.
The .profile file is only loaded for login shells, so the plugin has to execute its processes in a login shell, otherwise there would be a "ddev not found" error as it is not located in /usr/bin or /usr/local/bin.
For a login shell these plugins / extensions will be active.

We did some improvements to the error handling, so it is more obvious that a timeout is happening. We also increased the timeout from 5 to 8 seconds. Noramlly it should only take something around 100ms or less.

I'm afraid I can't really offer you a solution right now. I would suggest not using such shell plugins.

Could you maybe try to disable the git plugin, just to confirm this is causing the issue?

[nico-loeber]

As this issue is most probably caused by a 3rd party tool (shell with plugins) and we increased the timeout a bit, I will close this issue for now.
@marcvangend, please comment here if you have the same issue with a native bash or you have any idea on how to fix this issue better. Than I will reopen it.

[marcvangend]

Thanks for the debugging. Fish and its git prompt are essential for my day-to-day workflow, so I'm not going to disable either of them.

Disabling fish temporarily is possible of course, but that only makes sense if I know a sure-fire way to reproduce the error.

I don't know much about the internals of Fish and the git prompt, but I do know that the performance is pretty good. It never takes anything near 5 seconds to cd into a git repo. In fact, I just timed it a couple of times and its consistently in the range of 1-3 milliseconds. So it might just be my lack of knowledge, but I don't see how this could cause exceeding a 5s timeout.

So anyway, suppose I just keep using Fish and the git prompt, and I run into this error once in a while... Would that be a bad thing? Does anything not work after this error occurs? If so, is there something I can do manually to restore the ddev plugin to a working state?

[nico-loeber]

Sadly I can't explain why the shell takes 5 seconds in to execute in this context.
@juulliian was able to reproduce this timeout with zsh on mac, also I was able to reproduce it with a zsh shell in WSL.
@SpraxDev supported by testing on Linux.
We did some tests with a default shell (bash, and windows default) on different OS and were not able to reproduce any timeout then.
I can fully understand you, I am also a big fan of ZSH even the git plugin is just a nice to have for me.

The error shouldn't be that a big problem. The plugin will restore its state after the next ddev action (start / stop / restart) or after 10 seconds. So you might experience some delay before you can use some features.

We will keep an eye on this. I currently have no idea how to fix it and I don't see it critical for the 1.0 release, as this is "just" an issue with a 3rd party tool.
In case you have any new information about this issue, please keep me updated.

Just decided to keep it open, as it is an open issue...
First wanted to keep the issues section clean with only launch relevant issues. Sorry for any inconvenience.

[marcvangend]

Thank you, good to know that the plugin will restore itself to a working state.

And please, there is no need to apologize! Open issues will always exist. The decision to spend your time on it, or ignore it, is all yours. I am entitled to nothing and very grateful that you are sharing your plugin with us.

[nico-loeber]

@marcvangend did you try if the alpah3 release does help to mitigate your issue?

[marcvangend]

@nico-loeber I installed alpha-3 a couple of days ago. For what it's worth: I haven't seen the issue since. But then again, it didn't occur every day.

[marcvangend]

The problem still occurs. There seems to be a bit more debug info on the first line now:

de.php_perfect.intellij.ddev.cmd.CommandFailedException: Command 'ddev describe --json-output' returned non zero exit code {exitCode=1, timeout=false, cancelled=false, stdout=, stderr={"level":"fatal","msg":"\u001b[31mFailed to describe project(s): Get \"http://unix.sock/containers/json?all=1\u0026filters=%7B%22label%22%3A%5B%22com.ddev.site-name%3Drkdresearch%22%2C%22com.docker.compose.service%3Dweb%22%5D%7D\": dial unix /var/run/docker.sock: connect: no such file or directory\u001b[0m","time":"2022-05-16T08:56:15+02:00"}
}
	at de.php_perfect.intellij.ddev.cmd.DdevImpl.execute(DdevImpl.java:63)
	at de.php_perfect.intellij.ddev.cmd.DdevImpl.describe(DdevImpl.java:47)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.checkDescription(DdevStateManagerImpl.java:129)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.checkChanged(DdevStateManagerImpl.java:78)
	at de.php_perfect.intellij.ddev.state.DdevStateManagerImpl.updateDescription(DdevStateManagerImpl.java:61)
	at de.php_perfect.intellij.ddev.state.StateWatcherImpl.lambda$startWatching$0(StateWatcherImpl.java:27)
	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)

Also, I noticed there are two little arrows in the top left corner of the PhpStorm error dialog. I didn't notice those before, but it seems like this error has repeated more than 100 times since starting up this morning. After 100 errors, monitoring stopped.

[rfay]

The error in #23 (comment) looks like docker isn't running, or docker context is set wrong. Please use ddev manually in the shell to see if you can use it.

The output is absolutely not the same or even related to the previous problem:

de.php_perfect.intellij.ddev.cmd.CommandFailedException: Command 'ddev describe --json-output' returned non zero exit code {exitCode=1, timeout=false, cancelled=false, stdout=, stderr={"level":"fatal","msg":"\u001b[31mFailed to describe project(s): Get \"http://unix.sock/containers/json?all=1\u0026filters=%7B%22label%22%3A%5B%22com.ddev.site-name%3Drkdresearch%22%2C%22com.docker.compose.service%3Dweb%22%5D%7D\": dial unix /var/run/docker.sock: connect: no such file or directory\u001b[0m","time":"2022-05-16T08:56:15+02:00"

`

[marcvangend]

Hmm, yeah, maybe the explanation really is that simple. I should try it out tomorrow. (Now I'm wondering why that didn't occur to me before. :-D)

That said, it should be possible to run phpstorm without docker running, and not get any errors, right?

[nico-loeber]

it seems like this error has repeated more than 100 times since starting up this morning

ddev describe is triggert every 10 seconds to keep the plugin in sync if you run ddev stop manually on your command line.
I think that's why the error is logged that often.
This can be deactivated in the plugin settings in File | Settings | Tools | DDEV Integration.

That said, it should be possible to run phpstorm without docker running, and not get any errors, right?

Yes, we do already have an issue to avoid an exception when docker is not running:
#33

In case docker is not running at all the output of ddev describe seems to be
Failed to describe project(s): cannot connect to Docker endpoint
and not
Failed to describe project(s): Get "http://unix.sock/containers/json?all=1\u0026filters=%7B%22label%22%3A%5B%22com.ddev.site-name%3Drkdresearch%22%2C%22com.docker.compose.service%3Dweb%22%5D%7D": dial unix /var/run/docker.sock: connect: no such file or directory
like in this case...

I will try to reproduce this with the new information to implement a graceful handling of docker not running.

Thank you both for your input, @marcvangend and @rfay!

[nico-loeber]

Stopping Docker while ddev is running causes: Unable to get docker context: unable to run 'docker context inspect' - please make sure docker client is in path and up-to-date: exit status 1

Will be hard to handle this as the exit status of ddev is always 1 and the message can vary.

[nico-loeber]

@marcvangend, do you have any update on this?

[marcvangend]

Not really, I'm still getting the occasional error message. I do not always have time to dive in. Maybe it is worth mentioning that I do not auto-start Docker Desktop when I boot MacOS, so that might explain why I often have PhpStorm running before Docker and DDEV have started. But as a user of a plugin, I would expect the plugin to handle such a situation gracefully.

[nico-loeber]

Yes, this is an understandable request.

Thanks for your feedback!