HTTP Error: Converting JSONSpan to domain Span failed

[massimopacini]

Hello,
Sometimes on some span the ui is replying with a status 500 error

Status	500
Status text	Internal Server Error
URL	/api/traces
Query	end=1575368774721000&limit=20&lookback=1h&maxDuration&minDuration&service=**********&start=1575365174721000
Response body	{ "data": null, "total": 0, "limit": 0, "offset": 0, "errors": [ { "code": 500, "msg": "Converting JSONSpan to domain Span failed: encoding/hex: invalid byte: U+002E '.'" } ] }

For info we are using elk to store span data

[yurishkuro]

This is a backend issue. Can you try to load the spans for this trace directly from ES and attach JSON?

[pavolloffay]

This seems to be a duplicate of #1926.

@massimopacini JSON will help us to resolve this issue.

[massimopacini]

This is the log from the console from jaeger-query: v1.14.0

{"level":"error","ts":1575368745.5988796,"caller":"app/http_handler.go:410","msg":"HTTP handler, Internal Server Error","error":"Converting JSONSpan to domain Span failed: encoding/hex: invalid byte: U+002E '.'","errorVerbose":"encoding/hex: invalid byte: U+002E '.'\nConverting JSONSpan to domain Span failed\ngh.neting.cc/jaegertracing/jaeger/plugin/storage/es/spanstore.(*SpanReader).collectSpans\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/plugin/storage/es/spanstore/reader.go:221\ngh.neting.cc/jaegertracing/jaeger/plugin/storage/es/spanstore.(*SpanReader).multiRead\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/plugin/storage/es/spanstore/reader.go:355\ngh.neting.cc/jaegertracing/jaeger/plugin/storage/es/spanstore.(*SpanReader).FindTraces\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/plugin/storage/es/spanstore/reader.go:280\ngh.neting.cc/jaegertracing/jaeger/storage/spanstore/metrics.(*ReadMetricsDecorator).FindTraces\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/storage/spanstore/metrics/decorator.go:79\ngh.neting.cc/jaegertracing/jaeger/cmd/query/app/querysvc.QueryService.FindTraces\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/cmd/query/app/querysvc/query_service.go:88\ngh.neting.cc/jaegertracing/jaeger/cmd/query/app.(*APIHandler).search\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/cmd/query/app/http_handler.go:203\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/opentracing-contrib/go-stdlib/nethttp.MiddlewareFunc.func5\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/opentracing-contrib/go-stdlib/nethttp/server.go:132\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/gorilla/mux.(*Router).ServeHTTP\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/gorilla/mux/mux.go:212\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/gorilla/handlers/compress.go:146\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/gorilla/handlers.recoveryHandler.ServeHTTP\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/gorilla/handlers/recovery.go:78\nnet/http.serverHandler.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:2774\nnet/http.(*conn).serve\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1878\nruntime.goexit\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/runtime/asm_amd64.s:1337","stacktrace":"github.com/jaegertracing/jaeger/cmd/query/app.(*APIHandler).handleError\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/cmd/query/app/http_handler.go:410\ngh.neting.cc/jaegertracing/jaeger/cmd/query/app.(*APIHandler).search\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/cmd/query/app/http_handler.go:204\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/opentracing-contrib/go-stdlib/nethttp.MiddlewareFunc.func5\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/opentracing-contrib/go-stdlib/nethttp/server.go:132\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/gorilla/mux.(*Router).ServeHTTP\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/gorilla/mux/mux.go:212\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/gorilla/handlers/compress.go:146\nnet/http.HandlerFunc.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1995\ngh.neting.cc/jaegertracing/jaeger/vendor/github.com/gorilla/handlers.recoveryHandler.ServeHTTP\n\t/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/gorilla/handlers/recovery.go:78\nnet/http.serverHandler.ServeHTTP\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:2774\nnet/http.(*conn).serve\n\t/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/net/http/server.go:1878"}

[pavolloffay]

@massimopacini we need span JSON stored in Elasticsearch. The logs do not show the data causing the issue.

You can get the data by querying elasticsearch #1926 (comment)

[massimopacini]

I'm trying to find the segment causing the issue as traceID is not refered in the log

[pavolloffay]

From the log Converting JSONSpan to domain Span failed: encoding/hex:it seems that the problematic part is either tag or log with binary type

jaeger/plugin/storage/es/spanstore/dbmodel/to_domain.go

Line 229 in 343fcc6

value, err := hex.DecodeString(tagValue)

(hex lib is used only for binary annotation)

You should be able to find that tag in Elasticsearch. The type will be set to 4 or will have binary in the name.

[pavolloffay]

Alternativey if the instrumentation is small try to find where you use binary tag and get the value from there.

[massimopacini]

Yes I found it ;)

  "_index": "jaeger-span-2019-12-03",
  "_type": "span",
  "_id": "chw2y24B83Q9Z-Nk8mv3",
  "_version": 1,
  "_score": 0,
  "_source": {
    "traceID": "f30e6283a8829f8b",
    "spanID": "c6a389b7beecb804",
    "flags": 1,
    "operationName": "/*****/***",
    "references": [
      {
        "refType": "CHILD_OF",
        "traceID": "f30e6283a8829f8b",
        "spanID": "7a5fadef28a475fd"
      }
    ],
    "startTime": 1575367405662000,
    "startTimeMillis": 1575367405662,
    "duration": 22000,
    "tags": [],
    "tag": {
      "http_header_accept": "*/*",
      "http_header_accept-encoding": "gzip, deflate, br",
      "http_header_accept-language": "en-us",
      "http_header_content-length": "363",
      "http_header_content-type": "application/xml",
      "http_header_uber-trace-id": "f30e6283a8829f8b:7a5fadef28a475fd:914f151e851cd71d:1",
      "http_status_code": 200,
      "internal_span_format": "jaeger"
    },
    "logs": [
      {
        "timestamp": 1575367405663000,
        "fields": [
          {
            "key": "requestedBody",
            "type": "binary",
            "value": "3c3f786d6c2076657273696f6e3d22312e302220656e636f64696e673d227574662d38223f3e0a3c5265717565737420786d6c6e733d2275726e3a6576656e7469733a7472617869737765623a312e30223e0a202020203c4964656e746974793e0a20202020202020203c50726f66696c6549643e35386366343939662d356339662d343562372d623735342d6661623838633261353230337e7e32334d617374657250726f66696c653c2f50726f66696c6549643e0a202020203c2f4964656e746974793e0a202020203c526f6f7452656c6174696f6e51756572792072656c6174696f6e4e616d653d2243706573223e0a20202020202020203c4f707469..."
          }
        ]
      }
    ],
    "process": {
      "serviceName": "*******",
      "tags": [],
      "tag": {
        "*****_version": "3.0.0",
        "client-uuid": "b569c83e-6612-48d0-b5dc-cca3f078134a",
        "hostname": "b059c0fc2365",
        "ip": "10.0.101.22",
        "jaeger_version": "Node-3.17.0"
      }
    }
  },
  "fields": {
    "startTimeMillis": [
      "2019-12-03T10:03:25.662Z"
    ]
  },
  "highlight": {
    "operationName": [
      "@kibana-highlighted-field@/****/***@/kibana-highlighted-field@"
    ]
  }
}

[pavolloffay]

Did you cut the end? Because there are ... at the end.

[pavolloffay]

How do you add the value of requestedBody field?

[massimopacini]

@pavolloffay no I haven't touch that one it was already like that maybe somewhere cut by node libs.

for that I'm doing a

span.log({
'requestedBody': req.body
});

Body is coming from Restify and it could be a bin

[pavolloffay]

Alright, I found the issue.

If the length of binary array is longer than 256, the array is stripped and added ... at the end. This is stored to ES and at query time hex.DecodeString fails because of the dots.

@yurishkuro why the binary array is stripped?

Cassandra uses correct value

jaeger/plugin/storage/cassandra/spanstore/dbmodel/converter.go

Line 195 in 343fcc6

ValueBinary: t.Binary(),

. The stripped value is used only when indexing. ES and badger use ToString which seems like a bug.

[yurishkuro]

If the length of binary array is longer than 256, the array is stripped and added ... at the end.

Do we know where this happens? Typically tag value trimming happened in the clients.

[pavolloffay]

@massimopacini is using jaeger node client. Not sure if he disabled trimming or it's not applied by default.

[yurishkuro]

I don't believe Node client has any truncation logic.