Promtail logs are malformed with multiple backslashes when log.level=debug

[christopher-grech]

Describe the bug
Promtail logs get malformed with multiple backslashes (...\\\\\\\\\\\\\...) whenever debug logging is enabled via the -log.level=debug command line argument.

To Reproduce
Steps to reproduce the behavior:

1. Started Loki.
   • Helm chart https://grafana.github.io/loki/charts, name: loki, version: 0.25.3
2. Started Promtail daemon set with "-log.level=debug".
   • Helm chart: https://grafana.github.io/loki/charts, name: promtail, version: 0.19.2

Expected behavior
When debug log level is enabled, the correct debug logs are displayed. This is proven to work whenever the same containers are run directly via a docker-compose file. However, the behaviour is totally different when ran on Kubernetes via a DaemonSet. It seems that a good number of log lines are also being omitted completely when this occurs (sample log file attached).

Environment:

• Infrastructure: AWS EKS (Kubernetes) using Flux and a gitops repo to automatically sync deployments.
• Deployment tool: Flux via their HelmRelease manifest, which in turn deploys a promtail DaemonSet (sample config attached)

sample-daemonset-config.txt
sample-malformed.log

[cyriltovena]

Seems like you're shipping log wrapped in json (default docker format).

Can you share your promtail config ? I think you need to add docker stage. Not sure about those backslash yet.

[christopher-grech]

Yes, I am. Docker stage is being added explicitly since I need to further parse the logs for specific applications. The promtail config looks like the below. I might have another issue here but the logs issue is preventing me from seeing what's wrong. I'm specifying the pipelineStages value which is in turn applied to all default Kubernetes discovery configs. I found some issues with the template stage, but that is a discussion for another ticket, I guess :)

    config:
      server:
        http_listen_port: 3101
        log_level: debug

    ## Defines the loki server details.
    loki:
      serviceName: "loki"
      servicePort: 3100
      serviceScheme: http
      # user: user
      # password: pass

    pipelineStages:

    ## Extract log lines from docker output.  
    ## ref: https://github.com/grafana/loki/blob/master/docs/clients/promtail/configuration.md#docker
    - json:
        expressions:
          output: log
          stream: stream
          timestamp: time
    ## This stage will only apply to containers within pods that have a "app.kubernetes.io/part-of" meta data label equal to "payment-processing".  Note that the later label name
    ## is transformed in promtail.  Refer to https://prometheus.io/docs/prometheus/latest/configuration/configuration/#kubernetes_sd_config.
    - match:        
        selector: '{app_kubernetes_io_part_of="payment-processing"}'
        stages:
        - json:
            source: output
            expressions:
              ts: ts
              service: app
              level: level 
              line: line 
              logger: logger 
              method: method 
              msg: msg 
              stack: stack
              spanExportable: spanExportable 
              spanId: spanId 
              thread: thread 
              traceId: traceId 
        # Override the output key value extracted from the docker stage by setting it to the message extracted from the JSON output and attaching the stack trace if present.
        - template:
            source: output
            template: '{{ .msg }}{{if .stack }}{{printf " - stack:\n%s" .stack}}{{end}}'
        - labels:
            service:
            level: 
            line: 
            logger: 
            method:
            spanId: 
            thread: 
            traceId:
    - timestamp:
        source: timestamp
        format: RFC3339Nano
    - output:
        source: output

[cyriltovena]

     - labels:
            service:
            level: 
            line: 
            logger: 
            method:
            spanId: 
            thread: 
            traceId:

You should keep service, level only. We will support parsing at in LogQL in Q2 this year and what's you doing here is going to kill Loki storage.

Can you try without rewriting the output ? Might be related to your problem.

Also to make it simpler your can pipe the log (take one example file) directly to promtail and use --dry-run that will give you informations as you build that pipeline. (faster feedback look basically)

see https://github.com/grafana/loki/blob/master/docs/clients/promtail/troubleshooting.md#dry-running

[cyriltovena]

I know you want to filter with those labels, but Loki is more powerful when doing brute force.

{app="foo"} |= "service=A" |= "line=5"

Here is what's coming too #1848

[christopher-grech]

