Does this fix apply to HTTP/2 in cases where the second HTTP request starts before the first one ends, causing the two requests to share the same ctx.tracing?

Does this fix apply to HTTP/2 in cases where the second HTTP request starts before the first one ends, causing the two requests to share the same ctx.tracing?

https://github.com/apache/apisix/pull/13232/changes#diff-1b0efc84c955bbecaf03cb73a6b7c72f8cac0b1045c1d069fc01fa390d2c31daR109-R114

i've added the test case here to address your issue. after doing some digging, i found that in http2 requests, ctx.tracing won't be shared across different requests since each request would init a new one. hence could u elaborate more on your issue or if there is any reproduction steps?

The PR is on the right track; please fix the failed CI.

Does this fix apply to HTTP/2 in cases where the second HTTP request starts before the first one ends, causing the two requests to share the same ctx.tracing?

https://github.com/apache/apisix/pull/13232/changes#diff-1b0efc84c955bbecaf03cb73a6b7c72f8cac0b1045c1d069fc01fa390d2c31daR109-R114

i've added the test case here to address your issue. after doing some digging, i found that in http2 requests, ctx.tracing won't be shared across different requests since each request would init a new one. hence could u elaborate more on your issue or if there is any reproduction steps?

Does this fix apply to HTTP/2 in cases where the second HTTP request starts before the first one ends, causing the two requests to share the same ctx.tracing?

https://github.com/apache/apisix/pull/13232/changes#diff-1b0efc84c955bbecaf03cb73a6b7c72f8cac0b1045c1d069fc01fa390d2c31daR109-R114

i've added the test case here to address your issue. after doing some digging, i found that in http2 requests, ctx.tracing won't be shared across different requests since each request would init a new one. hence could u elaborate more on your issue or if there is any reproduction steps?

We recently encountered an similar issue in our online environment involving ngx.ctx during the SSL phase and request processing phases. Here is an example to demonstrate the problem:

nginx.conf:

   ssl_certificate_by_lua_block {
        ngx.ctx.tracing={}
        ngx.log(ngx.WARN, "id: ", tostring(ngx.ctx.tracing))
    }
    location /slow {
        content_by_lua_block {
            ngx.log(ngx.WARN, "id(slow): ", tostring(ngx.ctx.tracing))
            table.insert(ngx.ctx.tracing, "slow_1")    
            ngx.sleep(1)
            table.insert(ngx.ctx.tracing, "slow_2")    
            ngx.say("slow")
        }
    }
    location /fast {
        content_by_lua_block {
            ngx.log(ngx.WARN, "id(fast): ", tostring(ngx.ctx.tracing))
            table.insert(ngx.ctx.tracing, "fast_1")    
            ngx.say("fast")
        }
    }
    log_by_lua_block {
        ngx.log(ngx.WARN, "data: ", table.concat(ngx.ctx.tracing, ", "), ", id:", tostring(ngx.ctx.tracing))
        ngx.ctx.tracing=nil
        ngx.log(ngx.WARN, "nil?(after set to nil): ", ngx.ctx.tracing==nil)
        ngx.log(ngx.WARN, "data(after set to nil): ", table.concat(ngx.ctx.tracing, ", "))
    }

Run the command bellow to process two requests concurrently within the same connection:

curl -Z -k --http2 https://127.0.0.1:8443/slow  https://127.0.0.1:8443/fast

Error Log Output:(Prefix timestamps and metadata removed)

ssl_certificate_by_lua(nginx.conf:119):3: id: table: 0x7ff77b5a1060, context: ssl_certificate_by_lua*, client: 127.0.0.1, server: 0.0.0.0:8443
content_by_lua(nginx.conf:131):2: id(slow): table: 0x7ff77b5a1060, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"
content_by_lua(nginx.conf:141):2: id(fast): table: 0x7ff77b5a1060, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):2: data: slow_1, fast_1, id:table: 0x7ff77b5a1060 while logging request, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):4: nil?(after set to nil): false while logging request, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):5: data(after set to nil): slow_1, fast_1 while logging request, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):2: data: slow_1, fast_1, slow_2, id:table: 0x7ff77b5a1060 while logging request, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):4: nil?(after set to nil): false while logging request, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):5: data(after set to nil): slow_1, fast_1, slow_2 while logging request, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"

Key Observations from the Logs:

• ngx.ctx.tracing is shared across different requests on the same connection, leading to data interference between requests.
• Setting ngx.ctx.tracing = nil does not achieve the expected result; the value persists.

Based on the implementation relate to ngx.ctx get_ctx_table, the ngx.ctx accessed during the SSL phase acts as the metatable for the ngx.ctx accessed during the request processing phase.

In the example above:

• The value retrieved from ngx.ctx.tracing is always the one initialized during the SSL phase.
• Setting ngx.ctx.tracing to nil in the request phase does nothing because the request-level ngx.ctx table does not actually contain the tracing key itself. When access it again, Lua continues to look up the key along the metatable and finding the value stored in the SSL-phase ngx.ctx.

In this specific issue, the PR fixes the crash, the tracing data still interference across concurrent requests.

