Ratchet on 100% CPU load

[ollm]

Hi.

During the last month, I am having a problem with running a Ratchet server in a production environment, suddenly the process goes from normally using 0-1% of a CPU core to 98-100%, the websocket server still working but it takes longer to respond, this happens in a variety of ways, sometimes it takes a few hours to happen and others it takes days / weeks.

When it enters this state it does not exit again until I kill the process and supervisor starts a new one.

I am also checking the logic of my application so that it is not a problem on my part.

Apache version

Server Version: Apache/2.4.51 (cPanel) OpenSSL/1.1.1g mod_bwlimited/1.4
Server MPM: event
Server Built: Nov 7 2021 17:32:31

PHP version

PHP 8.0.12 (cli) (built: Nov 10 2021 01:18:26) ( NTS )
Copyright (c) The PHP Group
Zend Engine v4.0.12, Copyright (c) Zend Technologies
    with Zend OPcache v8.0.12, Copyright (c), by Zend Technologies

Ratchet version being used

cboden/ratchet v0.4.4 PHP WebSocket library
├──guzzlehttp/psr7 v1.8.3
├──ratchet/rfc6455 v0.3.1
├──react/event-loop v1.2.0
├──react/socket v1.10.0
├──symfony/http-foundation v6.0.1
└──symfony/routing v4.4.34

Event loop

ExtEvLoop
ev (1.1.4)

supervisor.conf

[unix_http_server]
file = /tmp/supervisor.sock

[supervisord]
logfile          = ./logs/supervisord.log
logfile_maxbytes = 50MB
logfile_backups  = 10
loglevel         = info
pidfile          = /tmp/supervisord.pid
nodaemon         = false
minfds           = 4096
minprocs         = 200

[rpcinterface:supervisor]
supervisor.rpcinterface_factory = supervisor.rpcinterface:make_main_rpcinterface

[supervisorctl]
serverurl = unix:///tmp/supervisor.sock

[program:ratchet]
directory				= /home/username/public_html
command                 = bash -c "ulimit -n 10000; exec php chat.php"
process_name            = Chat
numprocs                = 1
autostart               = true
autorestart             = true
user                    = root
stdout_logfile          = ./logs/chat_info.log
stdout_logfile_maxbytes = 1MB
stderr_logfile          = ./logs/chat_error.log
stderr_logfile_maxbytes = 1MB

I have this code in the app, but there is no record in chat_info.log or chat_error.log

public function onError(ConnectionInterface $conn, \Exception $e)
{
	echo "An error has occurred: {$e->getMessage()}\n";

	$conn->close();
}

This is what appears if I run strace in the pid

strace

--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10399) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10399) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10399) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10399) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10399) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10398) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10398) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10398) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10398) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10398) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10397) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10397) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10397) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10397) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)

Thank you for your replies.

[WyriHaximus]

What happens at the of the sudden increase in CPU usage, like more users/messages/anything?
Are you using any blocking code such as PDO or sleep or file_get_contents?

[ollm]

I still haven't been able to see how many users there are when it happens, since I realize hours later, but there are currently 200 users and there must be probably about 300/400 at their peak. currently the onMessage function receives about 10 messages per minute.

Are you using any blocking code such as PDO or sleep or file_get_contents?

My code has SQL queries and also uses the filemtime function.

I don't know if this has something to do with it, but I just noticed that the code that I use in onOpen and onColse to save the client is different from the one in the documentation.

I have something like to this:

public function onOpen(ConnectionInterface $conn)
{
	$this->clients[$conn->resourceId] = $conn;
}

public function onClose(ConnectionInterface $conn)
{
	// The connection is closed, remove it, as we can no longer send it messages
	unset($this->clients[$conn->resourceId]);
}

Thank for your replie.

[ahmeteminkocal]

You can make use of xdebug to find out exaclty where your app is struggling.

[zhiyong-ft]

