https://signoz.io logo
Join Slack
Powered by
hey folks, i am contemplating how the `timestamp` ...
# general
i
hey folks, i am contemplating how the 
timestamp
might have been corrupted somehow? 😅
Copy code
Row 5:
──────
timestamp:                16616360830611120685
observed_timestamp:       1669976312096499717
id:                       2IJmVr3fofdss3H3b6bL3YvjBKe
trace_id:                 234a5bcd543ef3fa53ce929d0e0e4736
span_id:                  b4b37b64bb3f6141
trace_flags:              0
severity_text:            
severity_number:          0
body:                     {"log":"{\"level\":\"info\",\"ts\":\"1912-01-01T11:12:36.901569069+1100\",\"msg\":\"hello\",\"error\":\"eeeeerrrrr\",\"trace_id\":\"234a5bcd543ef3fa53ce929d0e0e4736\",\"span_id\":\"b4b37b64bb3f6141\"}\r\n","stream":"stdout","time":"2022-12-02T10:18:31.908222809Z"}
resources_string_key:     []
resources_string_value:   []
attributes_string_key:    ['log_file_path','timestamp']
attributes_string_value:  ['/var/log/pods/default_echoer_9eb10131-9899-4112-9867-b1d6e0701d3a/echoer/0.log','1912-01-01T11:12:36.901569069+1100']
attributes_int64_key:     []
attributes_int64_value:   []
attributes_float64_key:   []
attributes_float64_value: []
repro:
Copy code
kubectl run --namespace default -it --rm --restart=Never --image=alpine echoer -- \
  echo '{"level":"info","ts":"1912-01-01T11:12:36.901569069+1100","msg":"hello","error":"eeeeerrrrr","trace_id":"234a5bcd543ef3fa53ce929d0e0e4736","span_id":"b4b37b64bb3f6141"}'
