Errors due to fast http client limited buffer not propagated to web UI, only showing in server logs

[spaskalev]

fortio server

then in ui trigger test against http://localhost:8080/echo?size=200000 - eg http://localhost:8080/fortio/?url=http%3A%2F%2Flocalhost%3A8080%2Fecho%3Fsize%3D200000&qps=10&t=3s&load=Start
shows

Code  -1 : 16 (66.7 %)
Code 200 : 8 (33.3 %)

and in the server logs the actual problem:

13:47:00 W http_client.go:960> [7] Buffer is too small for headers 120 + data 200000 - change -httpbufferkb flag to at least 196

these aren't bubbled up to the ui/visible

-----edited, was ----
Running fortio server and then running a load test against itself using
{ "url": "http://localhost:8080/?size=131072:50,65536:25,32768:25", "qps": "100", "t": "10s", "p": "50, 95, 99", "jitter": "on", "uniform": "on", "nocatchup": "on", "stdclient": "on" }
works properly.

When I remove the stdclient and switch to the fast one about one third of the requests fail with 'broken pipe' while writing the response.

[ldemailly]

which version? can you give exact repro steps?

[ldemailly]

I can reproduce the problem, which is due to asking for large payload:

$ fortio load -qps 100 -t 10s  "http://localhost:8080/?size=131072:50,65536:25,32768:25" 
Fortio 1.34.1 running at 100 queries per second, 10->10 procs, for 10s: http://localhost:8080/?size=131072:50,65536:25,32768:25
14:45:56 I httprunner.go:98> Starting http test for http://localhost:8080/?size=131072:50,65536:25,32768:25 with 4 threads at 100.0 qps and parallel warmup
14:45:56 W http_client.go:960> [2] Buffer is too small for headers 120 + data 131072 - change -httpbufferkb flag to at least 129
14:45:56 W http_client.go:960> [3] Buffer is too small for headers 120 + data 131072 - change -httpbufferkb flag to at least 129
Starting at 100 qps with 4 thread(s) [gomax 10] for 10s : 250 calls each (total 1000)
14:45:56 W http_client.go:889> [3] Non ok http code -1 ('?+S???/vQ۸)
[...]

The fix is easy though, it's to read the error and pass/change -httpbufferkb

$ fortio load -httpbufferkb 192 -qps 100 -t 10s  "http://localhost:8080/?size=131072:50,65536:25,32768:25" 
Fortio 1.34.1 running at 100 queries per second, 10->10 procs, for 10s: http://localhost:8080/?size=131072:50,65536:25,32768:25
14:46:34 I httprunner.go:98> Starting http test for http://localhost:8080/?size=131072:50,65536:25,32768:25 with 4 threads at 100.0 qps and parallel warmup
Starting at 100 qps with 4 thread(s) [gomax 10] for 10s : 250 calls each (total 1000)
14:46:44 I periodic.go:721> T001 ended after 10.002114167s : 250 calls. qps=24.994715699689333
14:46:44 I periodic.go:721> T000 ended after 10.002388042s : 250 calls. qps=24.99403132034577
14:46:44 I periodic.go:721> T003 ended after 10.002448959s : 250 calls. qps=24.99387910148295
14:46:44 I periodic.go:721> T002 ended after 10.002479625s : 250 calls. qps=24.99380247425398
Ended after 10.002586584s : 1000 calls. qps=99.974
Sleep times : count 996 avg 0.037823976 +/- 0.0007004 min 0.03323614 max 0.039898933 sum 37.6726799
Aggregated Function Time : count 1000 avg 0.0010143274 +/- 0.000419 min 0.000240166 max 0.005203125 sum 1.01432737
# range, mid point, percentile, count
>= 0.000240166 <= 0.001 , 0.000620083 , 56.00, 560
> 0.001 <= 0.002 , 0.0015 , 97.20, 412
> 0.002 <= 0.003 , 0.0025 , 99.80, 26
> 0.004 <= 0.005 , 0.0045 , 99.90, 1
> 0.005 <= 0.00520313 , 0.00510156 , 100.00, 1
# target 50% 0.000918444
# target 75% 0.00146117
# target 90% 0.00182524
# target 99% 0.00269231
# target 99.9% 0.005
Error cases : no data
14:46:44 I httprunner.go:197> [0]   1 socket used, resolved to 127.0.0.1:8080
14:46:44 I httprunner.go:197> [1]   1 socket used, resolved to 127.0.0.1:8080
14:46:44 I httprunner.go:197> [2]   1 socket used, resolved to 127.0.0.1:8080
14:46:44 I httprunner.go:197> [3]   1 socket used, resolved to 127.0.0.1:8080
Sockets used: 4 (for perfect keepalive, would be 4)
Uniform: false, Jitter: false
IP addresses distribution:
127.0.0.1:8080: 4
Code 200 : 1000 (100.0 %)
Response Header Sizes : count 1000 avg 119.477 +/- 0.4995 min 119 max 120 sum 119477
Response Body/Total Sizes : count 1000 avg 87773.877 +/- 4.312e+04 min 32887 max 131192 sum 87773877
All done 1000 calls (plus 4 warmup) 1.014 ms avg, 100.0 qps

Reopen if that's not answering your question

[spaskalev]

Thanks. This works for CLI runs but I can't find an option for setting the buffer in an API run / restHandler.go

[spaskalev]

And it seems that due to github's policy on opening/closing issues I can't reopen this one since it's marked as closed by a different account.

[ldemailly]

can't find an option for setting the buffer in an API

it's a global option that should work for fortio server invocation - I can confirm or you can confirm if it doesn't take effect that'd be a bug indeed

[ldemailly]

this being said we could also make it be a param for rest api - though the idea here was to limit resources consumption on the client/server

[spaskalev]

My deployment setup for fortio was running servers at two sites and then using the load test to measure the link's behavior across them from both sides. It served a great job for this.

I would vouch for making it a parameter to the rest ui and exposing it to the UI with a note as well - I would have probably figured it out if it was stated in the UI as a requirement for the fast http. OTOH, my applications that are going to be using the link are more likely to be using the standard golang client (and other languages) clients so the fast one wasn't a blocker for me - just a surprise that it was failing.

[ldemailly]

I confirmed it works if you pass -httpbufferkb 200 to the server before starting it

what I think is suboptimal here is the error only shows on the server logs not in the UI, making the configuration error harder to discover than it should

[ldemailly]

updated the description