I have 34 services reporting to my SigNoz. After a hour or two my clickhouse-setup_otel-collector_1 stops accepting traces. How do I gather logs to help identify the issue? Restarting the container fixes the issue for a couple more hours... The service hosts show errors like:

OpenTelemetry error: OTLP exporter received rpc.Status{message=value not found in metricKeyToDimensions cache by key "id-staging-app01\x00GET /admin/tag_management(.:format)\x00SPAN_KIND_SERVER\x00STATUS_CODE_UNSET\x00200\x00default\x00default", details=[]}

Hi @Bill Cavalieri it's a known bug and fix is coming tomorrow with a new release. Till then you can change the value to the one mentioned in below link. It must be much lower in version that you are using https://github.com/SigNoz/charts/blob/main/charts/signoz/values.yaml#L1288

Awesome! I'll just wait and update tomorrow then, I'm on v0.12.0

hey @Bill Cavalieri

v0.13.0

is out which has the above fix. Let us know how it goes https://github.com/SigNoz/signoz/releases/tag/v0.13.0

Just upgraded, looks like I made it 30 minutes before Services and Traces go blank. Restarting clickhouse-setup_otel-collector_1 resumes tracing collection. I am avg 5 mil spans per hour per usage explorer.

@Srikanth Chekuri any idea why this still might be happening?

A new chart version has been released. Please update (

signoz/signoz-otel-collector

image would be

v0.66.1

) and let us know if you still face the issue.

@Ankit Nayan Where do I find those logs in the container? I poked around a bit, but haven't found anything.

That’s strange. Would you be able to huddle now and show me the issue and possibly debug it?

yes I sure can

Thanks @Bill Cavalieri; looking at the logs, we found it wasn’t because of the metricKeyToDimensions, but a connection refused error from the trace exporter.

<http://github.com/SigNoz/signoz-otel-collector/exporter/clickhousetracesexporter.(*SpanWriter).writeBatch|github.com/SigNoz/signoz-otel-collector/exporter/clickhousetracesexporter.(*SpanWriter).writeBatch>
	/src/exporter/clickhousetracesexporter/writer.go:129
<http://github.com/SigNoz/signoz-otel-collector/exporter/clickhousetracesexporter.(*SpanWriter).backgroundWriter|github.com/SigNoz/signoz-otel-collector/exporter/clickhousetracesexporter.(*SpanWriter).backgroundWriter>
	/src/exporter/clickhousetracesexporter/writer.go:108
2022-12-30T16:54:32.516Z	error	clickhousetracesexporter/writer.go:109	Could not write a batch of spans	{"kind": "exporter", "data_type": "traces", "name": "clickhousetraces", "error": "dial tcp 172.27.0.2:9000: connect: connection refused"}
<http://github.com/SigNoz/signoz-otel-collector/exporter/clickhousetracesexporter.(*SpanWriter).backgroundWriter|github.com/SigNoz/signoz-otel-collector/exporter/clickhousetracesexporter.(*SpanWriter).backgroundWriter>

What’s surprising is only the traces exporter had the connection error.

That certainly matches what I've been seeing. Dashboard functions while the traces fail.

@Srikanth Chekuri Did you also check clickhouse server metrics like cpu, memory usage? Since trace exporter writes more data than metrics so it’s possible that it is disconnected to clickhouse because of that.

@Bill Cavalieri Does it still not work?

It was at a regular utilisation at the time.

Today I checked on SigNoz and no services/traces, error I see in clickhouse-setup_otel-collector_1

2023-01-02T15:44:59.119Z	error	prometheusexporter@v0.66.0/log.go:34	error encoding and sending metric family: write tcp 172.27.0.4:8889->172.27.0.7:49386: write: broken pipe
	{"kind": "exporter", "data_type": "metrics", "name": "prometheus"}
<http://github.com/open-telemetry/opentelemetry-collector-contrib/exporter/prometheusexporter.(*promLogger).Println|github.com/open-telemetry/opentelemetry-collector-contrib/exporter/prometheusexporter.(*promLogger).Println>
	/go/pkg/mod/github.com/open-telemetry/opentelemetry-collector-contrib/exporter/prometheusexporter@v0.66.0/log.go:34
<http://github.com/prometheus/client_golang/prometheus/promhttp.HandlerForTransactional.func1.2|github.com/prometheus/client_golang/prometheus/promhttp.HandlerForTransactional.func1.2>
	/go/pkg/mod/github.com/prometheus/client_golang@v1.14.0/prometheus/promhttp/http.go:187
