flush() doesn't appear to work

[withinboredom]

Example code:

<?php

echo "hello";
flush();
sleep(2);
echo "world";

Frankenphp should send hello, then 2 seconds later send world. However, we end up with no response sent for 2 seconds, then helloworld sent all in one go.

[withinboredom]

ah, it appears there is some buffering going, and you need to output at least 8192 bytes to get it flush the buffer. I'm now trying to determine which buffer it is.

[withinboredom]

Ok. So with PHP's output buffering off it drops down to 4kb instead of 8. So I think what is going on is that caddy/frankenphp is buffering 4kb. Judging by some old caddy v2 posts in the forum, there was some specific work to bypass buffering for proxy requests.

[withinboredom]

That appears to be the default buffer size for the HTTP transport in Caddy: https://github.com/caddyserver/caddy/blob/e43b6d81782ef79f22058179d8793f40cea89556/modules/caddyhttp/reverseproxy/httptransport.go#L87

[dunglas]

To fix the issue, we probably need to register a function that will call responseWriter.Flush() here: https://github.com/dunglas/frankenphp/blob/main/frankenphp.c#L486

[withinboredom]

I agree, but I don't think that's it. This also seems to affect headers_send as they won't actually send until the buffer is full (4k), which entirely negates the point.

header('Content-Type: ' . $content_type);
headers_send(200);

for ($i = 0; $i < (1024 * 4 - strlen("\nwait1")); $i++) {
    echo ' ';
}
echo "\nwait1";
flush();
sleep(2);
echo "\nwait2";
flush();
sleep(2);
echo "\nfinish\n";
sleep(2);

and I've been experimenting with various content types based on caddy's docs (event-stream, etc).

[dunglas]

Maybe could we start by adding a test in the library to check if it's related to Caddy or not. If it is we'll ask the Caddy maintainers if they have a clue about what's going on. WDYT?

[withinboredom]

Looks like its in golang itself ... been tracing it all the way down. So much fun! (barely sarcastic, I learned a lot!)

From the docs:

// WriteBufferSize specifies the size of the write buffer used
// when writing to the transport.
// If zero, a default (currently 4KB) is used.
WriteBufferSize [int](https://pkg.go.dev/builtin#int)

From: https://pkg.go.dev/net/http

I guess the smallest buffer you can have is 1 byte... I'm trying to work out how fastcgi module handles this and learning all about Go interfaces along the way. I will probably have a PR for you in the next couple of days to make an extra configuration for the frankenphp module to set this variable. Caddy doesn't really expose this natively.

[withinboredom]

Just in case anyone is curious why the 200 header isn't sent early in the above code:

From the documentation in the Go codebase:

    // WriteHeader sends an HTTP response header with the provided
    // status code.
    //
    // If WriteHeader is not called explicitly, the first call to Write
    // will trigger an implicit WriteHeader(http.StatusOK).
    // Thus explicit calls to WriteHeader are mainly used to
    // send error codes or 1xx informational responses.
    //
    // The provided code must be a valid HTTP 1xx-5xx status code.
    // Any number of 1xx headers may be written, followed by at most
    // one 2xx-5xx header. 1xx headers are sent immediately, but 2xx-5xx
    // headers may be buffered. Use the Flusher interface to send
    // buffered data. The header map is cleared when 2xx-5xx headers are
    // sent, but not with 1xx headers.
    //
    // The server will automatically send a 100 (Continue) header
    // on the first read from the request body if the request has
    // an "Expect: 100-continue" header.

Thus only 1xx headers may trigger an early send of headers. 200->5xx will not send headers. 1xx headers in the above code, do, in fact, send the headers.

[dunglas]

Calling explicitly responseWriter.WriteHeader(200) should immediately flush the headers (I'm pretty sure of that, as I've done it in Mercure).

Buffering the headers before sending the status code looks intended and correct to me. By the spec, clients should not use the headers before they have all been received (because a header can overwrite a previous one in some cases).

Calling WriteHeader() (if headers aren't already sent), or Flush() otherwise in the flush hook should do what's expected by most users.

[withinboredom]

or Flush() otherwise in the flush hook should do what's expected by most users.

That's a good point and I'll look into that vs. trying to create a whole new thing.

Calling explicitly responseWriter.WriteHeader(200) should immediately flush the headers (I'm pretty sure of that, as I've done it in Mercure).

Def isn't happening (as per docs):

code:

<?php

ini_set('output_buffering', '0');

header('Content-Type: text/plain');
headers_send(200);

sleep(5);

echo "hello world\n";

die();

output:

$> curl -k https://localhost -v
*   Trying 127.0.0.1:443...
* Connected to localhost (127.0.0.1) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* TLSv1.0 (OUT), TLS header, Certificate Status (22):
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS header, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS header, Finished (20):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.2 (OUT), TLS header, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: [NONE]
*  start date: Nov  7 21:20:20 2022 GMT
*  expire date: Nov  8 09:20:20 2022 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Using HTTP2, server supports multiplexing
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* Using Stream ID: 1 (easy handle 0x562661c4de80)
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
> GET / HTTP/2
> Host: localhost
> user-agent: curl/7.81.0
> accept: */*
>
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
SLEEPING
SLEEPING
SLEEPING
SLEEPING
SLEEPING
SLEEPING
SLEEPING
* TLSv1.2 (IN), TLS header, Supplemental data (23):
< HTTP/2 200
< alt-svc: h3=":443"; ma=2592000
< content-type: text/plain;charset=UTF-8
< server: Caddy
< x-powered-by: PHP/8.2.0RC5
< content-length: 12
< date: Mon, 07 Nov 2022 22:21:49 GMT
<
* TLSv1.2 (IN), TLS header, Supplemental data (23):
hello world
* Connection #0 to host localhost left intact

[withinboredom]

A 1xx status does immediately send however:

$> curl -k https://localhost -v
*   Trying 127.0.0.1:443...
* Connected to localhost (127.0.0.1) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* TLSv1.0 (OUT), TLS header, Certificate Status (22):
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS header, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS header, Finished (20):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.2 (OUT), TLS header, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: [NONE]
*  start date: Nov  7 21:20:20 2022 GMT
*  expire date: Nov  8 09:20:20 2022 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Using HTTP2, server supports multiplexing
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* Using Stream ID: 1 (easy handle 0x55ca5decce80)
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
> GET / HTTP/2
> Host: localhost
> user-agent: curl/7.81.0
> accept: */*
>
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
< HTTP/2 100
< alt-svc: h3=":443"; ma=2592000
< content-type: text/plain;charset=UTF-8
< server: Caddy
< x-powered-by: PHP/8.2.0RC5
SLEEPING
SLEEPING
SLEEPING
SLEEPING
SLEEPING
SLEEPING
SLEEPING
* TLSv1.2 (IN), TLS header, Supplemental data (23):
< HTTP/2 200
< content-type: text/plain;charset=UTF-8
< x-powered-by: PHP/8.2.0RC5
< content-length: 12
< date: Mon, 07 Nov 2022 22:25:15 GMT
<
* TLSv1.2 (IN), TLS header, Supplemental data (23):
hello world
* Connection #0 to host localhost left intact

[dunglas]

I confirm that this works as expected: https://github.com/dunglas/frankenphp/pull/90

[withinboredom]

For anyone coming along later after #90 is merged and wondering why it still isn't working, check your php.ini file for output_buffering or try ini_set('output_buffering', 'Off') (but note that it must be set before anything is output!).