You should keep service, level only. We will support parsing at in LogQL in Q2 this year and what's you doing here is going to kill Loki storage.

I didn't think about the index storage accumulation issue, you're absolutely right; will do. I would, however, want the log lines to be displayed neater in Grafana, hence why I wanted to only display the actual message and stack trace if the latter exists. I can do without indexing the said labels since I noticed that the parsed fields are still extracted and sent together with the log line, without them being labels, which is perfectly fine as long as they're still displayed when the log line is expanded (in Grafana) which seems to be the case.

Can you try without rewriting the output ? Might be related to your problem.

The parsing already works fine without the template stage. It will display the whole JSON entry as the log line, which isn't readable when monitoring logs, hence why I want to rewrite the output. In any case, removing the template and labels stages doesn't solve the malformed log issue.

Also to make it simpler your can pipe the log (take one example file) directly to promtail and use --dry-run that will give you informations as you build that pipeline. (faster feedback look basically)

The template stage works perfectly when tried locally. I'm spinning docker containers of Grafana, loki and promtail via docker-compose. It seems to be behaving differently when deployed on Kubernetes. The msg data element is not present in the template stage, hence why it's failing. I can't see how that makes sense though. Again, it works locally. I'll anyway try the dry run thing, maybe that behaviour is more faithful to what's happening on Kubernetes.

[christopher-grech]

I tried running promtail in dry-run mode by logging into one of the pods (as I believe that's what you meant in your comment) but I'm getting the following error:

flag provided but not defined: -dry-run

Attempted command:

cat 0.log | promtail --dry-run --client.url http://127.0.0.1:3100/loki/api/v1/push

Do I need to enable the dry run feature in some way?

promtail, version v1.3.0 (branch: HEAD, revision: 5e527a03)
  build user:       root@cc149380ea14
  build date:       2020-01-25T23:25:06Z
  go version:       go1.13.6

[cyriltovena]

Yeah you need promtail 1.4 :)

[cyriltovena]

The template stage works perfectly when tried locally. I'm spinning docker containers of Grafana, loki and promtail via docker-compose. It seems to be behaving differently when deployed on Kubernetes. The msg data element is not present in the template stage, hence why it's failing. I can't see how that makes sense though. Again, it works locally. I'll anyway try the dry run thing, maybe that behaviour is more faithful to what's happening on Kubernetes.

I'm with you here. I think you should download a log directly from kubernetes and try to debug locally so we can find what's going on. We might have a bug somewhere.

[christopher-grech]

I upgraded promtail and loki to v1.4.0 on my Kubernetes cluster in order to try the --dry-run feature. I had to change its grpc listening port for it to work since the default port is already in use by the instance running on the server. Regardless, in the end, this is the output I'm getting. I'm not seeing any logs pertaining to the parsing itself.

Command being executed:

cat 0.log | grep -m1 "" | promtail --dry-run --client.url http://127.0.0.1:3100/loki/api/v1/push --server.grpc-listen-port 9096 --log.level debug

Output:

Clients configured:
----------------------
url: http://127.0.0.1:3100/loki/api/v1/push
batchwait: 1s
batchsize: 102400
backoff_config:
  minbackoff: 500ms
  maxbackoff: 5m0s
  maxretries: 10
timeout: 10s
tenant_id: ""

level=info ts=2020-04-03T09:34:15.850132236Z caller=server.go:147 http=[::]:80 grpc=[::]:9096 msg="server listening on addresses"
level=info ts=2020-04-03T09:34:15.850356081Z caller=main.go:67 msg="Starting Promtail" version="(version=1.4.0, branch=HEAD, revision=375daaee)"

Not changing the grpc port gives me the following error:

level=error ts=2020-04-03T09:40:34.239595886Z caller=main.go:63 msg="error creating promtail" error="listen tcp :9095: bind: address already in use"

Any ideas?

[stale]

This issue has been automatically marked as stale because it has not had any activity in the past 30 days. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

[cyriltovena]

Grpc is not required for single binary version, it’s fine if you don’t use it.

[stale]

This issue has been automatically marked as stale because it has not had any activity in the past 30 days. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.