[Bug] incorrect span segment when enhancing the Gin framework

[Ruff-nono]

Search before asking

• I had searched in the issues and found no similar issues.

Apache SkyWalking Component

OAP server (apache/skywalking)

What happened

span will be created by the first HandlerFunc and closed by the last HandlerFunc, and cause incorrect SegmentID and SpanId in the gin middware

middleware before | {"SW_CTX": "[Your_ApplicationName,[email protected],ef322f52c00111eea77d2672e7982bed.82.39184361106090001,ef322f52c00111eea77d2672e7982bed.82.39184361106090002,0]"}
middleware after | {"SW_CTX": "[Your_ApplicationName,[email protected],N/A,N/A,-1]"}

What you expected to happen

handle the create and end span correctly

How to reproduce

using Gin middleware methods

g.Use(func(c *gin.Context) {
logger.Info("middleware before")
c.Next()
logger.Info("middleware after")
}

Anything else

No response

Are you willing to submit a pull request to fix on your own?

• Yes I am willing to submit a pull request on my own!

Code of Conduct

• I agree to follow this project's Code of Conduct

[wu-sheng]

span will be created by the first HandlerFunc and closed by the last HandlerFunc,

What was wrong? This sentence is not clear.

[Ruff-nono]

span will be created by the first HandlerFunc and closed by the last HandlerFunc,

What was wrong? This sentence is not clear.

I found that the Gin plugin has been changed to func (c *Context) Next(). However, this method will be handled multiple times by multiple middleware handlerFuncs in the route.
As a result, CreateEntrySpan is called every handlerFuncs and propagated by Invocation.SetContext() closed by the last handlerFunc, causing the segment to be incorrectly interrupted prematurely when customizing Gin middleware.

[wu-sheng]

Could you put a graph to explain this? You are using an instance level dynamic field, this should not be helpful is a handler instance repeatedly used in the process.

[Ruff-nono]

when customize middleware in Gin, the trace info will lost , such as

router := gin.Default()
router.Use(func(c *gin.Context) {
        logger.Info("do something before handler")
	c.Next()
	logger.Info("do something after handler")
})

and the log like this, after has no trace info

2024-01-31 16:56:02 | info | [email protected]/context.go:174 | do something before handler | {"SW_CTX": "[Your_ApplicationName,[email protected],8ad58d8ac01611eea4c42672e7982bed.36.39184449623780005,8ad58d8ac01611eea4c42672e7982bed.36.39184449623780006,0]"}
2024-01-31 16:56:02 | info | [email protected]/context.go:174 | handle | {"SW_CTX": "[Your_ApplicationName,[email protected],8ad58d8ac01611eea4c42672e7982bed.36.39184449623780005,8ad58d8ac01611eea4c42672e7982bed.36.39184449623780006,0]"}
2024-01-31 16:56:02 | info | [email protected]/context.go:174 | do something after handler | {"SW_CTX": "[Your_ApplicationName,[email protected],N/A,N/A,-1]"}
[GIN] 2024/01/31 - 16:56:02 | 200 |       179.3µs |             ::1 | GET      "/hello"

[wu-sheng]

I could understand your case now, then, when the context gets reset in the after? Is it caused by stop span at the end of #Next, or somewhere else?

[Ruff-nono]

because every middleware handlerFuncs could call #Next, then it will call #CreateEntrySpan in #BeforeInvoke and call span.End() in #AfterInvoke many times, but after span.End() first be Called by the last middleware handlerFunc, the TracingContext in current goroutine will be cleared, so the other handlerfuncs cannot get the TraceContext for use.

[wu-sheng]

OK, then there is typically solution for this, you should put a counter in the context of the chain. This counter increases one in before and minus one in after. Then, create span when the counter created, and stop span when counter back to zero.

Note, the counter should be kept in the request context.