View Issue Details

IDProjectCategoryView StatusLast Update
0001920XdebugStep Debuggingpublic2021-03-17 08:31
Reportertomjn Assigned Toderick  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionwon't fix 
Product Version3.0.1 
Summary0001920: When discover_client_host is active, failure to discover shows in the main PHP error log, even when a log is specified
Description

When discover_client_host is set to true, but fails to connect, it falls back to the client_host value we have specified as expected. However it is also printed in the main PHP error log, causing lots of noise.

Steps To Reproduce
  1. Set discover_client_host to true and restart PHP FPM
  2. Open a PHP page with XDebug in debug mode
  3. Ensure your IDE cannot be connected to via the HTTP header discovery
  4. Observe unexpected output in the PHP error log

Output is expected in the file specified in xdebug.log, but not in the PHP error log

Additional Information

We're using the Ubuntu 18 Ondrej PPA with the php-xdebug package in PHP 7.2 in a vagrant environment

PHP 7.3.24-3+ubuntu18.04.1+deb.sury.org+1 (cli) (built: Oct 31 2020 16:59:59) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.3.24, Copyright (c) 1998-2018 Zend Technologies
with Zend OPcache v7.3.24-3+ubuntu18.04.1+deb.sury.org+1, Copyright (c) 1999-2018, by Zend Technologies
with Xdebug v3.0.1, Copyright (c) 2002-2020, by Derick Rethans

PHP version: 7.3.24-3+ubuntu18.04.1+deb.sury.org+1

Our xdebug.ini:

zend_extension=xdebug.so

[XDebug]

xdebug.mode=debug
xdebug.start_with_request=yes
xdebug.client_host=_gateway
xdebug.discover_client_host=0
xdebug.var_display_max_depth=10
xdebug.var_display_max_children=256
xdebug.var_display_max_data=1024
xdebug.output_dir="/tmp"
xdebug.log="/var/log/php/xdebug-remote.log"
xdebug.profiler_output_name=cachegrind.out.%t.%p
xdebug.collect_return = 0
xdebug.dump.COOKIE = ""
xdebug.dump.FILES = ""
xdebug.dump.GET = ""
xdebug.dump.POST = ""
xdebug.dump.REQUEST = ""
xdebug.dump.SERVER = ""
xdebug.dump.SESSION = ""
xdebug.dump_globals = 1
xdebug.dump_once = 1
xdebug.dump_undefined = 0
xdebug.file_link_format = ""
xdebug.idekey = "VVVDEBUG"
xdebug.max_nesting_level = 100
xdebug.profiler_append = 0
xdebug.profiler_output_name = "cachegrind.out.%t-%s"
xdebug.show_exception_trace = 0
xdebug.show_local_vars = 0
xdebug.trace_format = 0
xdebug.trace_options = 0
xdebug.trace_output_name = "trace.%c"
xdebug.var_display_max_children = -1
xdebug.var_display_max_data = -1
xdebug.var_display_max_depth = -1

TagsNo tags attached.
Operating SystemUbuntu 18.04.3 LTS
PHP Version7.3.20-7.3.29

Relationships

duplicate of 0001948 closedderick Do not redirect warning and error messages to PHP's error log if an Xdebug log is active 

Activities

tomjn

2020-12-18 18:47

reporter   ~0005603

Apologies, xdebug.discover_client_host=0 in the above xdebug.ini was set to xdebug.discover_client_host=1 during testing

tomjn

2020-12-18 18:50

reporter   ~0005604

Likewise, with discovery turned off, if I load a page with XDebug active, but VSCode debugging stopped, it prints to the main php7.3_errors.log file:

[18-Dec-2020 18:49:05 UTC] Xdebug: [Step Debug] Could not connect to debugging client. Tried: _gateway:9003 (through xdebug.client_host/xdebug.client_port) :-(

derick

2020-12-21 13:29

administrator   ~0005605

Last edited: 2020-12-23 12:13

Hi,

I don't understand what you are trying to say. Where I stand, it works correctly.

On the command line without a client without a client running:
<pre>
$ REMOTE_ADDR=elephpant php -dxdebug.log=/tmp/xdebug.log -derror_log=/tmp/php-errors.log -dxdebug.mode=debug -dxdebug.discover_client_host=1 -dxdebug.start_with_request=yes /tmp/foo.php
</pre>

<pre>
$ cat /tmp/xdebug.log
[2425735] Log opened at 2020-12-21 13:27:20.322138
[2425735] [Step Debug] INFO: Checking remote connect back address.
[2425735] [Step Debug] INFO: Checking header 'HTTP_X_FORWARDED_FOR'.
[2425735] [Step Debug] INFO: Checking header 'REMOTE_ADDR'.
[2425735] [Step Debug] INFO: Client host discovered through HTTP header, connecting to elephpant:9003.
[2425735] [Step Debug] WARN: Creating socket for 'elephpant:9003', getaddrinfo: Invalid argument.
[2425735] [Step Debug] WARN: Could not connect to client host discovered through HTTP headers, connecting to configured address/port: localhost:9003. :-|
[2425735] [Step Debug] WARN: Creating socket for 'localhost:9003', poll success, but error: Operation now in progress (29).
[2425735] [Step Debug] WARN: Creating socket for 'localhost:9003', poll success, but error: Operation now in progress (29).
[2425735] [Step Debug] ERR: Could not connect to debugging client. Tried: elephpant:9003 (from REMOTE_ADDR HTTP header), localhost:9003 (fallback through xdebug.client_host/xdebug.client_port) :-(
[2425735] Log closed at 2020-12-21 13:27:20.338957
</pre>

<pre>
$ cat /tmp/php-errors.log
[21-Dec-2020 13:23:06 UTC] Xdebug: [Step Debug] Could not connect to debugging client. Tried: elephpant:9003 (from REMOTE_ADDR HTTP header), localhost:9003 (fallback through xdebug.client_host/xdebug.client_port) :-(
</pre>

As expected, the "ERR" from the xdebug.log shows up in the PHP error log.

With a client running:

<pre>
$ REMOTE_ADDR=elephpant php -dxdebug.log=/tmp/xdebug.log -derror_log=/tmp/php-errors.log -dxdebug.mode=debug -dxdebug.discover_client_host=1 -dxdebug.start_with_request=yes /tmp/foo.php
</pre>

<pre>
$ cat /tmp/xdebug.log
[2425570] Log opened at 2020-12-21 13:26:01.715806
[2425570] [Step Debug] INFO: Checking remote connect back address.
[2425570] [Step Debug] INFO: Checking header 'HTTP_X_FORWARDED_FOR'.
[2425570] [Step Debug] INFO: Checking header 'REMOTE_ADDR'.
[2425570] [Step Debug] INFO: Client host discovered through HTTP header, connecting to elephpant:9003.
[2425570] [Step Debug] WARN: Creating socket for 'elephpant:9003', getaddrinfo: Invalid argument.
[2425570] [Step Debug] WARN: Could not connect to client host discovered through HTTP headers, connecting to configured address/port: localhost:9003. :-|
[2425570] [Step Debug] INFO: Connected to debugging client: elephpant:9003 (from REMOTE_ADDR HTTP header), localhost:9003 (fallback through xdebug.client_host/xdebug.client_port). :-)
[2425570] [Step Debug] -> <init xmlns=" ... k Rethans]]></copyright></init>

[2425570] Log closed at 2020-12-21 13:26:03.629647
</pre>

<pre>
$ cat /tmp/php-errors.log
cat: /tmp/php-errors.log: No such file or directory
</pre>

This is exactly how I expected it to work. If it can't connect, it shows an error in the log. What did you expect to see differently?

cheers,
Derick

tomjn

2020-12-21 14:31

reporter   ~0005606

hmmm if that's intentional behaviour, how do I turn it off? I'm getting reports from users that their PHP error logs are filled with Xdebug messages about using client_host fallbacks.

My expectation is that if Xdebug tries to auto-discover/connect and can't, then falls back to the client_host, that it says so in the Xdebug log as configured. Instead I'm seeing it in both the Xdebug log and the PHP error log. The PHP error log is unexpected and undesired, especially since this is not an error, at best this particular scenario is a warning since Xdebug successfully connected via the client_host parameter

On top of that, Xdebug does indeed connect, falling back to the client_host defined parameter, and working fine for them with VSCode, so the message has no practical use other than to make PHP error logs completely useless.

The desired behaviour is that Xdebug logging goes in the Xdebug log when an Xdebug log is specified via PHP ini.

derick

2020-12-23 12:17

administrator   ~0005607

My expectation is that if Xdebug tries to auto-discover/connect and can't, then falls back to the client_host, that it says so in the Xdebug log as configured. Instead I'm seeing it in both the Xdebug log and the PHP error log.

It should only show up in PHP's error log if a connection can't be made at all, which is what my outputs show. In that case it will mention that it tried both the REMOTE_ADDR host and the fallback.

There should be no error in the PHP error log if there is just a warning (for xdebug's log): https://github.com/xdebug/xdebug/blob/master/src/lib/log.c#L121-L127

tomjn

2020-12-23 12:32

reporter   ~0005608

hmmm, then that might be a bug, but I'd still like the option for it to all go in the Xdebug log and only the Xdebug log, I've had multiple people poke me that their PHP error logs are being filibustered by these messages that are of no use to them.

The way we have Xdebug configured is that when it's turned on all requests are in debug mode. As a result unless you have VSCode listening before the environment is available, and keep it running without fail until the environment is shutdown ( possibly weeks later ), you'll get messages in your error log, lots of them. Restarting VSCode for an update and forgetting to begin the debugging session while a post editor in a forgotten tab sends heartbeat pings means your error log is spammed with these messages.

Instead, I'd like to tell people to look at the configured Xdebug log for Xdebug issues. I don't mind if i have to add an extra parameter for this. Would this be possible by adjusting the log level? If so the documentation isn't clear on that, my assumption is that it worked like the PHP error log level but for the Xdebug remote log, e.g. if you set the threshold to only errors, then only the errors appear in the Xdebug log.

tomjn

2020-12-23 12:38

reporter   ~0005609

Based on log.c I suspect this change will resolve my issue https://github.com/Varying-Vagrant-Vagrants/VVV/pull/2324/files I've not tested this.

If so, I'll think of a way to word the configuration document to avoid the confusion in future

derick

2020-12-23 13:16

administrator   ~0005610

hmmm, then that might be a bug, but I'd still like the option for it to all go in the Xdebug log and only the Xdebug log, I've had multiple people poke me that their PHP error logs are being filibustered by these messages that are of no use to them.

And I've had hundreds of people complain that Xdebug is hard to use, where having a look at these messages would tell them Xdebug is trying to connect to the wrongly configured host.

The way we have Xdebug configured is that when it's turned on all requests are in debug mode. As a result unless you have VSCode listening before the environment is available, and keep it running without fail until the environment is shutdown ( possibly weeks later ), you'll get messages in your error log, lots of them. Restarting VSCode for an update and forgetting to begin the debugging session while a post editor in a forgotten tab sends heartbeat pings means your error log is spammed with these messages.

Instead, I'd like to tell people to look at the configured Xdebug log for Xdebug issues.

Yes, that is what the log is for. And it will tell you in great detail what is going on (depending on log_level). The only errors that get bumped to PHP's error log are "XLOG_ERR" and "XLOG_CRIT" errors.

I don't mind if i have to add an extra parameter for this. Would this be possible by adjusting the log level?

To do what?

If so the documentation isn't clear on that, my assumption is that it worked like the PHP error log level but for the Xdebug remote log, e.g. if you set the threshold to only errors, then only the errors appear in the Xdebug log.

Yes, that is exactly correct. The xdebug.log_level value controls what goes into the xdebug.log log file.

Based on log.c I suspect this change will resolve my issue https://github.com/Varying-Vagrant-Vagrants/VVV/pull/2324/files I've not tested this.

That seems entirely pointless, as that means the log is always empty.

If so, I'll think of a way to word the configuration document to avoid the confusion in future

I changed the order and added "Criticals" to the documentation.

tomjn

2020-12-24 16:42

reporter   ~0005611

I want Xdebug logging to happen in the Xdebug log and only the Xdebug log, not the PHP error log. I understand the reason it's showing in the PHP error log, but it's causing more problems for VVV users than it solves. Output in the PHP error log is highly undesirable, and considered a showstopper bug by several of our users, and a major inconvenience.

Right now, people are using and debugging with Xdebug, yet despite this the PHP error log is filling up with irrelevant uninformative messages. I understand that if it can't connect then a PHP error message would be useful, but it does connect! And it prints it out anyway, and it does it in great numbers.

That seems entirely pointless, as that means the log is always empty.

Which log?

If you're referring to the PHP error log then great, that's good news! Exactly the desired behaviour. I agree that a critical error is useful to know about, but auto-discovery falling back to the client host then successfully connecting is at best a warning, if not an info message. After all if people are having Xdebug issues we can point them to the Xdebug log for Xdebug errors.

If you're talking about the Xdebug log then that's unfortunate, we don't want Xdebug spamming our PHP error logs telling us it fall back to client_host, we know the debugging connection succeeded and are successfully using it!

If you're talking about both then that's extremely unfortunate.

tomjn

2020-12-24 16:45

reporter   ~0005612

TLDR Xdebug works, it connects, successful debugging sessions are taking place, and yet it spams the main PHP error log that it used a fallback. I'm trying to fix that after multiple bug reports

tomjn

2020-12-24 16:51

reporter   ~0005613

My understanding is that if Xdebug tries to discover the client via headers and fails, but succeeds when it falls back to client_host, then nothing should appear in the PHP error log as a succesful connection was made. This is not what I'm seeing.

derick

2020-12-24 17:54

administrator   ~0005614

You're going to have to make a reproducible case for me then as that's not how it's supposed to work, and it's not what I'm seeing. It will/should only send an error to the PHP error log if it can't connect at all.

derick

2021-01-20 11:48

administrator   ~0005644

@ludwig.gramberg — I am hiding your comment as the claim in this report is that Xdebug warns even if it could make a connection, which as of now still has to be proven. Your issue is separate.

tomjn

2021-01-20 12:47

reporter   ~0005645

@derick is there a way to just turn off the offending feature? I'm still getting support issues for this. I understand you want to make things nice for new users, but these are not new users, and we have helper mechanisms in place already to help people get connected. This feature is hurting more than it's helping.

derick

2021-03-17 08:31

administrator   ~0005718

I'm closing this issue in favour of the feature issue 0001948 for Xdebug 3.1.

Issue History

Date Modified Username Field Change
2020-12-18 18:44 tomjn New Issue
2020-12-18 18:47 tomjn Note Added: 0005603
2020-12-18 18:50 tomjn Note Added: 0005604
2020-12-21 13:29 derick Assigned To => derick
2020-12-21 13:29 derick Status new => feedback
2020-12-21 13:29 derick Note Added: 0005605
2020-12-21 14:31 tomjn Note Added: 0005606
2020-12-21 14:31 tomjn Status feedback => assigned
2020-12-23 12:13 derick Note Edited: 0005605
2020-12-23 12:17 derick Note Added: 0005607
2020-12-23 12:32 tomjn Note Added: 0005608
2020-12-23 12:38 tomjn Note Added: 0005609
2020-12-23 13:16 derick Note Added: 0005610
2020-12-24 16:42 tomjn Note Added: 0005611
2020-12-24 16:45 tomjn Note Added: 0005612
2020-12-24 16:51 tomjn Note Added: 0005613
2020-12-24 17:54 derick Note Added: 0005614
2020-12-30 12:14 derick Status assigned => feedback
2021-01-20 11:48 derick Note Added: 0005644
2021-01-20 12:47 tomjn Note Added: 0005645
2021-01-20 12:47 tomjn Status feedback => assigned
2021-03-17 08:31 derick Status assigned => closed
2021-03-17 08:31 derick Resolution open => won't fix
2021-03-17 08:31 derick Note Added: 0005718
2021-03-17 08:31 derick Relationship added duplicate of 0001948