MicroProfile TCK OpenTracing failures

[gsmet]

I just stumbled upon this test failure in the TCK run on CI:

[ERROR] Failures: 
[ERROR]   OpenTracingClassMethodNameClientTests>Arquillian.run:138->OpenTracingClientBaseTests.testNestedSpans:414->OpenTracingBaseTests.testNestedSpans:385->OpenTracingBaseTests.assertEqualTrees:227 expected [[
  {
    span: "{ operationName: GET:org.eclipse.microprofile.opentracing.tck.application.TestServerWebServices.nested, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=1&nestBreadth=2&async=false&data=201&failNest=false, span.kind=server], logEntries: []}",
    children: [
      {
        span: "{ operationName: GET, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=client], logEntries: []}",
        children: [
          {
            span: "{ operationName: GET:org.eclipse.microprofile.opentracing.tck.application.TestServerWebServices.nested, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=server], logEntries: []}"
          }
        ]
      },
      {
        span: "{ operationName: GET, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=client], logEntries: []}",
        children: [
          {
            span: "{ operationName: GET:org.eclipse.microprofile.opentracing.tck.application.TestServerWebServices.nested, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=server], logEntries: []}"
          }
        ]
      }
    ]
  }
]
] but found [[
  {
    span: "{ operationName: GET, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=client], logEntries: []}",
    children: [
      {
        span: "{ operationName: GET:org.eclipse.microprofile.opentracing.tck.application.TestServerWebServices.nested, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=server], logEntries: []}"
      }
    ]
  },
  {
    span: "{ operationName: GET, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=client], logEntries: []}",
    children: [
      {
        span: "{ operationName: GET:org.eclipse.microprofile.opentracing.tck.application.TestServerWebServices.nested, tags: [component=jaxrs, http.method=GET, http.status_code=200, http.url=http://localhost:8081/rest/testServices/nested?nestDepth=0&nestBreadth=1&async=false&data=201&failNest=false, span.kind=server], logEntries: []}"
      }
    ]
  }
]
]

@stuartwdouglas I wonder if it could be related to your changes or not?

[geoand]

I saw this in a PR as well

[sberyozkin]

I wonder why all the checks have passed message was displayed, TCK tests do not run as part of the PR builds ?

[stuartwdouglas]

I am pretty sure this is because of a race between the span being closed and the response being sent.

I think previously most (but not all) JAX-RS responses would close the span before sending the response, after my change all JAX-RS responses do not have the span closed until after the response has been successfully sent.

This means that when using a REST client it is now possible that there is a race between the response being sent and the span finishing where the client can mark its span finished before the service that it invoked has finished its span. As the ordering is based on completion time rather than start time this can screw up the tests.

I think there were already some circumstances where this could happen, namely async responses and responses that use OutputStream, however I have attempted to change this back to the old behaviour.