Final error sending batch with 400 error

Grafana Loki
,
1

Hello everyone, I’m writing to ask for some help regarding an issue I’m encountering with Promtail.

Specifically, I noticed that when attempting to send a certain log to Loki, a 400 bad request is returned, but I don’t have any evidence in the writer logs even when setting everything to debug level.

Starting from the base log, I have this line:

2024-05-10T16:59:32.524953787Z stdout F {"timestamp":"2024-05-10T18:59:32.523+02:00","level":"ERROR","thread":"scheduling-1","logger":"it.konvergence.kss.service.AutoCallService","message":"[57c1d118-2222-4bb7-afec-8b26273e2ef3] exception response: ","context":"default","exception":"org.springframework.web.client.HttpServerErrorException$NotImplemented: 501 : \"{\"message\":\"ZUAXNGHW\",\"status\":\"OKTZ\"}\"\n\tat org.springframework.web.client.HttpServerErrorException.create(HttpServerErrorException.java:105)\n\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:186)\n\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:137)\n\tat org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)\n\tat org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:942)\n\tat org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:891)\n\tat org.springframework.web.client.RestTemplate.execute(RestTemplate.java:790)\n\tat org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:672)\n\tat it.konvergence.kss.service.AutoCallService.autoCall(AutoCallService.java:56)\n\tat java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124)\n\tat io.micrometer.observation.Observation.observe(Observation.java:499)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124)\n\tat org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)\n\tat java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)\n\tat java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)\n\tat java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n"}

The configuration I have for Promtail is:

      - job_name: kss-pods
          pipeline_stages:
            - cri: {}
            - json:
                expressions:
                  timestamp: timestamp
                  message: message
                  level: level
                  thread: thread
                  class: logger
                  context: context
                  exception: exception
            - labels:
                level:
                thread:
                class:
                context:
                exception:
            - timestamp:
                format: RFC3339
                source: timestamp
            - output:
                source: message
          kubernetes_sd_configs:
            - role: pod                
          relabel_configs:
             - ....

The logs from the Promtail pod say this:


level=debug ts=2024-05-10T17:02:22.736261738Z caller=json.go:182 component=file_pipeline component=stage type=json msg="extracted data debug in json stage" extracteddata="map[app:kss-random-test class:it.konvergence.kss.service.AutoCallService container:kss-random-test content:{\"timestamp\":\"2024-05-10T19:02:22.678+02:00\",\"level\":\"ERROR\",\"thread\":\"scheduling-1\",\"logger\":\"it.konvergence.kss.service.AutoCallService\",\"message\":\"[8786edce-b14b-4427-b605-f7964e14d3dc] exception response: \",\"context\":\"default\",\"exception\":\"org.springframework.web.client.HttpClientErrorException: 412 : \\\"{\\\"message\\\":\\\"RGPSOKJX\\\",\\\"status\\\":\\\"VEZJIOF\\\"}\\\"\\n\\tat org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:136)\\n\\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:183)\\n\\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:137)\\n\\tat org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)\\n\\tat org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:942)\\n\\tat org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:891)\\n\\tat org.springframework.web.client.RestTemplate.execute(RestTemplate.java:790)\\n\\tat org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:672)\\n\\tat it.konvergence.kss.service.AutoCallService.autoCall(AutoCallService.java:56)\\n\\tat java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)\\n\\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\\n\\tat org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130)\\n\\tat org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124)\\n\\tat io.micrometer.observation.Observation.observe(Observation.java:499)\\n\\tat org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124)\\n\\tat org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)\\n\\tat java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)\\n\\tat java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)\\n\\tat java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)\\n\\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\\n\\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\\n\\tat java.base/java.lang.Thread.run(Unknown Source)\\n\"} context:default exception:org.springframework.web.client.HttpClientErrorException: 412 : \"{\"message\":\"RGPSOKJX\",\"status\":\"VEZJIOF\"}\"\n\tat org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:136)\n\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:183)\n\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:137)\n\tat org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)\n\tat org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:942)\n\tat org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:891)\n\tat org.springframework.web.client.RestTemplate.execute(RestTemplate.java:790)\n\tat org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:672)\n\tat it.konvergence.kss.service.AutoCallService.autoCall(AutoCallService.java:56)\n\tat java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124)\n\tat io.micrometer.observation.Observation.observe(Observation.java:499)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124)\n\tat org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)\n\tat java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)\n\tat java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)\n\tat java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n filename:/var/log/pods/default_kss-random-test-7478b8bd88-hvs6m_99c5eeb6-8a51-49be-be44-b2d3e97c011d/kss-random-test/0.log flags:F job:default/kss-random-test level:ERROR message:[8786edce-b14b-4427-b605-f7964e14d3dc] exception response:  namespace:default node_name:k8s-cb-c4r16.konvergence.local pod:kss-random-test-7478b8bd88-hvs6m scrape_job:kubernetes-pods stream:stdout thread:scheduling-1 time:2024-05-10T17:02:22.679893705Z timestamp:2024-05-10T19:02:22.678+02:00]"


level=error ts=2024-05-10T17:02:23.431494118Z caller=client.go:430 component=client host=km-loki-gateway msg="final error sending batch" status=400 tenant= error="server returned HTTP status 400 Bad Request (400): stream '{app=\"kss-random-test\", class=\"it.konvergence.kss.service.AutoCallService\", container=\"kss-random-test\", context=\"default\", exception=\"org.springframework.web.client.HttpClientErrorException: 412 : \\\"{\\\"message\\\":\\\"RGPSOKJX\\\",\\\"status\\\":\\\"VEZJIOF\\\"}\\\"\\n\\tat org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:136)\\n\\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:183)\\n\\tat org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:137)\\n\\tat org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)\\n\\tat org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:942)\\n\\tat org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:891)\\n\\tat org.springframework.web.client.RestTemplate.execute(RestTemplate.java:790)\\n\\tat org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:6"

I’m puzzled that only this log has this problem, and it concerns me.

Does anyone have suggestions on where to investigate to understand the issue?

Is it possible that the exception field has exceeded the maximum allowed character limit? If so, where can I find this setting?

Is it possible to concatenate the values of ‘message’ and ‘exception’ to put them in the source field in order to remove the exception from the label?

2

I understand that labels have a limit of 1024 characters. Therefore, I changed my approach and concatenated the message and any exception like this:

          pipeline_stages:
            - cri: {}
            - json:
                expressions:
                  timestamp: timestamp
                  message: message
                  level: level
                  thread: thread
                  class: logger
                  context: context
                  exception: exception
                  data: "join('\n', [message, exception])"
            - labels:
                level:
                thread:
                class:
                context:
            - timestamp:
                format: RFC3339
                source: timestamp
            - output:
                source: data

The result is that when I have an exception in Loki, I get the line as expected. However, it doesn’t happen as I want when the exception is not present. Perhaps because the join fails.

image
image1000×275 47.4 KB

Could someone give me a solution to this last problem?

3

The solution to the problem involved moving the exception from the label, which has a maximum of 1024 characters, to the body. To do this, I concatenated the message and exception using JMESPath specifications as follows:

pipeline_stages:
  - cri: {}
  - json:
      expressions:
        timestamp: timestamp
        message: message
        level: level
        thread: thread
        class: logger
        context: context
        exception: exception
        data: "join('\n', [message, exception || '' ])"
  - labels:
      level:
      thread:
      class:
      context:
  - timestamp:
      format: RFC3339
      source: timestamp
  - output:
      source: data

Hope this might lend a hand to someone someday.

1 Like