Hi, I noticed that fortio reports l

I simplified the bad server code to: <div class="highlight highlight-source-go not

Improve error message for non compliant http servers missing \r\n (was Read error reported by fortio, but not curl/wrk) about fortio HOT 7 CLOSED

lbrndnr commented on May 27, 2024

Improve error message for non compliant http servers missing \r\n (was Read error reported by fortio, but not curl/wrk)

from fortio.

Comments (7)

ldemailly commented on May 27, 2024

Thanks, interesting, will try - can you check whether you get the same behavior with and without -stdclient ?

from fortio.

ldemailly commented on May 27, 2024

well reading the code of the server: one issue is your server isn't http protocol compliant:

"Server: webserver-c\n"

should be \r\n for headers

but looks like curl is lenient about that, let me see if I can make fortio just warn about it

from fortio.

lbrndnr commented on May 27, 2024

You're right, that actually fixes it! -stdclient also makes it work!

from fortio.

lbrndnr commented on May 27, 2024

Interestingly, when running with -stdclient and multiple requests -n 10, I get the following warning:

$ fortio load -n 10 -c 1 -stdclient http://127.0.0.1:3000/hi
16:47:26.071 r1 [INF] scli.go:125> Starting, command="Φορτίο", version="1.63.5 h1:XUxnT4F1vJ1EXLFAn0AYwseH0UUhr+Ti1+4REJo/faI= go1.21.5 amd64 linux", go-max-procs=8
Fortio 1.63.5 running at 8 queries per second, 8->8 procs, for 10 calls: http://127.0.0.1:3000/hi
16:47:26.072 r1 [INF] httprunner.go:121> Starting http test, run=0, url="http://127.0.0.1:3000/hi", threads=1, qps="8.0", warmup="parallel", conn-reuse=""
Starting at 8 qps with 1 thread(s) [gomax 8] : exactly 10, 10 calls each (total 10 + 0)
16:47:26.073 r34 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:26.212 r21 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:26.352 r38 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:26.490 r52 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:26.628 r42 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:26.768 r56 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:26.906 r46 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:27.046 r60 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:27.184 r62 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:27.323 r66 [WRN]> Unsolicited response received on idle HTTP channel starting with "\n"; err=<nil>, src="std"
16:47:27.323 r1 [INF] periodic.go:851> T000 ended after 1.251544663s : 10 calls. qps=7.990126357959628
Ended after 1.251628023s : 10 calls. qps=7.9896
16:47:27.323 r1 [INF] periodic.go:581> Run ended, run=0, elapsed=1251628023, calls=10, qps=7.989594205498227
Sleep times : count 9 avg 0.13722148 +/- 0.0003369 min 0.136759027 max 0.137654485 sum 1.23499336
Aggregated Function Time : count 10 avg 0.0011052665 +/- 0.0001827 min 0.00082008 max 0.001457551 sum 0.011052665
# range, mid point, percentile, count
>= 0.00082008 <= 0.001 , 0.00091004 , 20.00, 2
> 0.001 <= 0.00145755 , 0.00122878 , 100.00, 8
# target 50% 0.00117158
# target 75% 0.00131457
# target 90% 0.00140036
# target 99% 0.00145183
# target 99.9% 0.00145698
Error cases : no data
# Socket and IP used for each connection:
[0]  10 socket used, resolved to 127.0.0.1:3000, connection timing : count 10 avg 0.0003587242 +/- 8.997e-05 min 0.00021883 max 0.00058076 sum 0.003587242
Connection time histogram (s) : count 10 avg 0.0003587242 +/- 8.997e-05 min 0.00021883 max 0.00058076 sum 0.003587242
# range, mid point, percentile, count
>= 0.00021883 <= 0.00058076 , 0.000399795 , 100.00, 10
# target 50% 0.000379688
# target 75% 0.000480224
# target 90% 0.000540546
# target 99% 0.000576739
# target 99.9% 0.000580358
Sockets used: 10 (for perfect keepalive, would be 1)
Uniform: false, Jitter: false, Catchup allowed: true
IP addresses distribution:
127.0.0.1:3000: 10
Code 200 : 10 (100.0 %)
Response Header Sizes : count 10 avg 0 +/- 0 min 0 max 0 sum 0
Response Body/Total Sizes : count 10 avg 26 +/- 0 min 26 max 26 sum 260
All done 10 calls (plus 0 warmup) 1.105 ms avg, 8.0 qps

