dynatrace-oss / fluent-plugin-dynatrace

A fluentd output plugin for sending logs to the Dynatrace Generic log ingest API v2.
Apache License 2.0
6 stars 6 forks source link

send_to_dynatrace error #29

Closed matheusneder closed 2 years ago

matheusneder commented 2 years ago

Hello,

I'm getting the error below while trying to run fluentd to send logs to dynatrace. I'm following the example in this repository.

2022-01-20 20:15:40 +0000 [warn]: #0 got unrecoverable error in primary and no secondary error_class=NoMethodError error="undefined method `downcase' for nil:NilClass"
  2022-01-20 20:15:40 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/uri/generic.rb:1546:in `use_proxy?'
  2022-01-20 20:15:40 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/uri/generic.rb:1540:in `find_proxy'
  2022-01-20 20:15:40 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:1109:in `proxy_uri'
  2022-01-20 20:15:40 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:1096:in `proxy?'
  2022-01-20 20:15:40 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:936:in `connect'
  2022-01-20 20:15:40 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:930:in `do_start'
  2022-01-20 20:15:40 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:925:in `start'
  2022-01-20 20:15:40 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluent-plugin-dynatrace-0.1.2/lib/fluent/plugin/out_dynatrace.rb:118:in `send_to_dynatrace'
  2022-01-20 20:15:40 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluent-plugin-dynatrace-0.1.2/lib/fluent/plugin/out_dynatrace.rb:90:in `write'
  2022-01-20 20:15:40 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:1138:in `try_flush'
  2022-01-20 20:15:40 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:1450:in `flush_thread_run'
  2022-01-20 20:15:40 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:462:in `block (2 levels) in start'
  2022-01-20 20:15:40 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.13.3/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-01-20 20:15:40 +0000 [warn]: #0 bad chunk is moved to /tmp/fluent/backup/worker0/object_3fc275f56d70/5d6092a4e6a8c6fdf6164cf3216e9ca2.log

The content of /tmp/fluent/backup/worker0/object_3fc275f56d70/5d6092a4e6a8c6fdf6164cf3216e9ca2.log is like this (with some special characters):

bstractLogger","loggerName":"br.com.myorganization.retorno.ExceptionMappers","lev
el":"ERROR","message":"My log message","threadName":"executor-thread-0","threadId":21,"mdc":{},"ndc":"","hostName":"my-deployment-name-575cfcbf6-845mn"
,"processName":"quarkus-run.jar","processId":1}
�stream�stdout�docker��container_id�@6e6f34b143b443166d98b4c2f41247c7965b3a1fc00c7cc3f3325b21f2c50c91�kubernetes��container_name� my-deployment-name�namespace_name�axxxx�pod_name�0my-deployment-name-575cfcbf6-845mn�container_image�>my-registry/my-deployment-name:56057�container_image_idْdock
er-pullable://my-registry/my-deployment-name@sha256:d89870a4a995282867bfb6ea2263e936ff1d235d9943576dc4914ad45525982a�pod_id�$953a2f34-ab49-4d25-b17f-86ef
c1e07b23�pod_ip�10.244.9.1�host�my-k8s-node�labels��app� my-deployment-name�chart�&my-deployment-name-56057�heritage�Helm�pod-template
-hash�575cfcbf6�release� my-deployment-name�revision�5�master_url�https://10.96.0.1:443/api�namespace_id�$091e265e-4228-42a6-a4b5-833fc890a473��a���▲"*s��log�☺�{"tim
estamp":"2022-01-20T17:15:37.505-03:00","sequence":788,"loggerClassName":"org.apache.logging.log4j.spi.AbstractLogger","loggerName":"br.com.myorganization.MyClassName","level
":"INFO","message":"My log message [1]","threadName":"executor-thread-0","threadId":21,"mdc":{},"ndc":"","hostName":"xxxx
oconta-575cfcbf6-845mn","processName":"quarkus-run.jar","processId":1}
�stream�stdout�docker��container_id�@6e6f34b143b443166d98b4c2f41247c7965b3a1fc00c7cc3f3325b21f2c50c91�kubernetes��container_name� my-deployment-name�namespace_name�axxxx�pod_name�0my-deployment-name-575cfcbf6-845mn�container_image�>my-registry/my-deployment-name:56057�container_image_idْdock
er-pullable://my-registry/my-deployment-name@sha256:XXXX�pod_id�$953a2f34-ab49-4d25-b17f-86ef
c1e07b23�pod_ip�10.244.9.1�host�my-k8s-node�labels��app� my-deployment-name�chart�&my-deployment-name-56057�heritage�Helm�pod-template
-hash�575cfcbf6�release� my-deployment-name�revision�5�master_url�https://10.96.0.1:443/api�namespace_id�$091e265e-4228-42a6-a4b5-833fc890a473��a���▲L�ꄣlog�☺�{"time
stamp":"2022-01-20T17:15:37.508-03:00","sequence":789,"loggerClassName":"org.apache.logging.log4j.spi.AbstractLogger","loggerName":"br.com.myorganization.retorno.ExceptionMappers","lev
el":"ERROR","message":"My log message","threadName":"executor-thread-0","threadId":21,"mdc":{},"ndc":"","hostName":"my-deployment-name-575cfcbf6-845mn"
,"processName":"quarkus-run.jar","processId":1}
�stream�stdout�docker��container_id�@6e6f34b143b443166d98b4c2f41247c7965b3a1fc00c7cc3f3325b21f2c50c91�kubernetes��container_name� my-deployment-name�namespace_name�axxxx�pod_

