Caddy Crashing Due To Nil Pointer Dereference #5347

Rishi556 · 2023-01-31T00:43:15Z

On a production server, getting the following error:

an 31 00:24:41 Dw-Haproxy caddy[2568599]: panic: runtime error: invalid memory address or nil pointer dereference
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x5651f2]
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: goroutine 907455 [running]:
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: bufio.(*Writer).Available(...)
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]:         bufio/bufio.go:646
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: bufio.(*Writer).Write(0x0, {0x2a11ac0?, 0xc006e4b880?, 0xc00a8516ab?})
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]:         bufio/bufio.go:664 +0x52
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: net/http.(*response).WriteHeader(0xc00a8515e0, 0x64)
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]:         net/http/server.go:1165 +0x20e
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.(*Handler).reverseProxy.func1(0xc00490ee40?, 0xc008249b00?)
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]:         github.com/caddyserver/caddy/v2@v2.6.2/modules/caddyhttp/reverseproxy/reverseproxy.go:783 +0x6f
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: net/http.(*persistConn).readResponse(0xc00a0a6120, {{}, 0xc008249b00, {0xc008249a00}, 0xc0096cd020, 0x0, 0xc0096ccf60, 0xc0096ccfc0}, 0xc008155880)
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]:         net/http/transport.go:2313 +0x20c
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: net/http.(*persistConn).readLoop(0xc00a0a6120)
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]:         net/http/transport.go:2108 +0x3aa
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]: created by net/http.(*Transport).dialConn
Jan 31 00:24:41 Dw-Haproxy caddy[2568599]:         net/http/transport.go:1751 +0x173e
Jan 31 00:24:41 Dw-Haproxy systemd[1]: caddy.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Jan 31 00:24:41 Dw-Haproxy systemd[1]: caddy.service: Failed with result 'exit-code'.

The config being used is:

