i have been trying to instrument a node js application using SigNoz Community #general

i have been trying to instrument a node.js applica...

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

Itai Gendler

09/23/2022, 6:47 AM

how can i overcome this? is there a different way i can export the metrics so overcome this?

Itai Gendler

09/23/2022, 6:55 AM

@Ankit Nayan

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.

Itai Gendler

09/23/2022, 7:16 AM

what exactly do you want me to send and how to get the data?

Itai Gendler

09/23/2022, 7:16 AM

i can send the output from the console from debug mode

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.

Itai Gendler

09/23/2022, 7:19 AM

it happens very frequently

Itai Gendler

09/23/2022, 7:19 AM

i was just able to reproduce it

Itai Gendler

09/23/2022, 7:19 AM

i see first this output

Inconsistent start and end time, startTime > endTime [ 1663917517, 902433872 ] [ 1663917517, 901867218 ]

Itai Gendler

09/23/2022, 7:19 AM

and then entire log

Itai Gendler

09/23/2022, 7:20 AM

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

Itai Gendler

09/23/2022, 7:20 AM

this includes both dialog log level and node.js http debug output

Srikanth Chekuri

09/23/2022, 7:21 AM

That confirms it. I have seen this bug earlier with node.js SDK.

Srikanth Chekuri

09/23/2022, 7:27 AM

Which version of node are you using?

Itai Gendler

09/23/2022, 7:28 AM

in this case 18.3.0

Itai Gendler

09/23/2022, 7:28 AM

or you are talkinb about the sdk version not the node.js version

Itai Gendler

09/23/2022, 7:29 AM

i’m using the latest

@opentelemetry/sdk-node

which is

0.33.0

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

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?

Srikanth Chekuri

09/23/2022, 7:47 AM

https://github.com/open-telemetry/opentelemetry-js/pull/3134

Srikanth Chekuri

09/23/2022, 7:48 AM

but I think we will handle this gracefully on our collector side as well. Is this a blocker for you?

Itai Gendler

09/23/2022, 7:52 AM

preety much…

Itai Gendler

09/23/2022, 7:52 AM

unless there is a different way to pass the traces to signoz

Itai Gendler

09/23/2022, 7:52 AM

maybe through the collector pattern? if you can point me

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.

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?

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.

Itai Gendler

09/23/2022, 8:23 AM

Srikanth Chekuri

09/23/2022, 9:12 AM

@Itai Gendler can you update the image from

signoz/signoz-otel-collector:0.55.1

signoz/signoz-otel-collector:0.55.2

in your deployment and try again?

Itai Gendler

09/23/2022, 9:25 AM

will try soon

4 Views

Open in Slack

Previous Next