View Issue Details

IDProjectCategoryView StatusLast Update
0001401XdebugStep Debuggingpublic2020-01-27 19:33
Reporterjaytaph Assigned Toderick  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionfixed 
Platformosx 
Summary0001401: XDebug does not check correctly for closed connections
Description

In the master branch there is a new check in send_message() that will print out a warning whenever SSENDL() cannot correctly send over all data. However, this does not check to see if the current socket is already closed or not, resulting in a lot of warnings that shouldn't.

When remote_autostart & remote_connect_back are set (which is often the case when dealing with a development environment where you start the listener from the IDE like PHPStorm), normally, the 9000 port is closed, resulting in SYN packet from xdebug immediately followed by RST+ACK from osx since that port is not listening. XDebug does not detect this correctly, resulting in send_message() happily trying to send over data). As soon as the IDE debug listener is turned on, port 9000 is available and send_message() can send data without issues.

Steps To Reproduce

set configuration to:

  • remote_autostart=1
  • remote_connect_back=1

Run any script.
Warnings will be triggered like: "There was a problem sending 178 bytes on socket 7"

Turn on debugger on port 9000
No more warnings

TagsNo tags attached.
Operating Systemosx
PHP Version7.1.0-7.1.4

Activities

derick

2017-02-28 16:54

administrator   ~0004221

Curious, I thought I had replied to this one already.

I can not reproduce this.

When I run this on Linux with strace, I just get this:

socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
fcntl(3, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(9000), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
poll([{fd=3, events=POLLIN|POLLPRI|POLLOUT}], 1, 200) = 1 ([{fd=3, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
close(3)

And nothing else — perhaps it is different on OSX. Can you make something like an strace for OSX? I think it's called dtruss there.

jaytaph

2017-03-01 10:53

reporter   ~0004222

I've taken a closer look and the setup is a bit more complicated than simply osx (because docker). I've managed to track the issue down to automatically connecting to an incorrect IP address, which turns out is the same IP address where a php-fpm instance is running on port 9000.

This apparently does not like to chat with dbgp, since php-fpm drops the connection after the initial xml packet, but this isn't picked up by xdebug.

This is a backtrace of what's happening, with some small remarks

[pid 9] <... accept resumed> {sa_family=AF_INET6, sin6_port=htons(56418), inet_pton(AF_INET6, "::ffff:172.18.0.13", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 5
[pid 9] times({tms_utime=725, tms_stime=398, tms_cutime=0, tms_cstime=0}) = 4308070207
[pid 9] poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLIN}])
[pid 9] read(5, "\1\1\0\1\0\10\0\0", 8) = 8
[pid 9] read(5, "\0\1\0\0\0\0\0\0", 8) = 8
[pid 9] read(5, "\1\4\0\1\2J\6\0", 8) = 8
[pid 9] read(5, "\f\0QUERY_STRING\16\3REQUEST_METHODGE"..., 592) = 592
[pid 9] read(5, "\1\4\0\1\0\0\0\0", 8) = 8
[pid 9] lstat("/var/www/apipoc/web/app.php", {st_mode=S_IFREG|0664, st_size=53, ...}) = 0
[pid 9] lstat("/var/www/apipoc/web", {st_mode=S_IFDIR|0775, st_size=306, ...}) = 0
[pid 9] lstat("/var/www/apipoc", {st_mode=S_IFDIR|0755, st_size=748, ...}) = 0
[pid 9] lstat("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 9] lstat("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 9] stat("/var/www/apipoc/web/.user.ini", 0x7ffffd99a010) = -1 ENOENT (No such file or directory)
[pid 9] setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
[pid 9] rt_sigaction(SIGPROF, {0x55be0fe57940, [PROF], SA_RESTORER|SA_RESTART, 0x7f90d83ee0e0}, {0x55be0fe57940, [PROF], SA_RESTORER|SA_RESTART, 0x7f90d83ee0e0}, 8) = 0
[pid 9] rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
[pid 9] getcwd("/var/www/apipoc", 4095) = 16
[pid 9] chdir("/var/www/apipoc/web") = 0
[pid 9] fcntl(4, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1, len=1}) = 0
[pid 9] stat("/var/www/apipoc/web/app.php", {st_mode=S_IFREG|0664, st_size=53, ...}) = 0

opening Xdebug connection to 172.18.0.3:9000 (which runs php-fpm, not an xdebug listener)

[pid 9] socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 7
[pid 9] fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
[pid 9] connect(7, {sa_family=AF_INET, sin_port=htons(9000), sin_addr=inet_addr("172.18.0.3")}, 16) = -1 EINPROGRESS (Operation now in progress)
[pid 9] poll([{fd=7, events=POLLIN|POLLPRI|POLLOUT}], 1, 200) = 1 ([{fd=7, revents=POLLOUT}])
[pid 9] getpeername(7, {sa_family=AF_INET, sin_port=htons(9000), sin_addr=inet_addr("172.18.0.3")}, [16]) = 0
[pid 9] fcntl(7, F_SETFL, O_RDONLY) = 0
[pid 9] setsockopt(7, SOL_TCP, TCP_NODELAY, "\1\0\0\0\0\0\0\0", 8) = 0
[pid 9] write(7, "493\0<?xml version=\"1.0\" encoding"..., 498) = 498

php-fpm closes connection

[pid 9] recvfrom(7, 0x7ffffd998cb0, 128, 0, 0, 0) = -1 ECONNRESET (Connection reset by peer)
[pid 9] setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
[pid 9] read(10, "\320\356 n\303\264\r+", 8) = 8
[pid 9] chdir("/var/www/apipoc") = 0
[pid 9] times({tms_utime=725, tms_stime=398, tms_cutime=0, tms_cstime=0}) = 4308070208
[pid 9] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
[pid 9] write(6, "172.18.0.13 - 01/Mar/2017:10:48"..., 61) = 61
[pid 9] setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0

xdebug didn't handle closed connection and happily sends more data

[pid 9] write(7, "173\0<?xml version=\"1.0\" encoding"..., 178) = -1 EPIPE (Broken pipe)
[pid 9] --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=9, si_uid=33} ---
[pid 9] write(2, "There was a problem sending 178 "..., 49) = 49
[pid 9] recvfrom(7, "", 128, 0, NULL, NULL) = 0
[pid 9] close(7) = 0

[pid 9] fcntl(4, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
[pid 9] write(5, "\1\6\0\1\0T\4\0X-Powered-By: PHP/7.0.15"..., 112) = 112
[pid 9] shutdown(5, SHUT_WR) = 0
[pid 9] recvfrom(5, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
[pid 9] recvfrom(5, "", 8, 0, NULL, NULL) = 0
[pid 9] close(5) = 0
[pid 9] munmap(0x7f90c9a00000, 2097152) = 0
[pid 9] setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
[pid 9] accept(0,

derick

2017-03-01 12:26

administrator   ~0004223

I'll improve the error message, but it's working as expected:

Xdebug can't detect that a connection has been closed until it tries to write again. And when it tries to write, the write fails and Xdebug shows an error message.

In this case, the error message rightfully pointed out that something was wrong.

derick

2017-03-02 09:59

administrator   ~0004225

Improved the error message for 2.6dev.

vortextangent

2020-01-27 19:33

reporter   ~0005226

I noticed this happens in a specific instance for me. When phpstorm either has too many debug connections open or the connection has timed out. Closing php storm resolved the issue for me.

Issue History

Date Modified Username Field Change
2017-02-22 10:00 jaytaph New Issue
2017-02-28 16:54 derick Note Added: 0004221
2017-02-28 16:54 derick Assigned To => derick
2017-02-28 16:54 derick Status new => feedback
2017-03-01 10:53 jaytaph Note Added: 0004222
2017-03-01 10:53 jaytaph Status feedback => assigned
2017-03-01 12:26 derick Note Added: 0004223
2017-03-02 09:59 derick Note Added: 0004225
2017-03-02 09:59 derick Status assigned => closed
2017-03-02 09:59 derick Resolution open => fixed
2020-01-27 19:33 vortextangent Note Added: 0005226
2020-03-12 16:33 derick Category Remote Debugging => Step Debugging