sub.domain.tld {
        reverse_proxy localhost:8080 {
                #header_up X-Forwarded-For {header.Cf-Connecting-Ip} 
       }

        route /stats {
                reverse_proxy localhost:2087
        }

        handle_path /hidden/* {
                reverse_proxy 0.0.0.0:3000
        }
}

sub2.domain.tld {
        reverse_proxy localhost:8080
        route /stats {
                reverse_proxy localhost:2087
        }
}

The reverse_proxy 0.0.0.0:3000 part uses a different ip, and was replaced for 0.0.0.0 while sharing to hide sensitive info.

This has worked without issues for multiple months until today when crashes started. A simple restart fixes the issue and gets the application working.

➜  ~ caddy version
v2.6.2 h1:wKoFIxpmOJLGl3QXoo6PNbYvGW4xLEgo32GPBEjWL8o=

The text was updated successfully, but these errors were encountered:

francislavoie · 2023-01-31T00:56:40Z

Hmm... it looks like happened within a relatively new piece of code which handles 1xx status codes, specifically to handle 103 Early Hints.

caddy/modules/caddyhttp/reverseproxy/reverseproxy.go

Lines 777 to 795 in 6bad878

    
           if supports1xx { 
        
           	// Forward 1xx status codes, backported from https://github.com/golang/go/pull/53164 
        
           	trace := &httptrace.ClientTrace{ 
        
           		Got1xxResponse: func(code int, header textproto.MIMEHeader) error { 
        
           			h := rw.Header() 
        
           			copyHeader(h, http.Header(header)) 
        
           			rw.WriteHeader(code) 
        
           			// Clear headers coming from the backend 
        
           			// (it's not automatically done by ResponseWriter.WriteHeader() for 1xx responses) 
        
           			for k := range header { 
        
           				delete(h, k) 
        
           			} 
        
           			return nil 
        
           		}, 
        
           	} 
        
           	req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace)) 
        
           }

@dunglas do you have any clues as to the issue?

@Rishi556 do you know whether your backends might be using 103 Early Hints? Is it something you could try to replicate?

Rishi556 · 2023-01-31T01:08:08Z

The backend is a haproxy 2.6.8 server(updated to 2.7.2 about 5 minutes ago) which points to a few stateless JSONRPC2 servers, and I don't think those support early hints. The only part that might have early hints configured is the /stats endpoint which leads to the haproxy stats page. I'm checking there to see if early hints is used anywhere.

mholt · 2023-01-31T02:37:20Z

Bizarre:

https://cs.opensource.google/go/go/+/refs/tags/go1.19.5:src/net/http/server.go;l=1165

and

https://cs.opensource.google/go/go/+/refs/tags/go1.19.5:src/bufio/bufio.go;l=645;drc=007d8f4db1f890f0d34018bb418bdc90ad4a8c35

Like the buffer of the connection is nil? How is that even possible?

Maybe it's a bug in our code, but I wonder if there could be a very unlikely bug in Go std lib.

Rishi556 · 2023-01-31T03:08:01Z

I've enabled request logging and once I see another crash, I'll pass the logs back here.

WeidiDeng · 2023-02-03T07:25:00Z

From the log it appears to be a bug with stdlib. Maybe a corner case in net/http/transport

WeidiDeng · 2023-02-03T07:34:50Z

I remember once I also encountered this bug, that's about at least 2 years before. Way before 103 is introduced.

WeidiDeng · 2023-02-03T07:48:32Z

@Rishi556 Does your backend involve websockets?

Rishi556 · 2023-02-05T04:20:47Z

The backend does have support for websockets, but I verified that they are disabled. Doesn't stop a client from attempting to connect via them though. I made a few connection attempts and they didn't cause any crashes. There also has been no crashes after this issue was created.

dunglas · 2023-06-02T12:05:41Z

We also (very rarely) encounter this issue with Mercure (Websocket is not used), here is the detailed stack trace:

2023-06-01T15:29:59.035Z	panic: runtime error: invalid memory address or nil pointer dereference
2023-06-01T15:29:59.035Z	[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x6a6298]
2023-06-01T15:29:59.035Z	goroutine 170071 [running]:
2023-06-01T15:29:59.035Z	bufio.(*Writer).Flush(0xc0071bb0a0?)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/bufio/bufio.go:622 +0x18
2023-06-01T15:29:59.035Z	net/http.(*chunkWriter).flush(0x1e9dfc0?)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/net/http/server.go:402 +0x3f
2023-06-01T15:29:59.035Z	net/http.(*response).FlushError(0xc00057fb20)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/net/http/server.go:1707 +0x55
2023-06-01T15:29:59.035Z	net/http.(*response).Flush(0xc007f65720?)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/net/http/server.go:1699 +0x19
2023-06-01T15:29:59.035Z	github.com/caddyserver/caddy/v2/modules/caddyhttp.(*ResponseWriterWrapper).Flush(...)
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/caddyserver/caddy/v2@v2.6.4/modules/caddyhttp/responsewriter.go:51
2023-06-01T15:29:59.035Z	github.com/caddyserver/caddy/v2/modules/caddyhttp/encode.(*responseWriter).Flush(0x7f9520869850?)
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/caddyserver/caddy/v2@v2.6.4/modules/caddyhttp/encode/encode.go:212 +0x27
2023-06-01T15:29:59.035Z	github.com/dunglas/mercure.(*Hub).write.func1()
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/dunglas/mercure@v0.14.8/subscribe.go:211 +0x90
2023-06-01T15:29:59.035Z	created by github.com/dunglas/mercure.(*Hub).write
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/dunglas/mercure@v0.14.8/subscribe.go:209 +0x158

The error we get is the same #3713 (so it looks like the bug is not related to 103 Early Hints).

WeidiDeng · 2023-06-02T13:43:56Z

We also (very rarely) encounter this issue with Mercure (Websocket is not used), here is the detailed stack trace:

2023-06-01T15:29:59.035Z	panic: runtime error: invalid memory address or nil pointer dereference
2023-06-01T15:29:59.035Z	[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x6a6298]
2023-06-01T15:29:59.035Z	goroutine 170071 [running]:
2023-06-01T15:29:59.035Z	bufio.(*Writer).Flush(0xc0071bb0a0?)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/bufio/bufio.go:622 +0x18
2023-06-01T15:29:59.035Z	net/http.(*chunkWriter).flush(0x1e9dfc0?)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/net/http/server.go:402 +0x3f
2023-06-01T15:29:59.035Z	net/http.(*response).FlushError(0xc00057fb20)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/net/http/server.go:1707 +0x55
2023-06-01T15:29:59.035Z	net/http.(*response).Flush(0xc007f65720?)
2023-06-01T15:29:59.035Z	/opt/homebrew/Cellar/go/1.20.4/libexec/src/net/http/server.go:1699 +0x19
2023-06-01T15:29:59.035Z	github.com/caddyserver/caddy/v2/modules/caddyhttp.(*ResponseWriterWrapper).Flush(...)
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/caddyserver/caddy/v2@v2.6.4/modules/caddyhttp/responsewriter.go:51
2023-06-01T15:29:59.035Z	github.com/caddyserver/caddy/v2/modules/caddyhttp/encode.(*responseWriter).Flush(0x7f9520869850?)
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/caddyserver/caddy/v2@v2.6.4/modules/caddyhttp/encode/encode.go:212 +0x27
2023-06-01T15:29:59.035Z	github.com/dunglas/mercure.(*Hub).write.func1()
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/dunglas/mercure@v0.14.8/subscribe.go:211 +0x90
2023-06-01T15:29:59.035Z	created by github.com/dunglas/mercure.(*Hub).write
2023-06-01T15:29:59.035Z	/Users/dunglas/go/pkg/mod/github.com/dunglas/mercure@v0.14.8/subscribe.go:209 +0x158

The error we get is the same #3713 (so it looks like the bug is not related to 103 Early Hints).

It appears from the stack trace it's a problem with Mercure plug-in. Using a response writer after its handler already returned. I'm not using a computer now so I can't say for sure.

WeidiDeng · 2023-06-03T10:10:14Z

@dunglas I created a patch for your plugin. That issues doesn't have anything to with the error this issue described.

dunglas · 2023-06-03T22:46:20Z

Thank you very much, and sorry for the false report.

Rishi556 · 2023-06-03T22:48:07Z

Just an update from my side, it hadn’t crashed again since I’ve enabled request logging. Still waiting to see if it will though.

mholt · 2023-06-04T01:29:27Z

@WeidiDeng You're awesome. Thank you so much for doing that. @dunglas You rock too, we're glad for your contributions to the community!!

mholt · 2023-08-04T16:52:46Z

I assume this is working alright now with the patch upstream, so I'll close this. Thanks everyone!

francislavoie added the needs info 📭 Requires more information label Jan 31, 2023

mholt added bug 🐞 Something isn't working help wanted 🆘 Extra attention is needed labels Jan 31, 2023

WeidiDeng added the upstream ⬆️ Relates to some dependency of this project label Feb 3, 2023

mholt changed the title ~~Caddy Crashing Due To Memory Issue~~ Caddy Crashing Due To Nil Pointer Dereference Jun 2, 2023

WeidiDeng mentioned this issue Jun 3, 2023

fix: wait for dispatch goroutine to finish dunglas/mercure#780

Merged

mholt closed this as completed Aug 4, 2023

mholt removed help wanted 🆘 Extra attention is needed needs info 📭 Requires more information labels Aug 4, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Caddy Crashing Due To Nil Pointer Dereference #5347

Caddy Crashing Due To Nil Pointer Dereference #5347

Rishi556 commented Jan 31, 2023 •

edited

francislavoie commented Jan 31, 2023 •

edited

Rishi556 commented Jan 31, 2023

mholt commented Jan 31, 2023

Rishi556 commented Jan 31, 2023

WeidiDeng commented Feb 3, 2023

WeidiDeng commented Feb 3, 2023

WeidiDeng commented Feb 3, 2023

Rishi556 commented Feb 5, 2023

dunglas commented Jun 2, 2023 •

edited

WeidiDeng commented Jun 2, 2023

WeidiDeng commented Jun 3, 2023

dunglas commented Jun 3, 2023

Rishi556 commented Jun 3, 2023

mholt commented Jun 4, 2023

mholt commented Aug 4, 2023 •

edited

Caddy Crashing Due To Nil Pointer Dereference #5347

Caddy Crashing Due To Nil Pointer Dereference #5347

Comments

Rishi556 commented Jan 31, 2023 • edited

francislavoie commented Jan 31, 2023 • edited

Rishi556 commented Jan 31, 2023

mholt commented Jan 31, 2023

Rishi556 commented Jan 31, 2023

WeidiDeng commented Feb 3, 2023

WeidiDeng commented Feb 3, 2023

WeidiDeng commented Feb 3, 2023

Rishi556 commented Feb 5, 2023

dunglas commented Jun 2, 2023 • edited

WeidiDeng commented Jun 2, 2023

WeidiDeng commented Jun 3, 2023

dunglas commented Jun 3, 2023

Rishi556 commented Jun 3, 2023

mholt commented Jun 4, 2023

mholt commented Aug 4, 2023 • edited

Rishi556 commented Jan 31, 2023 •

edited

francislavoie commented Jan 31, 2023 •

edited

dunglas commented Jun 2, 2023 •

edited

mholt commented Aug 4, 2023 •

edited