I tried some different versions of dynatrace plugin, including 0.1.6 and 0.1.5

arminru commented 2 years ago

Hi @matheusneder! Please provide some details about your setup and the configuration you used for FluentD (without any tokens 🙂). It seems likely that the Active Gate ingest endpoint URI is set incorrectly. Also do you get the same error in 0.1.6? There is no send_to_dynatrace method in that version any more.

matheusneder commented 2 years ago

Hi @arminru, thanks for attention,

Here my configmap:

kind: ConfigMap
apiVersion: v1
data:
  CLUSTER_ID: "XXXX"
  INGEST_ENDPOINT: "https://XXXX.live.dynatrace.com/api/v2/logs/ingest"
  fluent.conf: |-
    <source>
      @type tail
      path /var/log/containers/*.log
      pos_file /var/log/fluentd.pos
      time_format %Y-%m-%dT%H:%M:%S.%NZ
      tag kubernetes.*
      format json
    </source>

    # Enriches records with Kubernetes metadata
    <filter kubernetes.**>
      @type kubernetes_metadata
    </filter>

    # Send to dynatrace log ingest
    <match kubernetes.**>
      @type dynatrace
      active_gate_url "#{ENV['AG_INGEST_URL']}"
      api_token "#{ENV['LOG_INGEST_TOKEN']}"
      ssl_verify_none true
      <buffer>
        retry_max_times 3
      </buffer>
    </match>

    <system>
        log_level info
    </system>
metadata:
  name: fluentd-ingest-configuration
  namespace: dynatrace

My deamonset:

apiVersion: apps/v1
kind: DaemonSet
metadata:
  name: fluentd
  namespace: dynatrace
  labels:
    k8s-app: fluentd-logging
    version: v1
spec:
  selector:
    matchLabels:
      k8s-app: fluentd-logging
      version: v1
  template:
    metadata:
      labels:
        k8s-app: fluentd-logging
        version: v1
    spec:
      containers:
      - env:
        - name: FLUENT_UID
          value: "0"
        - name: CLUSTER_ID
          valueFrom:
            configMapKeyRef:
              key: CLUSTER_ID
              name: fluentd-ingest-configuration
        - name: INGEST_ENDPOINT
          valueFrom:
            configMapKeyRef:
              key: INGEST_ENDPOINT
              name: fluentd-ingest-configuration
        - name: LOG_INGEST_TOKEN
          valueFrom:
            secretKeyRef:
              key: log-ingest
              name: tokens
        envFrom:
        - configMapRef:
            name: proxy-config
        image: matheusneder/fluentd-dynatrace:v14.3-0.1.6
        name: fluentd
        resources:
          limits:
            cpu: 200m
            ephemeral-storage: 1Gi
            memory: 400Mi
          requests:
            cpu: 100m
            ephemeral-storage: 1Gi
            memory: 200Mi
        volumeMounts:
        - mountPath: /var/log/
          name: var-log
          readOnly: true
        - mountPath: /var/lib
          name: var-lib
          readOnly: true
        - mountPath: /var/log/fluentd.pos
          name: var-log-pos
        - mountPath: /fluentd/etc/fluent.conf
          name: fluentd-ingest-configuration
          subPath: fluent.conf
      initContainers:
      - command:
        - sh
        - -c
        - 'touch /var/log/fluentd.pos; chmod -R 770 /var/log/fluentd.pos; '
        image: busybox
        name: fluentd-permission-fix
        volumeMounts:
        - mountPath: /var/log/
          name: var-log
      serviceAccount: dynatrace-monitoring
      serviceAccountName: dynatrace-monitoring
      terminationGracePeriodSeconds: 30
      tolerations:
      - effect: NoSchedule
        key: node-role.kubernetes.io/master
      volumes:
      - hostPath:
          path: /var/log/
          type: ""
        name: var-log
      - hostPath:
          path: /var/lib
          type: ""
        name: var-lib
      - hostPath:
          path: /var/log/fluentd.pos
          type: FileOrCreate
        name: var-log-pos
      - configMap:
          defaultMode: 420
          items:
          - key: fluent.conf
            path: fluent.conf
          name: fluentd-ingest-configuration
        name: fluentd-ingest-configuration

I also created the service account and the secret (with dynatrace token) as decribed in https://github.com/dynatrace-oss/fluent-plugin-dynatrace/blob/v0.1.6/example/

In 0.1.6 I get a very similar error, but it occurs at send_records instead of send_to_dynatrace, take a look:

2022-01-21 13:23:16 +0000 [warn]: #0 got unrecoverable error in primary and no secondary error_class=NoMethodError error="undefined method `downcase' for nil:NilClass"
  2022-01-21 13:23:16 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/uri/generic.rb:1546:in `use_proxy?'
  2022-01-21 13:23:16 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/uri/generic.rb:1540:in `find_proxy'
  2022-01-21 13:23:16 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:1109:in `proxy_uri'
  2022-01-21 13:23:16 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:1096:in `proxy?'
  2022-01-21 13:23:16 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:936:in `connect'
  2022-01-21 13:23:16 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:930:in `do_start'
  2022-01-21 13:23:16 +0000 [warn]: #0 /usr/local/lib/ruby/2.6.0/net/http.rb:925:in `start'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluent-plugin-dynatrace-0.1.6/lib/fluent/plugin/out_dynatrace.rb:144:in `send_records'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluent-plugin-dynatrace-0.1.6/lib/fluent/plugin/out_dynatrace.rb:137:in `block in synchronized_send_records'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluent-plugin-dynatrace-0.1.6/lib/fluent/plugin/out_dynatrace.rb:136:in `synchronize'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluent-plugin-dynatrace-0.1.6/lib/fluent/plugin/out_dynatrace.rb:136:in `synchronized_send_records'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluent-plugin-dynatrace-0.1.6/lib/fluent/plugin/out_dynatrace.rb:106:in `write'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.14.3/lib/fluent/plugin/output.rb:1179:in `try_flush'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.14.3/lib/fluent/plugin/output.rb:1491:in `flush_thread_run'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.14.3/lib/fluent/plugin/output.rb:499:in `block (2 levels) in start'
  2022-01-21 13:23:16 +0000 [warn]: #0 /fluentd/vendor/bundle/ruby/2.6.0/gems/fluentd-1.14.3/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-01-21 13:23:16 +0000 [warn]: #0 bad chunk is moved to /tmp/fluent/backup/worker0/object_3fcbdf9b4980/5d617853f9505e7166b4d6acc7a56aa7.log
dyladan commented 2 years ago

Hmm the string downcase doesn't appear anywhere in the plugin code or indeed the whole repository. It could be a problem with a dependency, but we really don't have any aside from fluentd itself. In both cases the error happens when @agent.start is called. It doesn't seem like @agent itself is Nil though because start is called.

The offending failure happens at https://github.com/ruby/ruby/blob/v2_6_0/lib/uri/generic.rb#L1546 which indicates that hostname is Nil at that point. Are you quite sure that the environment variable AG_INGEST_URL is set properly?

matheusneder commented 2 years ago

Hey @dyladan, the AG_INGEST_URL variable was missing. Thank you for support.