MantisBT

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0001401XdebugRemote Debuggingpublic2017-02-22 10:002017-03-02 09:59
Reporterjaytaph 
Assigned Toderick 
PrioritynormalSeverityminorReproducibilityalways
StatusclosedResolutionfixed 
PlatformosxOSOS Version
Product Version 
Target VersionFixed in Version 
Summary0001401: XDebug does not check correctly for closed connections
DescriptionIn 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 Reproduceset 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
Attached Files

- Relationships

-  Notes
(0004221)
derick (administrator)
2017-02-28 16:54

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.
(0004222)
jaytaph (reporter)
2017-03-01 10:53

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,
(0004223)
derick (administrator)
2017-03-01 12:26

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.
(0004225)
derick (administrator)
2017-03-02 09:59

Improved the error message for 2.6dev.

- 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


Copyright © 2000 - 2017 MantisBT Team
Powered by Mantis Bugtracker