<http://github.com/prometheus/client_golang/prometheus/promhttp.HandlerForTransactional.func1|github.com/prometheus/client_golang/prometheus/promhttp.HandlerForTransactional.func1>
	/go/pkg/mod/github.com/prometheus/client_golang@v1.14.0/prometheus/promhttp/http.go:205
net/http.HandlerFunc.ServeHTTP
	/usr/local/go/src/net/http/server.go:2084
net/http.(*ServeMux).ServeHTTP
	/usr/local/go/src/net/http/server.go:2462
<http://go.opentelemetry.io/collector/config/confighttp.(*decompressor).wrap.func1|go.opentelemetry.io/collector/config/confighttp.(*decompressor).wrap.func1>
	/go/pkg/mod/go.opentelemetry.io/collector@v0.66.0/config/confighttp/compression.go:162
net/http.HandlerFunc.ServeHTTP
	/usr/local/go/src/net/http/server.go:2084
<http://go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Handler).ServeHTTP|go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Handler).ServeHTTP>
	/go/pkg/mod/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp@v0.36.4/handler.go:204
<http://go.opentelemetry.io/collector/config/confighttp.(*clientInfoHandler).ServeHTTP|go.opentelemetry.io/collector/config/confighttp.(*clientInfoHandler).ServeHTTP>
	/go/pkg/mod/go.opentelemetry.io/collector@v0.66.0/config/confighttp/clientinfohandler.go:39
net/http.serverHandler.ServeHTTP
	/usr/local/go/src/net/http/server.go:2916
net/http.(*conn).serve
	/usr/local/go/src/net/http/server.go:1966

@Srikanth Chekuri Looks like this is not only related to clickhousetraceexporter.

No, they are independent issues

I noticed this as well:

2023-01-02T16:35:54.865Z	info	exporterhelper/queued_retry.go:426	Exporting failed. Will retry the request after interval.	{"kind": "exporter", "data_type": "logs", "name": "clickhouselogsexporter", "error": "PrepareBatch:read tcp 172.27.0.4:34884->172.27.0.2:9000: i/o timeout", "interval": "6.421334743s"}

@Bill Cavalieri the 172.27.0.4:8889 write: broken pipe is unrelated issue to other ones. It is used for the APM metrics. It could be that prom exporter is terminating the connection before they get fully scraped. How often did you notice this error?

Every 30-60 minutes this happens during the day. Just for APM, server metrics continue to work. When my sites slow, APM will work for hours.

Every 30-60 minutes this happens during the day.

Does a broken pipe error show up every 30mins?

Here are the last 4 of them:

2023-01-03T15:05:59.355Z	error	prometheusexporter@v0.66.0/log.go:34	error encoding and sending metric family: write tcp 172.27.0.4:8889->172.27.0.7:50926: write: broken pipe
2023-01-03T15:05:59.355Z	error	prometheusexporter@v0.66.0/log.go:34	error encoding and sending metric family: write tcp 172.27.0.4:8889->172.27.0.7:50926: write: broken pipe
2023-01-03T15:05:59.355Z	error	prometheusexporter@v0.66.0/log.go:34	error encoding and sending metric family: write tcp 172.27.0.4:8889->172.27.0.7:50926: write: broken pipe
2023-01-03T15:07:59.583Z	error	prometheusexporter@v0.66.0/log.go:34	error encoding and sending metric family: write tcp 172.27.0.4:8889->172.27.0.7:36196: write: broken pipe

The First 3 are the same; are there any of them prior to that? The services tab APM metrics partially work because not all of them come from traces.

I saw this back on the 30th, but generally no timeout errors a majority of the time

2022-12-30T16:43:09.311Z	info	prometheusreceiver@v0.66.0/metrics_receiver.go:288	Starting scrape manager	{"kind": "receiver", "name": "prometheus", "pipeline": "metrics"}
time="2022-12-30T16:54:13Z" level=error msg="read tcp 172.27.0.7:42490->172.27.0.2:9000: read: connection reset by peer" component=clickhouse
time="2022-12-30T16:54:19Z" level=error msg="dial tcp 172.27.0.2:9000: i/o timeout" component=clickhouse
time="2022-12-30T16:54:23Z" level=error msg="dial tcp 172.27.0.2:9000: connect: connection refused" component=clickhouse
time="2022-12-30T16:54:28Z" level=error msg="dial tcp 172.27.0.2:9000: connect: connection refused" component=clickhouse
2022-12-30T16:55:54.582Z	info	service/collector.go:219	Received signal from OS	{"signal": "terminated"}

What are the latest logs for

clickhouse-setup_otel-collector-metrics_1

?

docker ps