This does not happen when leaving -stdclient out.

from fortio.

ldemailly commented on May 27, 2024

I simplified the bad server code to:

package main

import (
	"fmt"
	"log"
	"net"
	"os"
)

const maxNumConn = 1000

func main() {
	if len(os.Args) < 2 {
		fmt.Fprintf(os.Stderr, "Usage: %s <listen:port>\n", os.Args[0])
		os.Exit(1)
	}

	laddr, err := net.ResolveTCPAddr("tcp", os.Args[1])
	if err != nil {
		log.Fatalf("Failed to resolve address: %v", err)
	}

	listener, err := net.ListenTCP("tcp", laddr)
	if err != nil {
		log.Fatalf("Failed to listen on %s: %v", laddr, err)
	}
	defer listener.Close()

	fmt.Printf("Listening on %s\n", listener.Addr())

	for {
		conn, err := listener.AcceptTCP()
		if err != nil {
			log.Printf("Failed to accept connection: %v", err)
			continue
		}

		fmt.Printf("New connection accepted: %s\n", conn.RemoteAddr())

		go handleConnection(conn)
	}
}

func handleConnection(conn *net.TCPConn) {
	defer conn.Close()
	buf := make([]byte, 1024)
	for {
		read, err := conn.Read(buf)
		if err != nil {
			log.Printf("Error reading from connection: %v", err)
			return
		}
		fmt.Printf("Received request: %s\n", string(buf[:read]))

		// \r missing on purpose
		response := "HTTP/1.1 200 OK\n" +
			"Server: webserver-go\n" +
			"Content-Length: 26\n" +
			"Content-type: text/html\n\n" +
			"<html>hello, world</html>\n"

		n, err := conn.Write([]byte(response))
		if err != nil {
			log.Printf("Error sending response: %v", err)
			return
		}
		fmt.Printf("Response sent %d bytes\n", n)
	}
}

with which the error reproduces, including explanation when in debug logging:

$ fortio curl -loglevel debug http://localhost:3000/foo
[...]
10:01:00.407 [DBG] [0] Read ok 107 total 107 so far (-0 headers = 107 data) HTTP/1.1 200 OK\nServer: webserver-go\nContent-Length: 26\nContent-type: text/html\n\n<html>hello, world</html>\n
10:01:00.407 [DBG] [0] Code 200, looking for end of headers at 12 / 107, last CRLF 0
10:01:03.409 [ERR] Read error, err={"Op":"read","Net":"tcp","Source":{"IP":"127.0.0.1","Port":59061,"Zone":""},"Addr":{"IP":"127.0.0.1","Port":3000,"Zone":""},"Err":{}}, size=107, dest={"IP":"127.0.0.1","Port":3000,"Zone":""}, url="http://localhost:3000/foo", thread=0, run=0

the key there is looking for end of headers last CRLF 0

which could be in the error printout

from fortio.

lbrndnr commented on May 27, 2024

Thanks for the quick fix! I have also noticed that fortio fails to reuse an open socket, something that wrk, curl and k6 seem to get right. I will come back to you if I can reproduce the problem.

from fortio.

ldemailly commented on May 27, 2024

fortio does reuse sockets unless you tell it not to or the server closes them.

I'd like to see the output when/if it does. It does tell you the exact number of sockets used at the end

from fortio.

Improve error message for non compliant http servers missing \r\n (was Read error reported by fortio, but not curl/wrk) about fortio HOT 7 CLOSED

Comments (7)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent