https://signoz.io logo
i

Itai Gendler

09/23/2022, 6:46 AM
i have been trying to instrument a node.js application using the guide in the docs. i have a problem that once in a while (impposible to work) the trace exporter is crashing with the following error
Copy code
2022/09/23 06:44:57 http: panic serving 172.21.0.1:60810: runtime error: index out of range [18] with length 18
goroutine 608759 [running]:
net/http.(*conn).serve.func1(0x40002406e0)
	/usr/local/go/src/net/http/server.go:1802 +0xe4
panic({0x3b35880, 0x400475f818})
	/usr/local/go/src/runtime/panic.go:1052 +0x2b4
<http://go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).End(0x400525f680|go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).End(0x400525f680>, {0x0, 0x0, 0x0})
	/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.7.0/trace/span.go:398 +0x83c
panic({0x3b35880, 0x400475f818})
	/usr/local/go/src/runtime/panic.go:1038 +0x224
<http://github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).updateLatencyMetrics(...)|github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).updateLatencyMetrics(...)>
	/src/processor/signozspanmetricsprocessor/processor.go:644
<http://github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).aggregateMetricsForSpan|github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).aggregateMetricsForSpan>(0x40000188c0, {0x4005bc7590, 0xf}, {0x40036c05b0}, {0x4005293320})
	/src/processor/signozspanmetricsprocessor/processor.go:607 +0x6ec
<http://github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).aggregateMetricsForServiceSpans(0x40000188c0|github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).aggregateMetricsForServiceSpans(0x40000188c0>, {0x4005293320}, {0x4005bc7590, 0xf})
	/src/processor/signozspanmetricsprocessor/processor.go:502 +0x9c
<http://github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).aggregateMetrics(0x40000188c0|github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).aggregateMetrics(0x40000188c0>, {0x4005863d88})
	/src/processor/signozspanmetricsprocessor/processor.go:491 +0xdc
<http://github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).ConsumeTraces(0x40000188c0|github.com/SigNoz/signoz-otel-collector/processor/signozspanmetricsprocessor.(*processorImp).ConsumeTraces(0x40000188c0>, {0x47e9bb8, 0x4003f4c2d0}, {0x4005863d88})
	/src/processor/signozspanmetricsprocessor/processor.go:279 +0x30
<http://go.opentelemetry.io/collector/receiver/otlpreceiver/internal/trace.(*Receiver).Export(0x40001976f8|go.opentelemetry.io/collector/receiver/otlpreceiver/internal/trace.(*Receiver).Export(0x40001976f8>, {0x47e9bb8, 0x400092b050}, {0x4005863d88})
	/go/pkg/mod/go.opentelemetry.io/collector@v0.55.0/receiver/otlpreceiver/internal/trace/otlp.go:60 +0xcc
<http://go.opentelemetry.io/collector/receiver/otlpreceiver.handleTraces({0x47bb730|go.opentelemetry.io/collector/receiver/otlpreceiver.handleTraces({0x47bb730>, 0x4005293260}, 0x4005d89900, 0x40001976f8, {0x484e850, 0x6e41ce0})
	/go/pkg/mod/go.opentelemetry.io/collector@v0.55.0/receiver/otlpreceiver/otlphttp.go:47 +0xd0
<http://go.opentelemetry.io/collector/receiver/otlpreceiver.(*otlpReceiver).registerTraceConsumer.func1({0x47bb730|go.opentelemetry.io/collector/receiver/otlpreceiver.(*otlpReceiver).registerTraceConsumer.func1({0x47bb730>, 0x4005293260}, 0x4005d89900)
	/go/pkg/mod/go.opentelemetry.io/collector@v0.55.0/receiver/otlpreceiver/otlp.go:189 +0x118
net/http.HandlerFunc.ServeHTTP(0x40007640e0, {0x47bb730, 0x4005293260}, 0x4005d89900)
	/usr/local/go/src/net/http/server.go:2047 +0x40
net/http.(*ServeMux).ServeHTTP(0x4000758180, {0x47bb730, 0x4005293260}, 0x4005d89900)
	/usr/local/go/src/net/http/server.go:2425 +0x18c
<http://go.opentelemetry.io/collector/config/confighttp.(*decompressor).wrap.func1(|go.opentelemetry.io/collector/config/confighttp.(*decompressor).wrap.func1(>{0x47bb730, 0x4005293260}, 0x4005d89900)
	/go/pkg/mod/go.opentelemetry.io/collector@v0.55.0/config/confighttp/compression.go:160 +0x174
net/http.HandlerFunc.ServeHTTP(0x4000d5a140, {0x47bb730, 0x4005293260}, 0x4005d89900)
	/usr/local/go/src/net/http/server.go:2047 +0x40
<http://go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Handler).ServeHTTP(0x400023e460|go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Handler).ServeHTTP(0x400023e460>, {0x47b9d20, 0x4005bd35e0}, 0x4005d89400)
	/go/pkg/mod/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp@v0.32.0/handler.go:191 +0xd0c
<http://go.opentelemetry.io/collector/config/confighttp.(*clientInfoHandler).ServeHTTP(0x400025cdc8|go.opentelemetry.io/collector/config/confighttp.(*clientInfoHandler).ServeHTTP(0x400025cdc8>, {0x47b9d20, 0x4005bd35e0}, 0x4004c9cc00)
	/go/pkg/mod/go.opentelemetry.io/collector@v0.55.0/config/confighttp/clientinfohandler.go:39 +0x26c
net/http.serverHandler.ServeHTTP({0x40002fb500}, {0x47b9d20, 0x4005bd35e0}, 0x4004c9cc00)
	/usr/local/go/src/net/http/server.go:2879 +0x45c
net/http.(*conn).serve(0x40002406e0, {0x47e9bb8, 0x4000747140})
	/usr/local/go/src/net/http/server.go:1930 +0xb54
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:3034 +0x4ac
how can i overcome this? is there a different way i can export the metrics so overcome this?
@Ankit Nayan
s

Srikanth Chekuri

09/23/2022, 7:10 AM
Can you share some sample traces which are causing this? This is very unlikely unless the span timestamps are so distant the difference overflows the range.
i

Itai Gendler

09/23/2022, 7:16 AM
what exactly do you want me to send and how to get the data?
i can send the output from the console from debug mode
s

Srikanth Chekuri

09/23/2022, 7:17 AM
Does it happen frequently?
i can send the output from the console from debug mode
Yes, use the console exporter and share the sample traces output that trigger this error.
i

Itai Gendler

09/23/2022, 7:19 AM
it happens very frequently
i was just able to reproduce it
i see first this output
Inconsistent start and end time, startTime > endTime [ 1663917517, 902433872 ] [ 1663917517, 901867218 ]
and then entire log
Copy code
Inconsistent start and end time, startTime > endTime [ 1663917517, 902433872 ] [ 1663917517, 901867218 ]
HTTP 69748: outgoing message end.
HTTP 69748: SERVER socketOnParserExecute 834
items to be sent [
  Span {
    attributes: {
      'http.route': '/',
      'express.name': 'query',
      'express.type': 'middleware'
    },
    links: [],
    events: [],
    status: { code: 0 },
    endTime: [ 1663917517, 901403189 ],
    _ended: true,
    _duration: [ 0, 63420 ],
    _clock: AnchoredClock {
      _monotonicClock: [Performance [EventTarget]],
      _epochMillis: 1663917517901,
      _performanceMillis: 74538.869541049
    },
    name: 'middleware - query',
    _spanContext: {
      traceId: '427ae950a2d2a411759a652a2dce77f5',
      spanId: '28bb4ae1410dd688',
      traceFlags: 1,
      traceState: undefined
    },
    parentSpanId: '024647d0e876b128',
    kind: 0,
    startTime: [ 1663917517, 901339769 ],
    resource: Resource { attributes: [Object] },
    instrumentationLibrary: {
      name: '@opentelemetry/instrumentation-express',
      version: '0.31.1',
      schemaUrl: undefined
    },
    _spanLimits: {
      attributeValueLengthLimit: Infinity,
      attributeCountLimit: 128,
      linkCountLimit: 128,
      eventCountLimit: 128
    },
    _spanProcessor: MultiSpanProcessor { _spanProcessors: [Array] },
    _attributeValueLengthLimit: Infinity
  },
  Span {
    attributes: {
      'http.route': '/',
      'express.name': 'expressInit',
      'express.type': 'middleware'
    },
    links: [],
    events: [],
    status: { code: 0 },
    endTime: [ 1663917517, 901846647 ],
    _ended: true,
    _duration: [ 0, 235080 ],
    _clock: AnchoredClock {
      _monotonicClock: [Performance [EventTarget]],
      _epochMillis: 1663917517901,
      _performanceMillis: 74538.869541049
    },
    name: 'middleware - expressInit',
    _spanContext: {
      traceId: '427ae950a2d2a411759a652a2dce77f5',
      spanId: '8e8227ce9c135ca7',
      traceFlags: 1,
      traceState: undefined
    },
    parentSpanId: '024647d0e876b128',
    kind: 0,
    startTime: [ 1663917517, 901611567 ],
    resource: Resource { attributes: [Object] },
    instrumentationLibrary: {
      name: '@opentelemetry/instrumentation-express',
      version: '0.31.1',
      schemaUrl: undefined
    },
    _spanLimits: {
      attributeValueLengthLimit: Infinity,
      attributeCountLimit: 128,
      linkCountLimit: 128,
      eventCountLimit: 128
    },
    _spanProcessor: MultiSpanProcessor { _spanProcessors: [Array] },
    _attributeValueLengthLimit: Infinity
  },
  Span {
    attributes: {
      'http.route': '/',
      'express.name': '<anonymous>',
      'express.type': 'middleware'
    },
    links: [],
    events: [],
    status: { code: 0 },
    endTime: [ 1663917517, 902332067 ],
    _ended: true,
    _duration: [ 0, 353574 ],
    _clock: AnchoredClock {
      _monotonicClock: [Performance [EventTarget]],
      _epochMillis: 1663917517901,
      _performanceMillis: 74538.869541049
    },
    name: 'middleware - <anonymous>',
    _spanContext: {
      traceId: '427ae950a2d2a411759a652a2dce77f5',
      spanId: 'b2f25d407ff996a2',
      traceFlags: 1,
      traceState: undefined
    },
    parentSpanId: '024647d0e876b128',
    kind: 0,
    startTime: [ 1663917517, 901978493 ],
    resource: Resource { attributes: [Object] },
    instrumentationLibrary: {
      name: '@opentelemetry/instrumentation-express',
      version: '0.31.1',
      schemaUrl: undefined
    },
    _spanLimits: {
      attributeValueLengthLimit: Infinity,
      attributeCountLimit: 128,
      linkCountLimit: 128,
      eventCountLimit: 128
    },
    _spanProcessor: MultiSpanProcessor { _spanProcessors: [Array] },
    _attributeValueLengthLimit: Infinity
  },
  Span {
    attributes: {
      'http.route': '/',
      'express.name': '/',
      'express.type': 'request_handler'
    },
    links: [],
    events: [],
    status: { code: 0 },
    endTime: [ 1663917517, 901867218 ],
    _ended: true,
    _duration: [ -1, 999433346 ],
    _clock: AnchoredClock {
      _monotonicClock: [Performance [EventTarget]],
      _epochMillis: 1663917517901,
      _performanceMillis: 74538.869541049
    },
    name: 'request handler - /',
    _spanContext: {
      traceId: '427ae950a2d2a411759a652a2dce77f5',
      spanId: 'af5eaec43dcd81da',
      traceFlags: 1,
      traceState: undefined
    },
    parentSpanId: '024647d0e876b128',
    kind: 0,
    startTime: [ 1663917517, 902433872 ],
    resource: Resource { attributes: [Object] },
    instrumentationLibrary: {
      name: '@opentelemetry/instrumentation-express',
      version: '0.31.1',
      schemaUrl: undefined
    },
    _spanLimits: {
      attributeValueLengthLimit: Infinity,
      attributeCountLimit: 128,
      linkCountLimit: 128,
      eventCountLimit: 128
    },
    _spanProcessor: MultiSpanProcessor { _spanProcessors: [Array] },
    _attributeValueLengthLimit: Infinity
  },
  Span {
    attributes: {
      'http.url': '<http://localhost:8080/>',
      'http.host': 'localhost:8080',
      'net.host.name': 'localhost',
      'http.method': 'GET',
      'http.target': '/',
      'http.user_agent': 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36',
      'http.flavor': '1.1',
      'net.transport': 'ip_tcp',
      attribute1: 'value1',
      'net.host.ip': '::1',
      'net.host.port': 8080,
      'net.peer.ip': '::1',
      'net.peer.port': 50573,
      'http.status_code': 304,
      'http.status_text': 'NOT MODIFIED',
      'http.route': ''
    },
    links: [],
    events: [ [Object], [Object] ],
    status: { code: 0 },
    endTime: [ 1663917517, 904494047 ],
    _ended: true,
    _duration: [ 0, 3440380 ],
    _clock: AnchoredClock {
      _monotonicClock: [Performance [EventTarget]],
      _epochMillis: 1663917517901,
      _performanceMillis: 74538.869541049
    },
    name: 'GET /',
    _spanContext: {
      traceId: '427ae950a2d2a411759a652a2dce77f5',
      spanId: '024647d0e876b128',
      traceFlags: 1,
      traceState: undefined
    },
    parentSpanId: undefined,
    kind: 1,
    startTime: [ 1663917517, 901053667 ],
    resource: Resource { attributes: [Object] },
    instrumentationLibrary: {
      name: '@opentelemetry/instrumentation-http',
      version: '0.32.0',
      schemaUrl: undefined
    },
    _spanLimits: {
      attributeValueLengthLimit: Infinity,
      attributeCountLimit: 128,
      linkCountLimit: 128,
      eventCountLimit: 128
    },
    _spanProcessor: MultiSpanProcessor { _spanProcessors: [Array] },
    _attributeValueLengthLimit: Infinity
  }
]
Instrumentation suppressed, returning Noop Span
HTTP 69748: have free socket
@opentelemetry/instrumentation-http http instrumentation outgoingRequest
@opentelemetry/instrumentation-http http.ClientRequest return request
HTTP 69748: write ret = true
HTTP 69748: outgoing message end.
HTTP 69748: server socket close
@opentelemetry/instrumentation-http outgoingRequest on request error() Error: socket hang up
    at connResetException (node:internal/errors:693:14)
    at Socket.socketOnEnd (node:_http_client:486:23)
    at Socket.emit (node:events:539:35)
    at endReadableNT (node:internal/streams/readable:1344:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
  code: 'ECONNRESET'
}
{"stack":"Error: socket hang up\n    at connResetException (node:internal/errors:693:14)\n    at Socket.socketOnEnd (node:_http_client:486:23)\n    at Socket.emit (node:events:539:35)\n    at endReadableNT (node:internal/streams/readable:1344:12)\n    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)","message":"socket hang up","code":"ECONNRESET","name":"Error"}
HTTP 69748: CLIENT socket onClose
HTTP 69748: removeSocket localhost:4318: writable: false
HTTP 69748: HTTP socket close
@opentelemetry/instrumentation
this includes both dialog log level and node.js http debug output
s

Srikanth Chekuri

09/23/2022, 7:21 AM
That confirms it. I have seen this bug earlier with node.js SDK.
Which version of node are you using?
i

Itai Gendler

09/23/2022, 7:28 AM
in this case 18.3.0
or you are talkinb about the sdk version not the node.js version
i’m using the latest
@opentelemetry/sdk-node
which is
0.33.0
s

Srikanth Chekuri

09/23/2022, 7:37 AM
If you see the output there are negative durations in it. This clock dirft was a known issue and should have been fixed in
0.33.0
.
i

Itai Gendler

09/23/2022, 7:44 AM
can you maybe point me to the github issue related to that pr? so i’ll post it there?
but I think we will handle this gracefully on our collector side as well. Is this a blocker for you?
i

Itai Gendler

09/23/2022, 7:52 AM
preety much…
unless there is a different way to pass the traces to signoz
maybe through the collector pattern? if you can point me
s

Srikanth Chekuri

09/23/2022, 7:53 AM
No, it’s data problem that should be handled. We will do a patch release with the fix. Should be available in an hour or two.
i

Itai Gendler

09/23/2022, 8:12 AM
ty! but isn’t it possible to use the collector pattern with signoz instead of the built in collector? what’s the difference?
s

Srikanth Chekuri

09/23/2022, 8:16 AM
Not sure I understood what you mean by use the collector pattern with signoz instead of the built in collector but we maintain a separate distribution with some customisation to work well with our backend and for generating the APM metrics generated using traces which are very helpful to give the high level service health.
i

Itai Gendler

09/23/2022, 8:23 AM
ok
s

Srikanth Chekuri

09/23/2022, 9:12 AM
@Itai Gendler can you update the image from
signoz/signoz-otel-collector:0.55.1
to
signoz/signoz-otel-collector:0.55.2
in your deployment and try again?
i

Itai Gendler

09/23/2022, 9:25 AM
will try soon
2 Views