cfg on log collector:
Copy code
receivers:
      filelog/containers:
        exclude:
        - /var/log/pods/otelcol_*/opentelemetry-collector/*.log
        include:
        - /var/log/pods/*/*/*.log
        include_file_name: false
        include_file_path: true
        operators:
        - id: mslog
          regex: '{.*?\\"ts\\":\\"(?P<timestamp>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{1,20}(\+|\-)\d{2}\d{2})\\".*?,\\"trace_id\\":\\"(?P<trace_id>\S*)\\",\\"span_id\\":\\"(?P<span_id>\S*)\\".*?'
          timestamp:
            layout: '%Y-%m-%dT%H:%M:%S.%f%z'
            parse_from: attributes.timestamp
          trace:
            span_id:
              parse_from: attributes.span_id
            trace_id:
              parse_from: attributes.trace_id
          type: regex_parser
        - field: attributes.trace_id
          type: remove
        - field: attributes.span_id
          type: remove
also, how to get 
timestamp
on the frontend to show 
1912-01-01T11:12:36.901569069+1100
? 🙏
a
cc: @nitya-signoz
n
Any reason you wanted to parse the year 1912. Right now the timestamp we have set is Uint instead of int https://github.com/SigNoz/signoz-otel-collector/blob/921457ce79766889fe472d0fbf35a[…]xporter/clickhouselogsexporter/migrations/000001_init_db.up.sql . Because of this I guess this issue is occurring.
i
thanks @nitya-signoz @Ankit Nayan i guess this means i can't predate UNIX epoch. i am not sure it'll be problematic. thank you for pointing it out.
Any reason you wanted to parse the year 1912.
just testing.
@nitya-signoz if i have current scenario where log items are missing in clickhouse, what would be a good place to start debugging ? i see that it has left the log collector's cluster but checking 
signoz_logs.logs
i do not see the log entry. on log source side:
Copy code
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector 2022-12-02T14:08:44.292Z        info    fileconsumer/file.go:159        Started watching file   {"kind": "receiver", "name": "filelog/microservice+json", "pipeline": "logs", "component": "fileconsumer", "path": "/var/log/pods/default_echoer_44add812-1732-4167-8b6f-269945e129a2/echoer/0.log"}
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector 2022-12-02T14:08:44.407Z        info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "logging", "#logs": 1}
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector 2022-12-02T14:08:44.407Z        info    ResourceLog #0
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector Resource SchemaURL: 
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector ScopeLogs #0
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector ScopeLogs SchemaURL: 
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector InstrumentationScope  
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector LogRecord #0
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector ObservedTimestamp: 2022-12-02 14:08:44.292300155 +0000 UTC
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector Timestamp: 2004-01-01 00:12:36.901569069 +0000 UTC
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector SeverityText: 
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector SeverityNumber: Unspecified(0)
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector Body: Str({"log":"{\"level\":\"info\",\"ts\":\"2004-01-01T11:12:36.901569069+1100\",\"msg\":\"hello\",\"error\":\"eeeeerrrrr\",\"trace_id\":\"234a5bcd543ef3fa53ce929d0e0e4736\",\"span_id\":\"b4b37b64bb3f6141\"}\r\n","stream":"stdout","time":"2022-12-02T14:08:44.07928492Z"})
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector Attributes:
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector      -> log.file.path: Str(/var/log/pods/default_echoer_44add812-1732-4167-8b6f-269945e129a2/echoer/0.log)
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector      -> timestamp: Str(2004-01-01T11:12:36.901569069+1100)
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector Trace ID: 234a5bcd543ef3fa53ce929d0e0e4736
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector Span ID: b4b37b64bb3f6141
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector Flags: 0
otc-opentelemetry-collector-agent-9swbc opentelemetry-collector         {"kind": "exporter", "data_type": "logs", "name": "logging"}
otc-opentelemetry-collector-agent-sbj9b opentelemetry-collector 2022-12-02T14:08:44.449Z        info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "logging", "#logs": 1}
on clickhouse, there are no new records:
Copy code
select body from signoz_logs.logs where log_file_path like '%echoer%' and trace_id != '' limit 10\G;

7 rows in set. Elapsed: 0.043 sec. Processed 2.98 million rows, 30.60 MB (69.01 million rows/s., 708.10 MB/s.)
any idea?
i see that it has left the log collector's cluster
or at least I think it does signify (the debug log) that it has left the source collector's cluster 😅
If I replay the log source (restart collector - it has start beginning set to true), it does reach clickhouse.
n
Interestingly, if anything fails to export then ideally it will be logged in the otel collector errors. Can’t think of a case right now but it will be helpful if you can share the configs, will get a better idea. Or if it’s for a specific kind of log, then we can try to reproduce with only that kind of log.
i
sure
straight from the configmap:
Copy code
apiVersion: v1
data:
  relay: |
    exporters:
      logging:
        loglevel: debug
      otlp/signoz:
        endpoint: 10.248.19.100:4317
        tls:
          insecure: true
    extensions:
      health_check: {}
      memory_ballast:
        size_in_percentage: 40
    processors:
      batch: {}
      k8sattributes:
        extract:
          metadata:
          - k8s.namespace.name
          - k8s.deployment.name
          - k8s.statefulset.name
          - k8s.daemonset.name
          - k8s.cronjob.name
          - k8s.job.name
        passthrough: false
        pod_association:
        - sources:
          - from: resource_attribute
            name: k8s.pod.ip
        - sources:
          - from: resource_attribute
            name: k8s.pod.uid
        - sources:
          - from: connection
      memory_limiter:
        check_interval: 5s
        limit_mib: 700
    receivers:
      filelog/kubernetes:
        exclude:
        - /var/log/pods/otelcol_*/opentelemetry-collector/*.log
        - /var/log/pods/default_*/*/*.log
        include:
        - /var/log/pods/*/*/*.log
        include_file_name: false
        include_file_path: true
        operators:
        - id: get-format
          routes:
          - expr: body matches "^\\{"
            output: parser-docker
          - expr: body matches "^[^ Z]+ "
            output: parser-crio
          - expr: body matches "^[^ Z]+Z"
            output: parser-containerd
          type: router
        - id: parser-crio
          output: extract_metadata_from_filepath
          regex: ^(?P<time>[^ Z]+) (?P<stream>stdout|stderr) (?P<logtag>[^ ]*) ?(?P<log>.*)$
          timestamp:
            layout: "2006-01-02T15:04:05.000000000-07:00"
            layout_type: gotime
            parse_from: attributes.time
          type: regex_parser
        - id: parser-containerd
          output: extract_metadata_from_filepath
          regex: ^(?P<time>[^ ^Z]+Z) (?P<stream>stdout|stderr) (?P<logtag>[^ ]*) ?(?P<log>.*)$
          timestamp:
            layout: '%Y-%m-%dT%H:%M:%S.%LZ'
            parse_from: attributes.time
          type: regex_parser
        - id: parser-docker
          output: extract_metadata_from_filepath
          timestamp:
            layout: '%Y-%m-%dT%H:%M:%S.%LZ'
            parse_from: attributes.time
          type: json_parser
        - id: extract_metadata_from_filepath
          parse_from: attributes["log.file.path"]
          regex: ^.*\/(?P<namespace>[^_]+)_(?P<pod_name>[^_]+)_(?P<uid>[a-f0-9\-]+)\/(?P<container_name>[^\._]+)\/(?P<restart_count>\d+)\.log$
          type: regex_parser
        - from: attributes.stream
          to: attributes["log.iostream"]
          type: move
        - from: attributes.container_name
          to: resource["k8s.container.name"]
          type: move
        - from: attributes.namespace
          to: resource["k8s.namespace.name"]
          type: move
        - from: attributes.pod_name
          to: resource["k8s.pod.name"]
          type: move
        - from: attributes.restart_count
          to: resource["k8s.container.restart_count"]
          type: move
        - from: attributes.uid
          to: resource["k8s.pod.uid"]
          type: move
        - from: attributes.log
          to: body
          type: move
        start_at: beginning
      filelog/microservice+json:
        exclude:
        - /var/log/pods/otelcol_*/opentelemetry-collector/*.log
        include:
        - /var/log/pods/default_*/*/*.log
        include_file_name: false
        include_file_path: true
        operators:
        - id: parser-microservice
          on_error: send
          regex: '{.*?\\"ts\\":\\"(?P<timestamp>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{1,20}(\+|\-)\d{2}\d{2})\\".*?,\\"trace_id\\":\\"(?P<trace_id>\S*)\\",\\"span_id\\":\\"(?P<span_id>\S*)\\".*?'
          timestamp:
            layout: '%Y-%m-%dT%H:%M:%S.%f%z'
            parse_from: attributes.timestamp
          trace:
            span_id:
              parse_from: attributes.span_id
            trace_id:
              parse_from: attributes.trace_id
          type: regex_parser
        - field: attributes.trace_id
          type: remove
        - field: attributes.span_id
          type: remove
        start_at: beginning
      jaeger:
        protocols:
          grpc:
            endpoint: 0.0.0.0:14250
          thrift_compact:
            endpoint: 0.0.0.0:6831
          thrift_http:
            endpoint: 0.0.0.0:14268
      otlp:
        protocols:
          grpc:
            endpoint: 0.0.0.0:4317
          http:
            endpoint: 0.0.0.0:4318
      prometheus:
        config:
          scrape_configs:
          - job_name: opentelemetry-collector
            scrape_interval: 10s
            static_configs:
            - targets:
              - ${MY_POD_IP}:8888
      zipkin:
        endpoint: 0.0.0.0:9411
    service:
      extensions:
      - health_check
      pipelines:
        logs:
          exporters:
          - logging
          - otlp/signoz
          processors:
          - k8sattributes
          - memory_limiter
          - batch
          receivers:
          - filelog/microservice+json
          - filelog/kubernetes
        metrics:
          exporters:
          - otlp/signoz
          processors:
          - k8sattributes
          - memory_limiter
          - batch
          receivers:
          - otlp
          - prometheus
        traces:
          exporters:
          - logging
          processors:
          - k8sattributes
          - memory_limiter
          - batch
          receivers:
          - otlp
          - jaeger
          - zipkin
      telemetry:
        metrics:
          address: 0.0.0.0:8888
kind: ConfigMap
Interestingly, if anything fails to export then ideally it will be logged in the otel collector errors
yap. have not seen any errors in the otel log collectors.
i can try sniffing on the hops to 
10.248.19.100:4317
but i thought there might be a meta table in clickhouse to check if records ever made it. is there a compaction going on btw?
(if there is even such thing in clickhouse)
even if there is, i wouldn't know - clickhouse logs show it is chugging along rather well 😅
Or if it’s for a specific kind of log, then we can try to reproduce with only that kind of log.
here it is:
Copy code
kubectl run --namespace us -it --rm --restart=Never --image=alpine echoer -- \
  echo '{"level":"info","ts":"2022-09-01T11:12:36.901569069+1100","msg":"hello","error":"eeeeerrrrr","trace_id":"234a5bcd543ef3fa53ce929d0e0e4736","span_id":"b4b37b64bb3f6141"}'
n
The config files seem to be all good, And also here all your logs have the same timestamp as seen on the regex which won’t cause any issues. Also, how did you verify that some logs are missing? You can also use a log generator that we have for testing purposes https://github.com/SigNoz/flog we have used it here https://github.com/SigNoz/logs-benchmark/blob/5c1990d8637beee6326dbcb6f376ed268f540246/signoz/signoz-client/docker-compose.yaml#L18
Have tried to replicate this locally but seems all the logs are getting ingested for me. Tried using a script which generates logs with a counter to check ordering as well as missing values but all seems to be ingested correctly.
Copy code
package main

import (
	"fmt"
	"os"
	"time"

	log "<http://github.com/sirupsen/logrus|github.com/sirupsen/logrus>"
)

func main() {

	customFormatter := &log.JSONFormatter{}
	customFormatter.TimestampFormat = "Mon, 02 Jan 2006 15:04:05 MST"

	f, err := os.OpenFile("testlogrus.log", os.O_APPEND|os.O_CREATE|os.O_RDWR, 0666)
	if err != nil {
		fmt.Printf("error opening file: %v", err)
	}

	defer f.Close()

	log.SetOutput(f)

	log.SetFormatter(customFormatter)
	for {
		time.Sleep(10 * time.Millisecond)
		log.WithFields(
			log.Fields{
				"status": "hello",
				"name":   "xyz",
			},
		).Info("This is a log message : " + fmt.Sprint(i))
	}
}
3 Views
Open in Slack
PreviousNext
Powered by