CONTAINER ID   IMAGE                                        COMMAND                  CREATED       STATUS                PORTS                                                                                                                                       NAMES
0964498e706c   signoz/frontend:0.13.0                       "nginx -g 'daemon of…"   5 days ago    Up 3 days             80/tcp, 0.0.0.0:3301->3301/tcp, :::3301->3301/tcp                                                                                           frontend
29743a5780f5   signoz/signoz-otel-collector:0.66.1          "/signoz-collector -…"   5 days ago    Up 41 minutes         0.0.0.0:4317-4318->4317-4318/tcp, :::4317-4318->4317-4318/tcp                                                                               clickhouse-setup_otel-collector_1
2d0db03a384e   signoz/signoz-otel-collector:0.66.1          "/signoz-collector -…"   5 days ago    Up 3 days             4317-4318/tcp                                                                                                                               clickhouse-setup_otel-collector-metrics_1
4be9e1f5908b   signoz/query-service:0.13.0                  "./query-service -co…"   5 days ago    Up 3 days (healthy)   8080/tcp                                                                                                                                    query-service
d207004996ec   clickhouse/clickhouse-server:22.8.8-alpine   "/entrypoint.sh"         3 weeks ago   Up 3 days (healthy)   0.0.0.0:8123->8123/tcp, :::8123->8123/tcp, 0.0.0.0:9000->9000/tcp, :::9000->9000/tcp, 0.0.0.0:9181->9181/tcp, :::9181->9181/tcp, 9009/tcp   clickhouse
725e4dea35b1   bitnami/zookeeper:3.7.0                      "/opt/bitnami/script…"   3 weeks ago   Up 3 days             0.0.0.0:2181->2181/tcp, :::2181->2181/tcp, 0.0.0.0:2888->2888/tcp, :::2888->2888/tcp, 0.0.0.0:3888->3888/tcp, :::3888->3888/tcp, 8080/tcp   zookeeper-1
5d41c306f5e7   signoz/alertmanager:0.23.0-0.2               "/bin/alertmanager -…"   4 weeks ago   Up 4 weeks            9093/tcp

docker stats

CONTAINER ID   NAME                                        CPU %     MEM USAGE / LIMIT    MEM %     NET I/O           BLOCK I/O         PIDS
0964498e706c   frontend                                    0.00%     2.332MiB / 9.72GiB   0.02%     2.43MB / 3.43MB   126MB / 8.9MB     5
29743a5780f5   clickhouse-setup_otel-collector_1           216.59%   2.167GiB / 9.72GiB   22.29%    3.16GB / 6.6GB    294MB / 131kB     11
2d0db03a384e   clickhouse-setup_otel-collector-metrics_1   55.05%    1.219GiB / 9.72GiB   12.54%    389GB / 46.9GB    38.8GB / 27.7GB   12
4be9e1f5908b   query-service                               0.05%     198.9MiB / 9.72GiB   2.00%     490MB / 240MB     15.6GB / 3.79GB   12
d207004996ec   clickhouse                                  57.66%    1.39GiB / 9.72GiB    14.30%    638GB / 762GB     1.09TB / 2.92TB   301
725e4dea35b1   zookeeper-1                                 0.25%     45.2MiB / 9.72GiB    0.45%     5.97MB / 5.59MB   7.76GB / 1.58GB   47
5d41c306f5e7   clickhouse-setup_alertmanager_1             0.08%     11.62MiB / 9.72GiB   0.12%     24.1MB / 23.8MB   9.14GB / 368MB    11

Did you restart the collector or is it getting restarted because it is up for 40 minutes while rest are up for days?

I didn't restart the collector the yet today, so it must have restarted itself?

Yes, depending on the ingested volume there might not be enough memory and it would have restarted.

The docker host has 10g ram, 4 cpu, and 500g disk space

You may have to increase the RAM and/or your collector config needs to be tuned up to handle the scale. What’s your ingestion rate for all traces/metrics/logs?

Looks like I avg 5 mil span counts an hour. Peak of 12 mil

Can you update the

scrape_interval

to 90s and set

scrape_timeout

to something like 50s and see how it goes?

done, I also increased the memory to 16g and cpu's to 6. Will monitor it

getting the last

ExitCode

of container might be helpful. Code

137

is OOMKilled.

docker inspect clickhouse-setup_otel-collector_1 --format='{{.State.ExitCode}}'

The exit code has always been 0 when I check on them after it stops showing services/traces in the ui. I did make the scrape_interval 90, but I didn't find scrape_timeout. Where would I add that?

You can do that right below

scrape_interval

, it’s not there today and uses the default value

Great, made the change and applied it. Will see how long we are collecting apm data now