We recently encountered an similar issue in our online environment involving ngx.ctx during the SSL phase and request processing phases. Here is an example to demonstrate the problem:

nginx.conf:

   ssl_certificate_by_lua_block {
        ngx.ctx.tracing={}
        ngx.log(ngx.WARN, "id: ", tostring(ngx.ctx.tracing))
    }
    location /slow {
        content_by_lua_block {
            ngx.log(ngx.WARN, "id(slow): ", tostring(ngx.ctx.tracing))
            table.insert(ngx.ctx.tracing, "slow_1")    
            ngx.sleep(1)
            table.insert(ngx.ctx.tracing, "slow_2")    
            ngx.say("slow")
        }
    }
    location /fast {
        content_by_lua_block {
            ngx.log(ngx.WARN, "id(fast): ", tostring(ngx.ctx.tracing))
            table.insert(ngx.ctx.tracing, "fast_1")    
            ngx.say("fast")
        }
    }
    log_by_lua_block {
        ngx.log(ngx.WARN, "data: ", table.concat(ngx.ctx.tracing, ", "), ", id:", tostring(ngx.ctx.tracing))
        ngx.ctx.tracing=nil
        ngx.log(ngx.WARN, "nil?(after set to nil): ", ngx.ctx.tracing==nil)
        ngx.log(ngx.WARN, "data(after set to nil): ", table.concat(ngx.ctx.tracing, ", "))
    }

Run the command bellow to process two requests concurrently within the same connection:

curl -Z -k --http2 https://127.0.0.1:8443/slow  https://127.0.0.1:8443/fast

Error Log Output:(Prefix timestamps and metadata removed)

ssl_certificate_by_lua(nginx.conf:119):3: id: table: 0x7ff77b5a1060, context: ssl_certificate_by_lua*, client: 127.0.0.1, server: 0.0.0.0:8443
content_by_lua(nginx.conf:131):2: id(slow): table: 0x7ff77b5a1060, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"
content_by_lua(nginx.conf:141):2: id(fast): table: 0x7ff77b5a1060, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):2: data: slow_1, fast_1, id:table: 0x7ff77b5a1060 while logging request, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):4: nil?(after set to nil): false while logging request, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):5: data(after set to nil): slow_1, fast_1 while logging request, client: 127.0.0.1, server: localhost, request: "GET /fast HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):2: data: slow_1, fast_1, slow_2, id:table: 0x7ff77b5a1060 while logging request, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):4: nil?(after set to nil): false while logging request, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"
log_by_lua(nginx.conf:123):5: data(after set to nil): slow_1, fast_1, slow_2 while logging request, client: 127.0.0.1, server: localhost, request: "GET /slow HTTP/2.0", host: "127.0.0.1:8443"

Key Observations from the Logs:

• ngx.ctx.tracing is shared across different requests on the same connection, leading to data interference between requests.
• Setting ngx.ctx.tracing = nil does not achieve the expected result; the value persists.

Based on the implementation relate to ngx.ctx get_ctx_table, the ngx.ctx accessed during the SSL phase acts as the metatable for the ngx.ctx accessed during the request processing phase.

In the example above:

• The value retrieved from ngx.ctx.tracing is always the one initialized during the SSL phase.
• Setting ngx.ctx.tracing to nil in the request phase does nothing because the request-level ngx.ctx table does not actually contain the tracing key itself. When access it again, Lua continues to look up the key along the metatable and finding the value stored in the SSL-phase ngx.ctx.

In this specific issue, the PR fixes the crash, the tracing data still interference across concurrent requests.

WDYT @Baoyuantop @membphis @nic-6443 ? I can confirm that this PR solves the crash issue, but I am not sure how to write test case to confirm no data interference between both requests. One idea is to check span using opentelemetry but ig we can do it in separate PR? i'm working on a solution right now just want to have ur guys opinion.

ctx.tracing = nil in release() is a no-op on a request-phase ctx

@hachi029 already demonstrated this empirically. The per-request ngx.ctx in an HTTP phase is created as a fresh empty table whose __index metatable points at the connection-scoped SSL-phase ctx. On the same TLS connection this means three distinct Lua tables are in play:

• The SSL-phase ctx table: lives on the TLS connection, populated once during the handshake, shared with every HTTP request on that connection via the metatable link below.
• Request 1's per-request ctx table: a fresh empty table created on first ngx.ctx access in request 1, whose metatable is the SSL-phase ctx table.
• Request 2's per-request ctx table: another fresh empty table created on first ngx.ctx access in request 2, whose metatable is also the SSL-phase ctx table.

tracer.start() runs in ssl_client_hello_phase (apisix/init.lua:209), where ctx is the SSL-phase ctx table directly, so it writes tracing into the SSL-phase ctx table. In every later HTTP phase, reading ctx.tracing on a per-request ctx finds no own field called tracing and falls through __index to the SSL-phase ctx table's tracing field. Writing ctx.tracing = nil on a per-request ctx only affects that per-request ctx; the SSL-phase ctx table has no __newindex metamethod, so its tracing field is untouched and the next read on any per-request ctx still returns the same tracing table.

