Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[bug][v6.0] Can not possible process "big" (>1Mb) files to HTTP Server with single_tread #5676

Closed
mrVrAlex opened this issue Jan 26, 2025 · 2 comments
Closed

[bug][v6.0] Can not possible process "big" (>1Mb) files to HTTP Server with single_tread #5676

mrVrAlex opened this issue Jan 26, 2025 · 2 comments
Labels
Bug fixed

Comments

@mrVrAlex
Copy link

To reproduce use script:

$http = new Swoole\Http\Server('0.0.0.0', 9501, SWOOLE_PROCESS);
$http->set([
               'single_thread' => true, // Need true with SWOOLE_PROCESS + PHP ZTS
               'worker_num'    => 1,
               'dispatch_mode' => 10,
               'package_max_length' => 134217728, // 128Mb
]);
$http->on('Request', function ($request, $response) {
    var_dump($request->files);
    $response->header('Content-Type', 'text/html; charset=utf-8');
    $response->end('<h1>Hello, Swoole. #' . rand(1000, 9999) . '</h1>');
});
$http->start();

Then make request like this with file bigger then 1Mb (I think any bigger then 65Kb because it seams it chunk size):

curl -X 'POST'   'http://localhost:9501/'   -H 'accept: application/json'  -H 'Content-Type: multipart/form-data'   -F '[email protected];type=text/csv'

And you see in console warning:

[2025-01-26 21:23:24 #4040616.0]        WARNING ReactorEpoll::add(): failed to add events[fd=6#0, type=3, events=1024], Error: File exists[17]

Request will end by curl timeout (so swoole never return response)
And then when stop server (kill PID) you can see:

[2025-01-26 21:24:41 *4040618.0]        WARNING Server::call_worker_stop_callback() (ERRNO 9103): unprocessed data in the worker process buffer

I tried it on many env - reproducable anywhere (PHP ZTS and not, iouring and not).
With 'single_thread' => false - all works as expected.

PHP 8.4.3 (cli) (built: Jan 19 2025 14:20:58) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.4.3, Copyright (c) Zend Technologies
    with Zend OPcache v8.4.3, Copyright (c), by Zend Technologies
Swoole => enabled
Author => Swoole Team <[email protected]>
Version => 6.0.0
Built => Dec 17 2024 05:36:57
coroutine => enabled with boost asm context
epoll => enabled
eventfd => enabled
signalfd => enabled
cpu_affinity => enabled
spinlock => enabled
rwlock => enabled
sockets => enabled
openssl => OpenSSL 3.0.13 30 Jan 2024
dtls => enabled
http2 => enabled
json => enabled
curl-native => enabled
pcre => enabled
c-ares => 1.27.0
mutex_timedlock => enabled
pthread_barrier => enabled
futex => enabled
mysqlnd => enabled
coroutine_pgsql => enabled
coroutine_sqlite => enabled
swoole.enable_library => On => On
swoole.enable_fiber_mock => Off => Off
swoole.enable_preemptive_scheduler => Off => Off
swoole.display_errors => On => On
swoole.use_shortname => On => On
swoole.unixsock_buffer_size => 8388608 => 8388608

In tracing mode see:

Server::accept_connection(:168): [Master] Accept new connection. maxfd=9|minfd=9|reactor_id=0|conn=12
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   ReactorEpoll::add(:107): add events[fd=12#0, type=0, events=512]
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Timer::select(:204): timer msec=103205, round=156
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 65536/65536 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Port_onRead_http(:507): content-length=1096625, keep-alive=0, chunked=0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 94848/1032016 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 363904/937168 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 196608/573264 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv -1/376656 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Timer::select(:204): timer msec=103206, round=157
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 65536/376656 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 65536/311120 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 65483/245584 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 53/180101 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 65536/180048 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 65536/114512 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Socket::recv(:734): recv 48975/48976 bytes, errno=11
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Server::dispatch_task(:871): dispatch task, size=1097551 bytes
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Server::dispatch_task(:879): session_id=14, len=1097551, qb=1097551
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     WARNING ReactorEpoll::add(): failed to add events[fd=7#0, type=3, events=1024], Error: File exists[17]
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=1|size=40|chunk_len=0|chunk=0x77bcb3a6f100
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=1|size=65464|chunk_len=40|chunk=0x77bcb3a6f100
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=2|size=40|chunk_len=0|chunk=0x77bcb3a6f1f0
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=2|size=65464|chunk_len=40|chunk=0x77bcb3a6f1f0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=3|size=40|chunk_len=0|chunk=0x77bcb3a6f2b0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=3|size=65464|chunk_len=40|chunk=0x77bcb3a6f2b0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=4|size=40|chunk_len=0|chunk=0x77bcb3a6efe0
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=4|size=65464|chunk_len=40|chunk=0x77bcb3a6efe0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=5|size=40|chunk_len=0|chunk=0x77bcb3a6f0a0
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   MessageBus::read(:130): append msgid=27, buffer=0x77bcadf5a800, n=65504
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   Timer::select(:204): timer msec=1361, round=10317
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=5|size=65464|chunk_len=40|chunk=0x77bcb3a6f0a0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=6|size=40|chunk_len=0|chunk=0x77bcb3a6f220
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=6|size=65464|chunk_len=40|chunk=0x77bcb3a6f220
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=7|size=40|chunk_len=0|chunk=0x77bcb3a6efb0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=7|size=65464|chunk_len=40|chunk=0x77bcb3a6efb0
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=65464
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=8|size=40|chunk_len=0|chunk=0x77bcb3a6f160
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=8|size=65464|chunk_len=40|chunk=0x77bcb3a6f160
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   MessageBus::write(:258): finish, type=0|len=50127
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=9|size=40|chunk_len=0|chunk=0x77bcb3a6ef80
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Buffer::append(:128): chunk_n=9|size=50127|chunk_len=40|chunk=0x77bcb3a6ef80

I think what problem somewhere in MessageBus & Buffer, because when file is small then after Server::dispatch_task I see accept event and received http request:

application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Server::dispatch_task(:879): session_id=13, len=1118, qb=1118
application-1  | [2025-01-25 22:29:16 #7.0]     TRACE   Timer::select(:204): timer msec=103193, round=153
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   Server::worker_accept_event(:132): [Worker] session_id=13, len=1118, qb=0
application-1  | [2025-01-25 22:29:16 *13.0]    TRACE   php_swoole_http_server_onReceive(:87): http request from 13 with 1118 bytes: <<EOF
@smathersPersonal
Copy link

smathersPersonal commented Feb 6, 2025 •
edited
Loading

I have reproduced this error with a 2mb file, the worker (if using multi process) hangs and cannot handle anymore requests. If the swoole dispatcher picks that worker again for new requests, they also hang

PHP 8.4.3 non-ZTS
Ubuntu 22.04
Swoole v6.0.0

$server = new Swoole\HTTP\Server('[::]', 9009, SWOOLE_PROCESS);
$cpus = swoole_cpu_num();
$server->set([
  'log_level' => 4,
  'reactor_num' => $cpus * 2,
  'worker_num' => $cpus * 6,
  'enable_coroutine' => true,
  'hook_flags' => SWOOLE_HOOK_TCP | SWOOLE_HOOK_NATIVE_CURL | SWOOLE_HOOK_SLEEP | SWOOLE_HOOK_BLOCKING_FUNCTION,
  'package_max_length' => 50 * 1024 * 1024 // 50MB
]);

logs:
[2025-02-06 13:58:15 #3602684.0]#011WARNING#011ReactorEpoll::add(): failed to add events[fd=7#0, type=3, events=1024], Error: File exists[17]

[2025-02-06 15:03:36 *1115173.47]#011WARNING#011Worker_reactor_try_to_exit() (ERRNO 9101): worker exit timeout, forced termination
[2025-02-06 15:03:36 *1118179.0]#011WARNING#011Worker_reactor_try_to_exit() (ERRNO 9101): worker exit timeout, forced termination
[2025-02-06 15:03:36 *1118179.0]#011WARNING#011Server::call_worker_stop_callback() (ERRNO 9103): unprocessed data in the worker process buffer
[2025-02-06 15:03:36 *1115261.20]#011WARNING#011Worker_reactor_try_to_exit() (ERRNO 9101): worker exit timeout, forced termination

@smathersPersonal
Copy link

Just another update here, if i enable threading. my file uploads work.

$server = new Swoole\HTTP\Server('[::]', 9009, SWOOLE_THREAD);
$cpus = swoole_cpu_num();
$server->set([
  'log_level' => 4,
  'reactor_num' => $cpus * 2,
  'worker_num' => $cpus * 6,
  'enable_coroutine' => true,
  'hook_flags' => SWOOLE_HOOK_TCP | SWOOLE_HOOK_NATIVE_CURL | SWOOLE_HOOK_SLEEP | SWOOLE_HOOK_BLOCKING_FUNCTION,
  'package_max_length' => 50 * 1024 * 1024 // 50MB
]);

@matyhtf matyhtf closed this as completed in 82bc69c Feb 8, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug fixed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mrVrAlex @matyhtf @smathersPersonal