@ollm two items come to mind: 1) You are running PHP8.0 Is this a good idea for production server? I read in some of the issues that ZMQ has trouble with PHP7.2+. I had trouble with PHP7.2+ on windows, but so far not on Ubuntu. Also not on a production server yet. 2) run garbage collection upon connection close? Also in one of issues from years ago, it was mentioned that we need to force garbage collection once in a while.

Just some observation, hope it helps.

[zhiyong-ft]

The other thing to try is use either artilery or autobahn to stress test your application or server, and see if this happens again.

[ollm]

I have been testing wsstat and artillery to stress the server and from 1000-1200 some of the new connections start to fail (wsstat shows error 429 and artillery shows ECONNRESET), up to 2200 connections, I don't know if this could be due to the websocket going through Cloudflare or it is some problem with my internet connection, I had seen in other issues that they have problems when exceeding 1024 connections, but it seems that this is not the same problem, during the stress test the process reaches 100% CPU, but once finished it returns to normal values.

Now I am testing with PHP 7.2, which is the oldest version that I currently have installed on the server.

Thanks for all replies.

[ollm]

Hi.

With PHP 7.2 I still have the same problem, I have been testing xdebug to see where it happens and the Broken pipe error appears between lines 129 and 139 of https://github.com/reactphp/stream/blob/70d6e15d5f90730651558852c74fbb767fd9215b/src/WritableResourceStream.php although it seems to be more related to the fwrite of line 124: https://github.com/reactphp/stream/blob/70d6e15d5f90730651558852c74fbb767fd9215b/src/WritableResourceStream.php#L124

strace

