diff --git a/CHANGELOG.md b/CHANGELOG.md index 986fb38b..963004c4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- **A TCP syslog sink wrote nothing on Windows, and its socket had two owners everywhere (#293).** Every record was counted as dropped: `log_io_type_for_fd` carried its whole body under `#ifndef PHP_WIN32`, so a socket was driven through the file path and `uv_fs_write` refused the SOCKET with EBADF. With the type detection in place the records arrive and uncover what the file path was hiding — the sink handed the descriptor to `ZEND_ASYNC_IO_CREATE` with `ZEND_ASYNC_IO_PRESERVE_FD` and kept the stream, on the assumption that the flag leaves the descriptor with it. The flag reaches only a descriptor the reactor would otherwise close itself; a socket is adopted by a libuv stream handle that closes it on teardown regardless, so the stream closed it a second time when the caller's resource went. Windows answered that with `socket operation on non-socket`, POSIX with a silent EBADF — the worse half, because the descriptor number is reused and a late close lands on another connection. Ownership now follows the handle type: a file descriptor stays with the stream under `PRESERVE_FD`, a socket belongs to the io and the stream is marked `PHP_STREAM_FLAG_NO_CLOSE`. Duplicating the socket instead was tried and is not a fix — closing the copy sends no FIN, so the collector never sees EOF, and `uv_tcp_open` puts the shared file description into non-blocking mode behind the stream's back. Two defects a review found on the way are fixed with it: `php_stream_cast` writes a `php_socket_t` through the pointer it is given, and the `int` that carried it took an eight-byte write past its own storage on 64-bit Windows; and a Windows socket the io cannot adopt — a datagram one, or the AF_UNIX that libuv will not take — was left on the file path, where it looks like a working sink and drops every record, so the sink refuses to start instead. Evidence: `core/023` fails 3 of 3 runs before and passes 5 of 5 after; the Windows suite goes from 3 failures to 2. - **The Windows build answered every request with identity encoding, whatever the client offered (#291).** Compression was compiled, zlib was linked and `isCompressionEnabled()` said true; `http_accept_encoding_select` returned `HTTP_CODEC_IDENTITY` all the same. It picks a codec inside `#ifdef HAVE_HTTP_COMPRESSION`, and `http_compression_negotiate.c` is pure C by design — the unit suite links it alone — so it includes no PHP header. On POSIX the macro arrives through `config.h`; on Windows it lives in `main/config.w32.h`, which a translation unit sees only through `php.h`, and the block compiled out. `http_compression.c` gates the brotli and zstd registry entries the same way, so those backends would have been built and never reached. `config.w32` passes the three macros on the command line beside the `AC_DEFINE`, as it already does for `HAVE_LLHTTP`. Evidence: a 4200-byte `text/html` body asked for with `Accept-Encoding: gzip` comes back `encoding=gzip` and `Content-Length: 69` where it was 4200 uncompressed, on the buffered and the streamed route alike; `compression/074` fails on its first assertion before and passes after. The rest of the compression group skips on Windows, where the zlib extension the tests decode with is absent, so that one assertion was the whole coverage. - **A streaming HTTP/2 handler that threw could lose the whole response, status line included (#285).** The peer read `status=0` on a stream whose two chunks the handler had written, while RST_STREAM(INTERNAL_ERROR) arrived and every later stream on the connection was served. `h2_stream_append_chunk` ends with `http2_session_emit`, which skips the send while a writev is in flight and leaves the frames to the write completion's re-drive; `h2_stream_abort` then submitted RST_STREAM, and nghttp2 drops what it has queued for a stream it moves to the closing state — the HEADERS commit among it. The ring-exists check that guards the reset reads a non-NULL `chunk_queue` as "the HEADERS are on the wire", and a skipped emit breaks that. The abort now flushes the session through `http2_session_emit_now` before it raises `streaming_ended` and submits the reset, so everything the handler wrote reaches the peer ahead of the reset, on every platform. Evidence: `h2/053` fails 3 of 3 runs on Windows before the fix with an empty body and passes 5 of 5 after; the same test with a 100 ms delay before the first `write()` passes without the fix, which is the race. The test asserted `body=alpha` — one platform's timing, the second chunk lost to the same race — and asserts `body=alphabeta` now. - **A client still uploading when its body was refused read nothing back (#287).** The 413 never reached the peer, though `parse_errors_413_total` counted it. After a parse error `http_connection_handle_read_completion` returns early and consumes nothing, so `read_buffer_len` stays where the error left it and grows with every chunk the peer goes on sending; `http_connection_alloc_cb` then hands the reactor a zero-length buffer and libuv reports `UV_ENOBUFS`, which latches `write_failed` and takes the connection down before the refusal is delivered. Waiting behind it, a socket closed with unread bytes in its receive buffer is reset rather than finished, and the reset discards what this side has written. Latching a parse error now opens a lingering close — nginx's `lingering_close`, Apache's `ap_lingering_close`: arriving bytes are thrown away instead of buffered, and the destroy waits for 500 ms of silence from the peer, refreshed by every chunk, bounded by 5 s in total. Both bounds reach the connection through the deadline tick that already walks the connection list, so no timer is added and the tick period is the resolution: the wait is at least this long, not exactly. Evidence: `h1/005` fails 3 of 4 runs on Windows before and passes 5 of 5 after; with the upload cut to exactly what trips the limit, leaving nothing inbound, it passes either way, which is the cause. diff --git a/src/log/http_log.c b/src/log/http_log.c index 8f561222..1505e5e5 100644 --- a/src/log/http_log.c +++ b/src/log/http_log.c @@ -1124,13 +1124,16 @@ static void *formatter_ud_pretty(HashTable *spec, zval *stream_zv) return NULL; } - int fd = -1; + /* Same carrier as in http_log_sink_start: the cast writes a php_socket_t. */ + php_socket_t raw_fd = (php_socket_t)-1; + if (php_stream_cast(s, PHP_STREAM_AS_FD | PHP_STREAM_CAST_INTERNAL, - (void *)&fd, 0) != SUCCESS || fd < 0) { + (void *)&raw_fd, 0) != SUCCESS + || raw_fd == (php_socket_t)-1) { return NULL; } - return http_log_color_for_fd(fd) ? (void *)1 : NULL; + return http_log_color_for_fd((int)raw_fd) ? (void *)1 : NULL; } /* syslog carries the facility code in ud (default user=1). */ @@ -1902,8 +1905,13 @@ static void writer_teardown(http_log_writer_cb_t *cb) typedef struct { http_log_sink_t *sink; int fd; + zend_async_io_type io_type; http_log_write_mode_t mode; bool ok; + /* Raised as soon as the io exists. From that moment the descriptor is the + * io's, whether the rest of the open succeeds or not — a failure disposes + * the io, and disposing it closes an adopted socket. */ + bool io_created; } log_open_arg_t; /* A stream socket must be driven as a socket, not as a file. Wrapped as a file, @@ -1918,6 +1926,19 @@ typedef struct { * reliable — a wedged collector fills its receive queue and the blocking sendto * then parks a pool thread until the stop deadline abandons it. Everything else * — regular files, stdout, a pipe — keeps its current behaviour. */ +#ifdef PHP_WIN32 +/* Whether the descriptor is a socket at all. Only Windows needs the question: + * there the file path cannot carry one, so a socket the io refuses is a dead + * sink rather than a slow one. */ +static bool log_fd_is_socket(const int fd) +{ + int type = 0; + int tlen = (int) sizeof type; + + return getsockopt((SOCKET) fd, SOL_SOCKET, SO_TYPE, (char *) &type, &tlen) == 0; +} +#endif + static zend_async_io_type log_io_type_for_fd(const int fd) { #ifndef PHP_WIN32 @@ -1946,7 +1967,33 @@ static zend_async_io_type log_io_type_for_fd(const int fd) return ZEND_ASYNC_IO_TYPE_TCP; } #else - (void)fd; + /* A Windows socket is not a CRT descriptor, so the file path does not + * merely park a pool thread here — uv_fs_write refuses the handle with + * EBADF and every record is dropped. The descriptor php_stream_cast hands + * over is the SOCKET itself, which is what the socket calls below take. + * + * Anything but a TCP stream — a datagram socket, or the AF_UNIX that + * Windows 10 has and libuv's pipe handle will not adopt — therefore has no + * transport here at all, and the sink refuses to start rather than drop + * every record. log_fd_is_socket tells that case from a real file. */ + int type = 0; + int tlen = (int) sizeof type; + + if (getsockopt((SOCKET) fd, SOL_SOCKET, SO_TYPE, (char *) &type, &tlen) != 0 + || type != SOCK_STREAM) { + return ZEND_ASYNC_IO_TYPE_FILE; + } + + struct sockaddr_storage sa; + int salen = (int) sizeof sa; + + if (getsockname((SOCKET) fd, (struct sockaddr *) &sa, &salen) != 0) { + return ZEND_ASYNC_IO_TYPE_FILE; + } + + if (sa.ss_family == AF_INET || sa.ss_family == AF_INET6) { + return ZEND_ASYNC_IO_TYPE_TCP; + } #endif return ZEND_ASYNC_IO_TYPE_FILE; @@ -1956,15 +2003,21 @@ static void log_sink_open_op(void *arg) { log_open_arg_t *const a = (log_open_arg_t *)arg; + /* PRESERVE_FD only reaches a descriptor the reactor would otherwise close + * itself, which is the FILE path; a socket is adopted by a libuv stream + * handle that closes it on teardown whatever the flag says. */ zend_async_io_t *const io = - ZEND_ASYNC_IO_CREATE((zend_file_descriptor_t)a->fd, - log_io_type_for_fd(a->fd), - ZEND_ASYNC_IO_WRITABLE | ZEND_ASYNC_IO_PRESERVE_FD); + ZEND_ASYNC_IO_CREATE((zend_file_descriptor_t)a->fd, a->io_type, + a->io_type == ZEND_ASYNC_IO_TYPE_FILE + ? ZEND_ASYNC_IO_WRITABLE | ZEND_ASYNC_IO_PRESERVE_FD + : ZEND_ASYNC_IO_WRITABLE); if (io == NULL) { return; } + a->io_created = true; + http_log_writer_cb_t *const cb = (http_log_writer_cb_t *) ZEND_ASYNC_EVENT_CALLBACK_EX(writer_complete_cb, sizeof(http_log_writer_cb_t)); @@ -2397,17 +2450,42 @@ static bool http_log_sink_start(http_log_sink_t *sink, /* The stream's own async-IO handle is not usable: it belongs to this * thread's loop, and the writes run on the log thread's. Take the raw - * descriptor instead — PRESERVE_FD keeps it with the stream, which stays - * referenced by sink->stream_zv for as long as the sink lives. */ - int fd = -1; + * descriptor instead. + * + * Who owns it afterwards follows the handle type. A file descriptor stays + * with the stream, which sink->stream_zv holds for as long as the sink + * lives, and the reactor leaves it alone. A socket cannot be shared: libuv + * adopts it into a stream handle and closes it on teardown, so the stream + * is released below once the transport is up, and a descriptor still owned + * by a live stream would be closed twice — the second close landing on + * whatever connection has since taken that number. */ + php_socket_t raw_fd = (php_socket_t)-1; if (php_stream_cast(stream, PHP_STREAM_AS_FD | PHP_STREAM_CAST_INTERNAL, - (void *)&fd, 0) != SUCCESS || fd < 0) { + (void *)&raw_fd, 0) != SUCCESS + || raw_fd == (php_socket_t)-1) { fprintf(stderr, "http_server: log stream has no descriptor; sink disabled\n"); return false; } + /* The cast writes a php_socket_t, which is a SOCKET on Windows and eight + * bytes wide there, so the carrier above cannot be an int. Narrowing to one + * afterwards is the documented move: Windows guarantees a SOCKET value fits + * in 32 bits, and the socket calls take it back. */ + const int fd = (int)raw_fd; + + const zend_async_io_type io_type = log_io_type_for_fd(fd); + +#ifdef PHP_WIN32 + if (io_type == ZEND_ASYNC_IO_TYPE_FILE && log_fd_is_socket(fd)) { + fprintf(stderr, + "http_server: only a TCP log transport is supported on Windows; " + "sink disabled\n"); + return false; + } +#endif + tsrm_mutex_lock(g_log_lock); const bool have_thread = log_thread_ref(); tsrm_mutex_unlock(g_log_lock); @@ -2417,9 +2495,17 @@ static bool http_log_sink_start(http_log_sink_t *sink, return false; } - log_open_arg_t arg = { .sink = sink, .fd = fd, .mode = spec->write_mode, .ok = false }; + log_open_arg_t arg = { .sink = sink, .fd = fd, .io_type = io_type, + .mode = spec->write_mode, .ok = false, + .io_created = false }; if (!reactor_pool_exec(g_log_pool, 0, log_sink_open_op, &arg) || !arg.ok) { + /* The io took the socket and its dispose has closed it, so the stream + * must not close that number a second time. */ + if (arg.io_created && io_type != ZEND_ASYNC_IO_TYPE_FILE) { + stream->flags |= PHP_STREAM_FLAG_NO_CLOSE; + } + tsrm_mutex_lock(g_log_lock); log_thread_unref(); tsrm_mutex_unlock(g_log_lock); @@ -2428,6 +2514,16 @@ static bool http_log_sink_start(http_log_sink_t *sink, return false; } + /* A socket belongs to the io from here, and the stream must not close it + * when the caller drops the resource: libuv has adopted it, closes it on + * teardown, and a second close would land on whatever connection has taken + * that descriptor since. A file descriptor stays the stream's, and + * PRESERVE_FD keeps the reactor off it. The stream object itself is held + * either way — freeing it would leave the caller a dead resource. */ + if (io_type != ZEND_ASYNC_IO_TYPE_FILE) { + stream->flags |= PHP_STREAM_FLAG_NO_CLOSE; + } + ZVAL_COPY(&sink->stream_zv, stream_zv); sink->stream_set = true; sink->formatter = spec->formatter != NULL ? spec->formatter