View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0002096XdebugStep Debuggingpublic2022-05-17 16:132022-06-06 08:41
Reporterrastor Assigned Toderick  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionunable to reproduce 
OSMacOS MontereyOS Version12.2.1 (21D62) 
Product Version3.1.4 
Summary0002096: xdebug.connect_timeout_ms not working
Description

Debug works well when listening is enabled on my PHP Storm IDE. When I disable it and try to run any script by php-cli or php-fpm it stops.

xdebug configuration:

xdebug.start_with_request => yes => yes
xdebug.connect_timeout_ms => 200 => 200
xdebug.client_host => host.docker.internal => host.docker.internal
xdebug.client_port => 9009 => 9009
xdebug.log_level => 7 => 7

xdebug log:

[52] Log opened at 2022-05-17 15:55:30.401775
[52] [Step Debug] INFO: Connecting to configured address/port: host.docker.internal:9009.
[52] [Step Debug] INFO: Connected to debugging client: host.docker.internal:9009 (through xdebug.client_host/xdebug.client_port). :-)
[52] [Step Debug] -> <init xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" fileuri="file:///var/www/html/1.php" language="PHP" xdebug:language_version="7.4.28" protocol_version="1.0" appid="52"><engine version="3.1.4"><![CDATA[Xdebug]]></engine><author><![CDATA[Derick Rethans]]></author><url><![CDATA[https://xdebug.org]]></url><copyright><![CDATA[Copyright (c) 2002-2022 by Derick Rethans]]></copyright></init>

strace log:

1652802930.537897 connect(3, {sa_family=AF_INET, sin_port=htons(9009), sin_addr=inet_addr("192.168.65.2")}, 16) = -1 EINPROGRESS (Operation now in progress)
1652802930.539528 ppoll([{fd=3, events=POLLIN|POLLPRI|POLLOUT}], 1, {tv_sec=0, tv_nsec=200000000}, NULL, 0) = 1 ([{fd=3, revents=POLLOUT}], left {tv_sec=0, tv_nsec=199998459})
1652802930.541190 getpeername(3, {sa_family=AF_INET, sin_port=htons(9009), sin_addr=inet_addr("192.168.65.2")}, [28->16]) = 0
1652802930.542757 fcntl(3, F_SETFL, O_RDONLY) = 0
1652802930.544035 setsockopt(3, SOL_TCP, TCP_NODELAY, "\1\0\0\0\0\0\0\0", 8) = 0
1652802930.545167 setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
1652802930.546427 setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [600], 4) = 0
1652802930.547566 setsockopt(3, SOL_TCP, TCP_KEEPCNT, [20], 4) = 0
1652802930.548766 setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
1652802930.550019 getpid()              = 52
1652802930.551395 write(4, "[52] [Step Debug] INFO: Connecte"..., 134) = 134
1652802930.553138 getpid()              = 52
1652802930.554555 getpid()              = 52
1652802930.555783 write(4, "[52] [Step Debug] -> <init xmlns"..., 445) = 445
1652802930.557769 write(3, "466\0<?xml version=\"1.0\" encoding"..., 471) = 471
1652802930.559008 getpid()              = 52
1652802930.560368 recvfrom(3, 0xffffe6575a68, 128, 0, NULL, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
1652803213.215200 --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
1652803213.218784 rt_sigaction(SIGINT, NULL, {sa_handler=0xaaaab5c52870, sa_mask=~[ILL TRAP ABRT BUS FPE KILL SEGV CONT STOP TSTP TTIN TTOU SYS RTMIN RT_1], sa_flags=SA_SIGINFO}, 8) = 0
1652803213.227541 rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_SIGINFO}, NULL, 8) = 0
1652803213.232202 rt_sigprocmask(SIG_UNBLOCK, [INT], NULL, 8) = 0
1652803213.238565 getpid()              = 52
1652803213.241703 kill(52, SIGINT)      = 0
1652803213.245381 --- SIGINT {si_signo=SIGINT, si_code=SI_USER, si_pid=52, si_uid=0} ---
1652803213.273444 +++ killed by SIGINT +++
TagsNo tags attached.
Operating SystemMac OS M1
PHP Version7.4.20-7.4.29