strace: Process 1707488 attached
recvfrom(133, "step_into -i 2797\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 306) = 306
write(133, "322\0<?xml version=\"1.0\" encoding"..., 327) = 327
recvfrom(133, "step_into -i 2798\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 343) = 343
write(133, "359\0<?xml version=\"1.0\" encoding"..., 364) = 364
recvfrom(133, "step_into -i 2799\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 344) = 344
write(133, "360\0<?xml version=\"1.0\" encoding"..., 365) = 365
recvfrom(133, "step_into -i 2800\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 342) = 342
write(133, "358\0<?xml version=\"1.0\" encoding"..., 363) = 363
recvfrom(133, "step_into -i 2801\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 342) = 342
write(133, "358\0<?xml version=\"1.0\" encoding"..., 363) = 363
recvfrom(133, "step_into -i 2802\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 342) = 342
write(133, "358\0<?xml version=\"1.0\" encoding"..., 363) = 363
recvfrom(133, "step_into -i 2803\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 353) = 353
write(133, "369\0<?xml version=\"1.0\" encoding"..., 374) = 374
recvfrom(133, "step_into -i 2804\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 342) = 342
write(133, "358\0<?xml version=\"1.0\" encoding"..., 363) = 363
recvfrom(133, "step_into -i 2805\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 342) = 342
write(133, "358\0<?xml version=\"1.0\" encoding"..., 363) = 363
recvfrom(133, "step_into -i 2806\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 342) = 342
write(133, "358\0<?xml version=\"1.0\" encoding"..., 363) = 363
recvfrom(133, "step_into -i 2807\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 342) = 342
write(133, "358\0<?xml version=\"1.0\" encoding"..., 363) = 363
recvfrom(133, "step_into -i 2808\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 344) = 344
write(133, "360\0<?xml version=\"1.0\" encoding"..., 365) = 365
recvfrom(133, "step_into -i 2809\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 340) = 340
write(133, "356\0<?xml version=\"1.0\" encoding"..., 361) = 361
recvfrom(133, "step_into -i 2810\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 341) = 341
write(133, "357\0<?xml version=\"1.0\" encoding"..., 362) = 362
recvfrom(133, "step_into -i 2811\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 340) = 340
write(133, "356\0<?xml version=\"1.0\" encoding"..., 361) = 361
recvfrom(133, "step_into -i 2812\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 350) = 350
write(133, "366\0<?xml version=\"1.0\" encoding"..., 371) = 371
recvfrom(133, "step_into -i 2813\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 350) = 350
write(133, "366\0<?xml version=\"1.0\" encoding"..., 371) = 371
recvfrom(133, "step_into -i 2814\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 319) = 319
write(133, "335\0<?xml version=\"1.0\" encoding"..., 340) = 340
recvfrom(133, "step_into -i 2815\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 350) = 350
write(133, "366\0<?xml version=\"1.0\" encoding"..., 371) = 371
recvfrom(133, "step_into -i 2816\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 350) = 350
write(133, "366\0<?xml version=\"1.0\" encoding"..., 371) = 371
recvfrom(133, "step_into -i 2817\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 336) = 336
write(133, "352\0<?xml version=\"1.0\" encoding"..., 357) = 357
recvfrom(133, "step_into -i 2818\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 328) = 328
write(133, "344\0<?xml version=\"1.0\" encoding"..., 349) = 349
recvfrom(133, "step_into -i 2819\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 328) = 328
write(133, "344\0<?xml version=\"1.0\" encoding"..., 349) = 349
recvfrom(133, "step_into -i 2820\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2821\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2822\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2823\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2824\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
write(21, "\27\3\3\0\25\2553\354\364)\367\271\244\0312|\261B\377\252\25&\233v\302\330", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1707488, si_uid=0} ---
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2825\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2826\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2827\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2828\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2829\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2830\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 338) = 338
write(133, "354\0<?xml version=\"1.0\" encoding"..., 359) = 359
recvfrom(133, "step_into -i 2831\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 328) = 328
write(133, "344\0<?xml version=\"1.0\" encoding"..., 349) = 349
recvfrom(133, "step_into -i 2832\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2833\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 339) = 339
write(133, "355\0<?xml version=\"1.0\" encoding"..., 360) = 360
recvfrom(133, "step_into -i 2834\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 339) = 339
write(133, "355\0<?xml version=\"1.0\" encoding"..., 360) = 360
recvfrom(133, "step_into -i 2835\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 339) = 339
write(133, "355\0<?xml version=\"1.0\" encoding"..., 360) = 360
recvfrom(133, "step_into -i 2836\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2837\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 339) = 339
write(133, "355\0<?xml version=\"1.0\" encoding"..., 360) = 360
recvfrom(133, "step_into -i 2838\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2839\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2840\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2841\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2842\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2843\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
epoll_wait(7, [{EPOLLOUT|EPOLLHUP, {u32=21, u64=11300058955797}}, {EPOLLIN, {u32=167, u64=8177617731751}}, {EPOLLIN, {u32=17, u64=19116899434513}}, {EPOLLIN, {u32=102, u64=13713830576230}}, {EPOLLIN, {u32=8, u64=4294967304}}, {EPOLLIN, {u32=81, u64=12468290060369}}, {EPOLLIN, {u32=30, u64=20143396618270}}, {EPOLLIN, {u32=66, u64=16642998272066}}, {EPOLLIN, {u32=98, u64=15401752723554}}, {EPOLLIN, {u32=170, u64=7816840478890}}], 262, 1) = 10
epoll_ctl(7, EPOLL_CTL_MOD, 21, {EPOLLOUT, {u32=21, u64=11300058955797}}) = 0
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 329) = 329
write(133, "345\0<?xml version=\"1.0\" encoding"..., 350) = 350
recvfrom(133, "step_into -i 2844\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 330) = 330
write(133, "346\0<?xml version=\"1.0\" encoding"..., 351) = 351
recvfrom(133, "step_into -i 2845\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 344) = 344
write(133, "360\0<?xml version=\"1.0\" encoding"..., 365) = 365
recvfrom(133, "step_into -i 2846\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 344) = 344
write(133, "360\0<?xml version=\"1.0\" encoding"..., 365) = 365
recvfrom(133, "step_into -i 2847\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 347) = 347
write(133, "363\0<?xml version=\"1.0\" encoding"..., 368) = 368
recvfrom(133, "step_into -i 2848\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 352) = 352
write(133, "368\0<?xml version=\"1.0\" encoding"..., 373) = 373
recvfrom(133, "step_into -i 2849\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 347) = 347
write(133, "363\0<?xml version=\"1.0\" encoding"..., 368) = 368
recvfrom(133, "step_into -i 2850\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 344) = 344
write(133, "360\0<?xml version=\"1.0\" encoding"..., 365) = 365
recvfrom(133, "step_into -i 2851\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488

xdebug

(cmd) step_into
2797 | step_into > break/ok
2797 | file:///home/username/public_html/includes/chat.php:3636

(cmd) 
2798 | step_into > break/ok
2798 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php:76

(cmd) 
2799 | step_into > break/ok
2799 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php:132

(cmd) 
2800 | step_into > break/ok
2800 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php:251

(cmd) 
2801 | step_into > break/ok
2801 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php:252

(cmd) 
2802 | step_into > break/ok
2802 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php:254

(cmd) 
2803 | step_into > break/ok
2803 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Handshake/PermessageDeflateOptions.php:167

(cmd) 
2804 | step_into > break/ok
2804 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php:258

(cmd) 
2805 | step_into > break/ok
2805 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php:195

(cmd) 
2806 | step_into > break/ok
2806 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php:198

(cmd) 
2807 | step_into > break/ok
2807 | file:///home/username/public_html/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php:199

(cmd) 
2808 | step_into > break/ok
2808 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php:154

(cmd) 
2809 | step_into > break/ok
2809 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/Http/HttpServer.php:55

(cmd) 
2810 | step_into > break/ok
2810 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/Server/IoServer.php:116

(cmd) 
2811 | step_into > break/ok
2811 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/Server/IoServer.php:96

(cmd) 
2812 | step_into > break/ok
2812 | file:///home/username/public_html/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php:127

(cmd) 
2813 | step_into > break/ok
2813 | file:///home/username/public_html/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php:134

(cmd) 
2814 | step_into > break/ok
2814 | file:///home/username/public_html/vendor/react/stream/src/Util.php:72

(cmd) 
2815 | step_into > break/ok
2815 | file:///home/username/public_html/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php:127

(cmd) 
2816 | step_into > break/ok
2816 | file:///home/username/public_html/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php:134

(cmd) 
2817 | step_into > break/ok
2817 | file:///home/username/public_html/vendor/react/stream/src/DuplexResourceStream.php:202

(cmd) 
2818 | step_into > break/ok
2818 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:97

(cmd) 
2819 | step_into > break/ok
2819 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:96

(cmd) 
2820 | step_into > break/ok
2820 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:118

(cmd) 
2821 | step_into > break/ok
2821 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:119

(cmd) 
2822 | step_into > break/ok
2822 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:123

(cmd) 
2823 | step_into > break/ok
2823 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:124

(cmd) 
2824 | step_into > break/ok
2824 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:129

(cmd) 
2825 | step_into > break/ok
2825 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:139

(cmd) 
2826 | step_into > break/ok
2826 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:146

(cmd) 
2827 | step_into > break/ok
2827 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:147

(cmd) 
2828 | step_into > break/ok
2828 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:150

(cmd) 
2829 | step_into > break/ok
2829 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:155

(cmd) 
2830 | step_into > break/ok
2830 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:167

(cmd) 
2831 | step_into > break/ok
2831 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:97

(cmd) 
2832 | step_into > break/ok
2832 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:192

(cmd) 
2833 | step_into > break/ok
2833 | file:///home/username/public_html/vendor/react/event-loop/src/Tick/FutureTickQueue.php:42

(cmd) 
2834 | step_into > break/ok
2834 | file:///home/username/public_html/vendor/react/event-loop/src/Tick/FutureTickQueue.php:44

(cmd) 
2835 | step_into > break/ok
2835 | file:///home/username/public_html/vendor/react/event-loop/src/Tick/FutureTickQueue.php:49

(cmd) 
2836 | step_into > break/ok
2836 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:194

(cmd) 
2837 | step_into > break/ok
2837 | file:///home/username/public_html/vendor/react/event-loop/src/Tick/FutureTickQueue.php:58

(cmd) 
2838 | step_into > break/ok
2838 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:195

(cmd) 
2839 | step_into > break/ok
2839 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:196

(cmd) 
2840 | step_into > break/ok
2840 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:201

(cmd) 
2841 | step_into > break/ok
2841 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:202

(cmd) 
2842 | step_into > break/ok
2842 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:208

(cmd) 
2843 | step_into > break/ok
2843 | file:///home/username/public_html/vendor/react/event-loop/src/ExtEvLoop.php:162

(cmd) 
2844 | step_into > break/ok
2844 | file:///home/username/public_html/vendor/react/event-loop/src/Timer/Timer.php:48

(cmd) 
2845 | step_into > break/ok
2845 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php:210

(cmd) 
2846 | step_into > break/ok
2846 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php:211

(cmd) 
2847 | step_into > break/ok
2847 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsConnection.php:31

(cmd) 
2848 | step_into > break/ok
2848 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/AbstractConnectionDecorator.php:31

(cmd) 
2849 | step_into > break/ok
2849 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsConnection.php:32

(cmd) 
2850 | step_into > break/ok
2850 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php:213

(cmd) 
2851 | step_into > break/ok
2851 | file:///home/username/public_html/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php:215

xdebug and strace with this breakpoints:

breakpoint_set -t line -f file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php -n 129
breakpoint_set -t line -f file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php -n 139

strace

write(123, "\27\3\3\0\25\17y\225\267n\303=\271\340\225K\220\354H\317\3624<z\270\233", 26) = 26
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2781\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2782\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
shutdown(123, SHUT_RDWR)                = 0
fcntl(123, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(123, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
write(123, "\27\3\3\0\23\324\360>\2\252\314\2341\301\204v\177\341\324!\23\320\34>", 24) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1707488, si_uid=0} ---
close(123)                              = 0
write(122, "\27\3\3\0\25\270\313\315\34\\j\216\30\260)\1\16\357{\335bs\2\230\233\"", 26) = 26
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2783\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2784\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
shutdown(122, SHUT_RDWR)                = 0
fcntl(122, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(122, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
write(122, "\27\3\3\0\23g\341\261\265\234\277\267\330\341\341\200\7\303K\333\24?\37\340", 24) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1707488, si_uid=0} ---
close(122)                              = 0
write(121, "\27\3\3\0\25\267F3\361\303\25\326\351\255\211\210\236<Q\236\254n\245\270D\256", 26) = 26
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2785\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2786\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
shutdown(121, SHUT_RDWR)                = 0
fcntl(121, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(121, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
write(121, "\27\3\3\0\23mV\0275\16j|+\17bR\217\36R\215\240y\225\215", 24) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1707488, si_uid=0} ---
close(121)                              = 0
write(120, "\27\3\3\0\25$\267\317\202\204F\2\353\20\311\177\220\257\227+p2|.\276\30", 26) = 26
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2787\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2788\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
shutdown(120, SHUT_RDWR)                = 0
fcntl(120, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(120, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
write(120, "\27\3\3\0\0236=\362!\336\304\16\357\271\10QQ.S\210V2M\5", 24) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1707488, si_uid=0} ---
close(120)                              = 0
write(119, "\27\3\3\0\25\225\336\340\374\257\351\212\225&\307\276\271\233=\223`\256\246|\32L", 26) = 26
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2789\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2790\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38
shutdown(119, SHUT_RDWR)                = 0
fcntl(119, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(119, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
write(119, "\27\3\3\0\23\335 \3728\374\320\241\313\207\216H\371?] 6B\2561", 24) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1707488, si_uid=0} ---
close(119)                              = 0
write(118, "\27\3\3\0\25B\307\223d\312\337\263\354\241\375\312\"\353&\354d\17\370\355\"\220", 26) = 26
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 332) = 332
write(133, "348\0<?xml version=\"1.0\" encoding"..., 353) = 353
recvfrom(133, "run -i 2791\0", 128, 0, NULL, NULL) = 12
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- run -i"..., 38) = 38

xdebug

(cmd) 
2781 | run > break/ok
2781 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:139

(cmd) 
2782 | run > break/ok
2782 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:129

(cmd) 
2783 | run > break/ok
2783 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:139

(cmd) 
2784 | run > break/ok
2784 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:129

(cmd) 
2785 | run > break/ok
2785 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:139

(cmd) 
2786 | run > break/ok
2786 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:129

(cmd) 
2787 | run > break/ok
2787 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:139

(cmd) 
2788 | run > break/ok
2788 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:129

(cmd) 
2789 | run > break/ok
2789 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:139

(cmd) 
2790 | run > break/ok
2790 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:129

(cmd) 
2791 | run > break/ok
2791 | file:///home/username/public_html/vendor/react/stream/src/WritableResourceStream.php:139

I also have this in strace, but I don't know if it is important.

strace

write(4, "[1707488] [Step Debug] -> <respo"..., 336) = 336
write(133, "352\0<?xml version=\"1.0\" encoding"..., 357) = 357
recvfrom(133, "step_into -i 2340\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 336) = 336
write(133, "352\0<?xml version=\"1.0\" encoding"..., 357) = 357
recvfrom(133, "step_into -i 2341\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
poll([{fd=55, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 1 ([{fd=55, revents=POLLIN}])
read(55, "\27\3\3\0U", 5)               = 5
read(55, "i\300\311CW\7\221]\202G\21\273nz\357\26\377D2-\36\315\343`\223/2\345+s\f\272"..., 85) = 85
poll([{fd=55, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 1 ([{fd=55, revents=POLLIN}])
read(55, "\27\3\3\0\272", 5)            = 5
read(55, "\17\246\240\217SATUw8\376\21\336\342i\376\213Us\253\261\357\3\216\233\365\326\257\246wN-"..., 186) = 186
poll([{fd=55, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
read(55, 0x5605808a0be3, 5)             = -1 EAGAIN (Resource temporarily unavailable)
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 336) = 336
write(133, "352\0<?xml version=\"1.0\" encoding"..., 357) = 357
recvfrom(133, "step_into -i 2342\0", 128, 0, NULL, NULL) = 18
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] <- step_i"..., 44) = 44
getpid()                                = 1707488
write(4, "[1707488] [Step Debug] -> <respo"..., 336) = 336
write(133, "352\0<?xml version=\"1.0\" encoding"..., 357) = 357
recvfrom(133, "step_into -i 2343\0", 128, 0, NULL, NULL) = 18
getpid()

xdebug

(cmd) 
2340 | step_into > break/ok
2340 | file:///home/username/public_html/vendor/react/stream/src/DuplexResourceStream.php:185

(cmd) 
2341 | step_into > break/ok
2341 | file:///home/username/public_html/vendor/react/stream/src/DuplexResourceStream.php:187

(cmd) 
2342 | step_into > break/ok
2342 | file:///home/username/public_html/vendor/react/stream/src/DuplexResourceStream.php:189

(cmd) 
2343 | step_into > break/ok
2343 | file:///home/username/public_html/vendor/react/stream/src/DuplexResourceStream.php:195

(cmd) 
2344 | step_into > break/ok
2344 | file:///home/username/public_html/vendor/react/stream/src/DuplexResourceStream.php:196

For now I will proceed to install PHP 7.1 to see if the problem persists with this version.

Thank you for your replies.

[zhiyong-ft]

My hunch is this has something to do with resource. Are you running it on a shared host or VPS? I saw cPanel in your Apache info. Also did you try to run garbage collection on connection close?

[ollm]

I am running Ratchet in a VPS (AlmaLinux v8.4.0) with KVM (QEMU), in this same VPS I also have my website running with Apache

uname -a

Linux xxxx-xxxxx.server.name 4.18.0-305.19.1.el8_4.x86_64 #1 SMP Wed Sep 15 11:28:53 EDT 2021 x86_64 x86_64 x86_64 GNU/Linux

hostnamectl

   Static hostname: xxxx-xxxxx.server.name
         Icon name: computer-vm
           Chassis: vm
        Machine ID: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
           Boot ID: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
    Virtualization: kvm
  Operating System: AlmaLinux 8.4 (Electric Cheetah)
       CPE OS Name: cpe:/o:almalinux:almalinux:8.4:GA
            Kernel: Linux 4.18.0-305.19.1.el8_4.x86_64
      Architecture: x86-64

Yes, I added gc_collect_cycles(); on the end of onClose function.

I also leave a couple of screenshots of Munin showing sudden CPU usage:

Thank for your replie.

[zhiyong-ft]

This sort of things are really hard to track down. If I were you, I would just set up server(s) on a dedicated bare metal box, most likely your headache will just go away. Those from OVH are rather inexpensive.

[ollm]

Thanks for the suggestion, for now I'm going to wait, chat is a fairly secondary function in my application and at the moment it is not a big problem.

Thanks for all replies.

[acadjsr]

Hi ollm,

Have you resolved this?
I'm also having this issue with 100% CPU load.

[clue]

@ollm Thanks for looking into this, this definitely shouldn't have happened! I did take a look at your strace and xdebug logs and it looks like the server may indeed be "stuck" on a "dead" connection, continuously trying to write some data on each loop tick and always getting an EPIPE/SIGPIPE in return.

epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---
epoll_wait(6, [{EPOLLOUT|EPOLLHUP, {u32=144, u64=3702261809296}}], 680, 10400) = 1
epoll_ctl(6, EPOLL_CTL_MOD, 144, {EPOLLOUT, {u32=144, u64=3702261809296}}) = 0
write(144, "\27\3\3\0\25\261\3\360_\3138\365>\260H\207\321X\226\361\206\240v\326:\351", 26) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=3517427, si_uid=0} ---

(Note to self: The underlying epoll calls seem to confirm you're correctly using ExtEvLoop on a Linux-based system.)

Translating the above snippet to ReactPHP's logic means the event loop (correctly) identified this connection as writable and notified the outgoing stream to (try to) write some data which reports an error message on the syscall level (all correct for dead connections). As rightfully identified, the stream component is responsible for detecting this error condition and properly closing the socket connection in this case. For some reason, this logic doesn't seem to trigger, so the stream accepts an empty write and retries in the next loop iteration ad infinitum, thus causing 100% CPU usage.

It looks like this issue might be related to my changes introduced in reactphp/stream#150 in response to reactphp/stream#149. In this case, it would be helpful for further debugging if you could dump the contents of $sent and $error before this line: https://github.com/reactphp/stream/blob/70d6e15d5f90730651558852c74fbb767fd9215b/src/WritableResourceStream.php#L139

We have reproducible test cases for the existing behavior and I would love to come up with a reproducible test case for your specific error. The test suite contains a number of tests for broken pipes on various platforms and before seeing this very ticket here, I would have expected this to be a non-issue. In either case, thanks for reporting this high quality ticket!

[zhiyong-ft]

@clue this sounds very serious. Should we revert back to certain commit for production servers while you are working on this issue?

[clue]

@zhiyong-ft No reason to panic. To the best of our knowledge this is a very rare error condition that does not seem to happen very often. The PRs linked above have been merged more than a year ago and we are not currently aware of any other reports running into this, despite ReactPHP being used in production in countless applications.

If this condition occurs, you will see load spikes, but the server should stay responsive otherwise (there's no crash or known DoS afaict). If you manage to run into this, please help us identify the root cause (see previous message) and I'm happy to look into this. Reverting to an old version doesn't seem sensible at this point as the previous version had other known issues (again linked in previous message) that are in turn known to be fixed in the current version.