This matches @hachi029's repro: the logged table address 0x7ff77b5a1060 is identical in the SSL phase, both concurrent HTTP/2 streams, and the log phase, and ngx.ctx.tracing = nil followed by a re-read returns the same table.

So line 88 (ctx.tracing = nil) is dead code under the metatable inheritance that OpenResty actually uses. The crash is prevented purely by the not tracing.spans guard on line 42, and it only happens to work because tablepool.fetch returns the just-released tracing table back (LIFO), effectively re-fusing it onto the SSL-phase ctx's tracing field.

Proposal: sever the inheritance with rawget / rawset

Both issues disappear if tracer.start and tracer.release operate on the per-request ctx directly, bypassing the metatable:

function _M.start(ctx, name, kind)
    ...
    local tracing = rawget(ctx, "tracing")
    if not tracing then
        tracing = tablepool.fetch("tracing", 0, 8)
        tracing.spans = tablepool.fetch("tracing_spans", 20, 0)
        rawset(ctx, "tracing", tracing)
    end
    ...
end

function _M.release(ctx)
    local tracing = rawget(ctx, "tracing")
    if not tracing then
        return
    end
    for _, sp in ipairs(tracing.spans) do
        sp:release()
    end
    tablepool.release("tracing_spans", tracing.spans)
    tablepool.release("tracing", tracing)
    rawset(ctx, "tracing", nil)
end

Why this works:

• In the SSL phase, ctx is the SSL-phase ctx table directly; rawget on it is identical to the regular field read. The SSL-handshake span continues to be recorded on the SSL-phase ctx table's tracing field as before.
• In every HTTP phase, rawget(ctx, "tracing") returns nil on first access because the per-request ctx has no own tracing key and rawget does not follow __index. Each request initialises its own fresh tracing table on its own per-request ctx. No cross-stream sharing, no stale-pointer crash, no double-release.
• The not tracing.spans defensive check is no longer needed rawget guarantees each phase only ever sees its own tracing table, which is either nil or fully initialised.

CAVEAT: Release the SSL-phase tracing table explicitly

With rawget in place, the tracing table on the SSL-phase ctx (set during ssl_client_hello_phase) is no longer picked up or released by any HTTP request phase, so it would leak for the lifetime of the TLS connection. It should be released at the end of ssl_client_hello_phase in apisix/init.lua, immediately after span:finish(ngx_ctx):

span:finish(ngx_ctx)
tracer.release(ngx_ctx)

This is, in effect, what's happening implicitly today the SSL-phase tracing table is being released by request 1's log phase, which is exactly the coupling that causes #13200. Making it explicit and SSL-scoped is the correct shape.

One consequence: the SSL-handshake span becomes its own standalone trace rather than being stitched into the HTTP request's trace. Stitching across SSL and HTTP requires propagating only the span context (traceparent IDs), not the live tracing object a separate, larger change.

TEST 4 currently only asserts the response body, which isn't sensitive to either span mixing or log-phase failures. A useful addition would be to assert, at the end of each request, that ngx.ctx.tracing.spans contains only the spans belonging to that request, i.e. no cross-stream contamination.

I have carefully read the problem analysis and fix suggestions provided by @shreemaan-abhishek, and I agree with his views. It is the correct approach to separate the tracers for SSL and HTTP, because the same SSL connection can be shared by multiple HTTP requests, and forcibly linking them together will lead to data disorder issues.

Thanks for the thorough and detailed explanation @shreemaan-abhishek, and I totally agree with your view and have already implemented the fix based on your suggestion.

The changes made:

• tracer.start() now uses rawget(ctx, "tracing") instead of ctx.tracing, bypassing the __index metatable chain so each per-request ctx gets its own fresh tracing table
• tracer.release() now uses rawset(ctx, "tracing", nil) to clear the per-request ctx's own field directly
• tracer.release(ngx_ctx) is now explicitly called at all exit points of ssl_client_hello_phase in init.lua to prevent the SSL-phase tracing table from leaking for the lifetime of the TLS connection

As you mentioned, one consequence of this fix is that the SSL-handshake span is now its own standalone trace rather than being stitched into the HTTP request's trace. This also means ssl_client_hello_phase no longer appears in the OTel exported spans — since the SSL-phase tracing table is released at the end of ssl_client_hello_phase, the OTel plugin (which runs in the HTTP log phase) never has access to it. As a result, the existing ssl_client_hello_phase child span assertion in opentelemetry6.t TEST 6 has been removed to reflect this new behaviour.
https://github.com/apache/apisix/pull/13232/changes#diff-9e1d47dc1723f3a0ba7fc191e686f69c23200b98766520a15878cc862a7e7533L221-L227
cc @nic-6443

For the tests, I have added:

• t/node/tracer.t: consecutive HTTPS keepalive
• t/plugin/opentelemetry6.t: concurrent HTTP/2 span isolation test using a new verify_isolated_traces helper in t/lib/test_otel.lua that verifies each stream produces its own separate trace with no duplicate spans (cross-stream contamination)