Activities

rastor

2022-05-18 07:19

reporter   ~0006308

At this point, listening was already disabled

1652802930.537897 connect(3, {sa_family=AF_INET, sin_port=htons(9009), sin_addr=inet_addr(&quot;192.168.65.2&quot;)}, 16) = -1 EINPROGRESS (Operation now in progress)
1652802930.539528 ppoll([{fd=3, events=POLLIN|POLLPRI|POLLOUT}], 1, {tv_sec=0, tv_nsec=200000000}, NULL, 0) = 1 ([{fd=3, revents=POLLOUT}], left {tv_sec=0, tv_nsec=199998459})

derick

2022-05-18 10:27

administrator   ~0006310

Last edited: 2022-05-18 10:29

These lines indicate that Xdebug could make a connection, but that that writing is timing out — that is not influenced by the xdebug.connect_timeout_ms setting. The return of poll indicates (1 ([{fd=3, revents=POLLOUT}]) that fd=3 is ready for writing data to, and that it took (200000000 - 199998459) = 1541 nano seconds.

This indicates that the write also succeeded, as it wrote the requested 471 bytes:

1652802930.557769 write(3, "466\0<?xml version="1.0" encoding"..., 471) = 471

The place where this goes wrong is reading form the socket:

1652802930.560368 recvfrom(3, 0xffffe6575a68, 128, 0, NULL, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
1652803213.215200 --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---

(I presume you Ctrl-C'ed this).

Is it possible that there is a firewall being annoying?
Or perhaps that macOS doesn't adhere to "poll" correctly?
Or is it possible Docker is being silly? I read something about that a new version of docker on osx is having some issues, but can't find the article now.
Perhaps, the disabling of the listening socket wasn't actually done yet? (You can check that with netstat -a -n on Linux, and I believe on macOS too)

rastor

2022-05-18 11:17

reporter   ~0006311

Last edited: 2022-05-18 12:56

Thanks for a quick response!

Ok, but I cannot understand why a connection can be successfully created if the port was not opened on IDE. So it seems that a connection must not be established in this case. Is this correct?

(I presume you Ctrl-C'ed this).

yes

Is it possible that there is a firewall being annoying?

I don't think so, coz all works fine when listening is enabled on the IDE side.

Or perhaps that macOS doesn't adhere to "poll" correctly?

I will try to make some tests.

Perhaps, the disabling of the listening socket wasn't actually done yet?

It was definitely disabled. That was one of the first things that I checked.

rastor

2022-05-18 11:23

reporter   ~0006312

Sorry, I have som problems with formatting syntax

derick

2022-05-18 12:57

administrator   ~0006313

No worries about the formatting, I've fixed that. You needed an empty line under ones that start with ">".

rastor

2022-05-26 07:07

reporter   ~0006320

Hey, I've updated PHP Storm to the latest version and haven't seen the issue for a few days now. I think the issue is no longer relevant.

derick

2022-06-06 08:41

administrator   ~0006323

Thanks @rastor for letting me know. I'll close this then, as I have not heard from anybody else with this same issue.

Issue History

Date Modified Username Field Change
2022-05-17 16:13 rastor New Issue
2022-05-18 07:19 rastor Note Added: 0006308
2022-05-18 10:26 derick Assigned To => derick
2022-05-18 10:26 derick Status new => feedback
2022-05-18 10:27 derick Note Added: 0006310
2022-05-18 10:29 derick Note Edited: 0006310
2022-05-18 11:17 rastor Note Added: 0006311
2022-05-18 11:17 rastor Status feedback => assigned
2022-05-18 11:23 rastor Note Added: 0006312
2022-05-18 12:55 derick Note Edited: 0006311
2022-05-18 12:55 derick Note Edited: 0006311
2022-05-18 12:56 derick Note Edited: 0006311
2022-05-18 12:57 derick Note Added: 0006313
2022-05-26 07:07 rastor Note Added: 0006320
2022-06-06 08:41 derick Status assigned => resolved
2022-06-06 08:41 derick Resolution open => unable to reproduce
2022-06-06 08:41 derick Note Added: 0006323