Uncomplete strange panic message

[koteesy]

Sometimes, randomly, our go GRPC application crash, and at this point we not understand why.

Full error

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x54 pc=0x6c335c]

goroutine 226092 [running]:
net/http/httptrace.ContextClientTrace(...)
	/usr/local/go/src/net/http/httptrace/trace.go:25
net/http.(*Request).write(0xc00053f560, 0xe541c0, 0xc0000401c0, 0x1, 0xc000dda090, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/request.go:548 +0x5c
net/http.(*persistConn).writeLoop(0xc0014766c0)
	/usr/local/go/src/net/http/transport.go:2385 +0x1a7
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1744 +0xc9c

That's all...No stack trace, no any additional information from where it was called, nothing,
application can work hour, 30 minutes, or 10 minutes and then just got panic and crash

What version of Go are you using (go version)?

$ go version go1.16 linux/amd64

What operating system and processor architecture are you using (go env)?

go env

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/root/work/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/root/work"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.16"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/var/www/test-api/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1064844775=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Our api work as grpc microservice, which accept incoming request and parse some websites by passed rules.

Main code, which do http requests, I left only the main piece of code, because the other methods like AddHeadersToRequest, AddPreviousHeaders, do not carry any serious logic and only add headers to the request.

request.go

// Client
func getClient() *http.Client {
	proxyUrl, err := url.Parse("proxy url here")

	if err != nil {
		log.Fatal("Proxy error", err.Error())
	}

	return &http.Client{
		Timeout: time.Second * 60,
		Transport: &http.Transport{
			TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
			Proxy: http.ProxyURL(proxyUrl),
	}}
}

// generateClientRequest func
func generateClientRequest(ctx context.Context, method string, s string, body *strings.Reader) (*http.Request, error) {
	if body == nil {
		return http.NewRequestWithContext(ctx, method, s, nil)
	}

	return http.NewRequestWithContext(ctx, method, s, body)
}

// Main code. HttpRequest func
func (r *Rule) HTMLRequest(args *Args, values *ValueArguments) {
  iterate := args.Iteration(r)

  defer iterate.IsStarted()()
  
  var options Request

  unmarshalError := json.Unmarshal(r.Data.Value, &options)
  
  if unmarshalError != nil {
  iterate.RegisterError(unmarshalError)
  
  return
  }

  ctx, cancel := context.WithTimeout(context.Background(), getTimeoutForService(r.Service.Timeout))
  
  defer cancel()
  
  endpoint := values.ReplaceStringFromVariables(r.Value)
  
  req, reqError := generateClientRequest(ctx, options.Method, endpoint, options.GetBody(values))
  
  if reqError != nil {
  iterate.RegisterError(reqError)
  
  setSystemStatus(args, r, "error")
  
  return
  }
  
  // Fix increasing socket connections.
  req.Close = true
  
  options.AddHeadersToRequest(req, values)
  
  options.AddPreviousHeaders(req, values)
  
  if req == nil {
  log.Fatal("Request is nil...", values.Value, args.Data())
  }
  
  if cl == nil {
  log.Fatal("Client is nil...", values.Value, args.Data())
  }
  
  resp, doError := cl.Do(req)
  
  if resp != nil {
  defer func() {
  err := resp.Body.Close()
  
  if err != nil {
	  iterate.RegisterError(err)
  
	  setSystemStatus(args, r, "error")
  
	  fmt.Printf("Defer[336]: %s\n", err.Error())
  }
  }()
  }
  
  if doError != nil {
  fmt.Println("Error here", doError.Error())
  
  iterate.RegisterError(doError)
  
  setSystemStatus(args, r, "error")
  
  return
  }
  
  // Oops, we have nil response, that mean we need stop here.
  if resp == nil {
  fmt.Println("Response is nil", endpoint)
  
  iterate.RegisterError(errors.New("response is nil for" + endpoint))
  
  setSystemStatus(args, r, "error")
  
  return
  }
  
  stringStatusCode := fmt.Sprintf("%d", resp.StatusCode)
  
  ok := setResponseStatus(r, args, stringStatusCode)
  
  if !ok {
  return
  }
  
  utf8, readerError := charset.NewReader(resp.Body, resp.Header.Get("Content-Type"))
  
  if readerError != nil {
  iterate.RegisterError(readerError)
  
  setSystemStatus(args, r, "error")
  
  return
  }
  
  bts, readError := ioutil.ReadAll(utf8)
  
  if readError != nil {
  iterate.RegisterError(readError)
  
  setSystemStatus(args, r, "error")
  
  return
  }
}

Almost everywhere i put defer with recover function for get all info what i can, but in panic log's i newer seen what he executed, and didn't see panic messages in sentry, i call it like that:

SentryRecover

func SentryRecover(data interface{}) func() {
	return func() {
		err := recover()

		if err != nil {
			fmt.Println(err)
			fmt.Println(string(debug.Stack()))
			fmt.Println(data)

			sentry.WithScope(func(scope *sentry.Scope) {
				scope.SetExtra("Details", data)
				sentry.CurrentHub().Recover(err)
			})
		}
	}
}

defer helpers.SentryRecover(map[string]string{
	"type":    "MainCaller",
	"value":   arguments.Value,
})()

What did you expect to see?

At least more information log, with stack trace, so that I could understand where this error starts from

What did you see instead?

Panic, and strange error without any additional information

[cherrymui]

goroutine 226092 [running]:
net/http/httptrace.ContextClientTrace(...)
	/usr/local/go/src/net/http/httptrace/trace.go:25
net/http.(*Request).write(0xc00053f560, 0xe541c0, 0xc0000401c0, 0x1, 0xc000dda090, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/request.go:548 +0x5c
net/http.(*persistConn).writeLoop(0xc0014766c0)
	/usr/local/go/src/net/http/transport.go:2385 +0x1a7
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1744 +0xc9c

This is the stack trace. It shows which function panics, at which line. What other additional information would you expect? Thanks.

[koteesy]

goroutine 226092 [running]:
net/http/httptrace.ContextClientTrace(...)
	/usr/local/go/src/net/http/httptrace/trace.go:25
net/http.(*Request).write(0xc00053f560, 0xe541c0, 0xc0000401c0, 0x1, 0xc000dda090, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/request.go:548 +0x5c
net/http.(*persistConn).writeLoop(0xc0014766c0)
	/usr/local/go/src/net/http/transport.go:2385 +0x1a7
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1744 +0xc9c

This is the stack trace. It shows which function panics, at which line. What other additional information would you expect? Thanks.

When my app crash previously, or if i just panic in some function manually, i will see which function and where exactly crash, i mean my functions, for example, if i put nil value to function which are not allow nil in middle logic of our script, i will see something like that:

Here i can see all what i need for debug. The first function which calling when request income, the second, etc...

runtime error: invalid memory address or nil pointer dereference
goroutine 46 [running]:
runtime/debug.Stack(0xe55f00, 0xc000010018, 0xc000b47428)
/usr/local/go/src/runtime/debug/stack.go:24 +0x9f
test_api/helpers.SentryRecover.func1()
/var/www/test_api/helpers/helpers.go:20 +0xd9
panic(0xc6c740, 0x1349400)
/usr/local/go/src/runtime/panic.go:965 +0x1b9
test_api/rules.(*Request).processResponse(0xc00010e780, 0xc000df2000, 0x2cfc4, 0x0, 0x0, 0x0)
/var/www/test_api/rules/request.go:193 +0x245
test_api/rules.(*Request).processResponseStatus(0xc00010e780, 0xc000df2000, 0x2cfc4, 0xc00042a500, 0xc000b13300, 0xc0004d8990, 0x0)
/var/www/test_api/rules/request.go:209 +0x11b
test_api/rules.(*Rule).HTMLRequest(0xc00042a500, 0xc000b13300, 0xc0005300e0)
/var/www/test_api/rules/request.go:421 +0xa6e
test_api/rules.(*Rule).Process(0xc00042a500, 0xc000b13300, 0xc0005300e0)
/var/www/test_api/rules/rule.go:109 +0x4df
test_api/rules.Rule.Start(...)
/var/www/test_api/rules/rule.go:229
test_api/app.(*App).Tracking.func1(0xc000b0b500, 0x1378c80, 0xc000ae84c0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0xc0003b6c20, ...)
/var/www/test_api/app/app.go:137 +0x233
created by test_api/app.(*App).Tracking
/var/www/test_api/app/app.go:118 +0x1b8

but in the stack trace that I gave as an example (

net/http/httptrace.ContextClientTrace(...)

) initially-there is no useful information for me, where, from, who calls these functions - I can't understand where. At the beginning of the script, somewhere inside the GRPC server, or somewhere in my logic.

If I manually simulate a panic , everything is fine. I can see where and from where and why it occurs, and sentry and my custom recover functions works well, as you see in normal strack trace.

Thanks

[cherrymui]

there is no useful information for me, where, from, who calls these functions - I can't understand where

Sorry I still don't really understand. The stack trace is clear that the function net/http/httptrace.ContextClientTrace (in the net/http/httptrace package) panics. The source code is /usr/loc al/go/src/net/http/httptrace/trace.go:25. This function is called from net/http.(*Request).write. I still don't see how this is differ from your "normal strack trace".

[randall77]

I think the issue that @koteesy is having is that none of the application code is in the backtrace. The backtrace is all inside net/http. There's no obvious way to correlate that to a bug in his code.
Maybe more than one line of trace in the created by section would be illustrative, to see who created the goroutine. Or maybe net/http just isn't designed to give good backtraces to user code (e.g. it has a pool of workers spawned by net/http itself, and gets work from clients via channels, or something).

And of course fixing the nil pointer exception in net/http would be a good idea, if it isn't a random corruption or other nonlocal problem.

[koteesy]

I think the issue that @koteesy is having is that none of the application code is in the backtrace. The backtrace is all inside net/http. There's no obvious way to correlate that to a bug in his code.
Maybe more than one line of trace in the created by section would be illustrative, to see who created the goroutine. Or maybe net/http just isn't designed to give good backtraces to user code (e.g. it has a pool of workers spawned by net/http itself, and gets work from clients via channels, or something).

And of course fixing the nil pointer exception in net/http would be a good idea, if it isn't a random corruption or other nonlocal problem.

@randall77, yes, thank you, that's what i trying to say via my poor english. But for now, i open for myself -race flag, and see some errors when debug with that flag, and now i can't reproduce this error.

@cherrymui please, don't close this issues at least few days, I will try to fix all the errors in Data race(-race), and will try reproduce this error one more time.

Thanks you for replies.

[ALTree]

If you get random panics it's very likely that the data races are the culprit, and you won't be able to reproduce the issue after you fix them.

Leaving this as waiting for info for now, feel free to report back when you've fixed the data-races.

[koteesy]

Guys, i think this can be closed, i'll fix all what i see with -race flag, and now looks like it work like a charm. But I still think that this is not normal - when an application crashes with an error like mine without the context of my application, maybe this is a problem for me personally - since I didn't know about Data Race, but in any case, I would like to thank everyone. Thanks!