Why my log entry causes 400 BAD_REQUEST?

Promtail 2.1.0 in docker Loki 2.8.0 in docker

My app writes a log entry

{"@timestamp":"2023-04-14T17:46:16.262735669+03:00","@version":"1","message":"Normalized request_id=44c30be0-3761-4560-bdfa-cd681f6f1536  POST uri=/gpx/api/files\nrequest_headers=[\ncontent-length: 767\nx-forwarded-proto: https,http\ncookie: QA_ACCESS_TOKEN=eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJkNjRlMjQ4YS03NDJjLTQzODAtOWI4MS0wNGY4OWFkNzY3ODAiLCJpc3MiOiJ5aC1hdXRoIiwiasdfasdfasdfaWF0IjoxNjgxNDgzNTc2LCJleHAiOjE2ODE0ODM2OTZ9.yJvWahg2W021nbFntGNIcuPOzkfh5g0CJFFXgFDTX2KtrT6_d693J4dJ3ERJfu7P-S5E0m5drLapL6m5koUdPg\ncookie: QA_REFRESH_TOKEN=eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJkNjRlMjQ4YS03NDJjLTQzODAtOWI4MS0wNGY4OWFkNzY3ODAiLCJpc3MiOiJ5aC1hdXRoIiwiaWF0IjoxNjgxNDgzNTc2LCJleHAiOjE2ODE0ODM2OTZ9.yJvWahg2W021nbFntGNIcuPOzkfh5g0CJFFXgFDTX2KtrT6_d693J4dJ3ERJfu7P-S5E0m5drLapL6m5koUdPg\nx-forwarded-port: 80\nx-forwarded-for: 172.18.0.10\nyh-user-uid: d64e248a-742c-4380-9b81-04f89ad76780\nyh-user-subscription-gpxfiles-slots-total: 0\nforwarded: proto=http;host=qa.your-hike.ru;for=\"172.18.0.10:44356\"\naccept: */*\nx-real-ip: *.*.*.*\nx-forwarded-scheme: https\nx-forwarded-host: qa.your-hike.ru\nhost: yh-gpx-storage:8080\ncontent-type: application/json; charset=UTF-8\nyh-user-subscription-expires-on: \naccept-encoding: gzip\nyh-user-role: USER_GRANTED\nuser-agent: okhttp/4.10.0\n]\nrequest_time=2023-04-14T17:46:16.241\nrequest_body=[\n{\"content\":\"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiPz4KPGdweAp4bWxucz0iaHR0cDovL3d3dy50b3BvZ3JhZml4LmNvbS9HUFgvMS8xIgp2ZXJzaW9uPSIxLjEiCmNyZWF0b3I9Im1lLmJ2bjEzLnNkay5hbmRyb2lkLmdweCIKeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVtYS1pbnN0YW5jZSIKeHNpOnNjaGVtYUxvY2F0aW9uPSJodHRwOi8vd3d3LnRvcG9ncmFmaXguY29tL0dQWC8xLzEgaHR0cDovL3d3dy50b3BvZ3JhZml4LmNvbS9HUFgvMS8xL2dweC54c2QiPgo8dGltZT4yMDIzLTA0LTE0VDE3OjQ1OjQ2LjasdfasdfczNSswMzowMDwvdGltZT4KPG1ldGFkYXRhPgo8bmFtZT4yMDIzLTA0LTE0VDE3OjQ1OjQ2LjczMzwvbmFtZT4KPGRlc2M+PC9kZXNjPgo8YXV0aG9yPgo8bmFtZT48L25hbWU+CjwvYXV0aG9yPgo8L21ldGFkYXRhPgo8dHJrPgo8bmFtZT50cmFjay0yMDIzLTA0LTE0LS0xNy00NS00NS5ncHg8L25hbWU+Cjx0cmtzZWc+CjwvdHJrc2VnPgo8L3Ryaz4KPC9ncHg+\",\"description\":\"track-2023-04-14--17-45-45.gpx\",\"filename\":\"\"}\n]normalized_request=[\n{\n  \"requestId\" : \"44c30be0-3761-4560-bdfa-cd681f6f1536\",\n  \"request\" : {\n    \"filename\" : \"\",\n    \"content\" : \"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiPz4KPGdweAp4bWxucz0iaHR0cDovL3d3dy50b3BvZ3JhZml4LmNvbS9HUFgvMS8xIgp2ZXJzaW9uPSIxLjEiCmNyZWF0b3I9Im1lLmJ2bjEzLnNkay5hbmRyb2lkLmdweCIKeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVtYS1pbnN0YW5jZSIKeHNpOnNjaGVtYUxvY2F0aW9uPSJodHRwOi8vd3d3LnRvcG9ncmFmaXguYasasdfasdfdfasdf29tL0dQWC8xLzEgaHR0cDovL3d3dy50b3BvZ3JhZml4LmNvbS9HUFgvMS8xL2dweC54c2QiPgo8dGltZT4yMDIzLTA0LTE0VDE3OjQ1OjQ2LjczNSswMzowMDwvdGltZT4KPG1ldGFkYXRhPgo8bmFtZT4yMDIzLTA0LTE0VDE3OjQ1OjQ2LjczMzwvbmFtZT4KPGRlc2asdfasdasdfM+PC9kZXNjPgo8YXV0aG9yPgo8bmFtZT48L25hbWU+CjwvYXV0aG9yPgo8L21ldGFkYXRhPgo8dHJrPgo8bmFtZT50cmFjay0yMDIzLTA0LTE0LS0xNy00NS00NS5ncHg8L25hbWU+Cjx0cmtzZWc+CjwvdHJrc2VnPgo8L3Ryaz4KPC9ncHg+\",\n    \"description\" : \"track-2023-04-14--17-45-45.gpx\"\n  },\n  \"response\" : {\n    \"body\" : null,\n    \"status\" : {\n      \"code\" : \"BAD_REQUEST\",\n      \"message\" : \"Maximum files count limit 0 for user with uid d64e248a-742c-4380-9b81-04f89ad76780 reached\"\n    }\n  }\n}\n]\nResponse 400\nresponse_headers=[\nX-Frame-Options: DENY\nTransfer-Encoding: chunked\nCache-Control: no-cache, no-store, max-age=0, must-revalidate\nX-Content-Type-Options: nosniff\nConnection: close\nPragma: no-cache\nExpires: 0\nX-XSS-Protection: 0\nDate: Fri, 14 Apr 2023 14:46:16 GMT\nContent-Type: application/json\n]\nresponse_body=[\n{\"body\":null,\"status\":{\"code\":\"BAD_REQUEST\",\"message\":\"Maximum files count limit 0 for user with uid d64e248a-742c-4380-9b81-04f89ad76780 reached\"}}\n]","logger_name":"ru.yh.gpxstorage.logging.web.LoggingFilter","thread_name":"http-nio-8080-exec-3","level":"INFO","level_value":20000,"request_id":"44c30be0-3761-4560-bdfa-cd681f6f1536"}

It is a valid JSON formed with Logstash from Spring application.

Promtail successfully eats it and tries to send to Loki. But faced 400 BAD REQUEST. Promtail's log contains only

s=2023-04-14T14:58:49.674682084Z caller=log.go:124 component=tailer level=info msg="Successfully reopened truncated /var/log/yh/yh-backend-gpx-storage.log"
level=error ts=2023-04-14T14:58:50.714494087Z caller=client.go:294 component=client host=10.0.0.7:3100 msg="final error sending batch" status=400 error="server returned HTTP status 400 Bad Request (400): stream '{filename=\"/var/log/yh/yh-backend-gpx-storage.log\", job=\"yh-gpx-storage-monitoring\", level=\"INFO\", logger_name=\"ru.yh.gpxstorage.logging.web.LoggingFilter\", message=\"Normalized request_id=44c30be0-3761-4560-bdfa-cd681f6f1536  POST uri=/gpx/api/files\\nrequest_headers=[\\ncontent-length: 767\\nx-forwarded-proto: https,http\\ncookie: QA_ACCESS_TOKEN=eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJkNjRlMjQ4YS03NDJjLTQzODAtOWI4MS0wNGY4OWFkNzY3ODAiLCJpc3MiOiJ5aC1hdXRoIiwiasdfasdfasdfaWF0IjoxNjgxNDgzNTc2LCJleHAiOjE2ODE0ODM2OTZ9.yJvWahg2W021nbFntGNIcuPOzkfh5g0CJFFXgFDTX2KtrT6_d693J4dJ3ERJfu7P-S5E0m5drLapL6m5koUdPg\\ncookie: QA_REFRESH_TOKEN=eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJkNjRlMjQ4YS03NDJjLTQzODAtOWI4MS0wNGY4OWFkNzY3ODAiLCJpc3MiOiJ5aC1hdXRoIiwiaWF0IjoxNjgxNDgzNTc2LCJleHAiOjE2ODE0ODM2OTZ9.yJvWahg2W021nbFntGNIcuPOzkfh5g0CJFFXgFDTX2KtrT6_d693J4dJ3ERJfu7P-S5E0m5drLapL6m5koUdPg\\nx-forwarded-port: 80\\nx-forwarded-for: 172.18.0.10\\nyh-user-uid: d64e248a-742c-4380-9b81-04f89ad76780\\nyh-user-subscription-gpxfiles-slots-tota"

Loki's logs are silent about this entry.

What is going on?

Loki config

auth_enabled: false

server:
  http_listen_port: 3100

common:
  path_prefix: /loki
  storage:
    filesystem:
      chunks_directory: /loki/chunks
      rules_directory: /loki/rules
  replication_factor: 1
  ring:
    kvstore:
      store: inmemory

schema_config:
  configs:
    - from: 2020-10-24
      store: boltdb-shipper
      object_store: filesystem
      schema: v11
      index:
        prefix: index_
        period: 24h

ruler:
  alertmanager_url: http://localhost:9093

limits_config:
  ingestion_rate_mb: 10
  ingestion_burst_size_mb: 15
  per_stream_rate_limit: 5MB

# By default, Loki will send anonymous, but uniquely-identifiable usage and configuration
# analytics to Grafana Labs. These statistics are sent to https://stats.grafana.org/
#
# Statistics help us better understand how Loki is used, and they show us performance
# levels for most users. This helps us prioritize features and documentation.
# For more information on what's sent, look at
# https://github.com/grafana/loki/blob/main/pkg/usagestats/stats.go
# Refer to the buildReport method to see what goes into a report.
#
# If you would like to disable reporting, uncomment the following lines:
#analytics:
#  reporting_enabled: false

Proimtail config

server:
  http_listen_port: 9080
  grpc_listen_port: 0

positions:
  filename: /var/log/yh/positions.yaml

clients:
  - url: http://10.0.0.7:3100/loki/api/v1/push

scrape_configs:
  - job_name: yh-gateway
    static_configs:
      - targets:
          - localhost
        labels:
          job: yh-gateway-monitoring
          __path__: /var/log/yh/yh-backend-gateway.log
    pipeline_stages:
      - json:
          expressions:
            level: level
            level_value: level_value
            logger_name: logger_name
            message: message
      - labels:
          level:
          level_name:
          logger_name:
          message:
  - job_name: yh-auth
    static_configs:
      - targets:
          - localhost
        labels:
          job: yh-auth-monitoring
          __path__: /var/log/yh/yh-backend-auth.log
    pipeline_stages:
      - json:
          expressions:
            level: level
            level_value: level_value
            logger_name: logger_name
            message: message
      - labels:
          level:
          level_name:
          logger_name:
          message:
  - job_name: yh-gpx-storage
    static_configs:
      - targets:
          - localhost
        labels:
          job: yh-gpx-storage-monitoring
          __path__: /var/log/yh/yh-backend-gpx-storage.log
    pipeline_stages:
      - json:
          expressions:
            level: level
            level_value: level_value
            logger_name: logger_name
            message: message
      - labels:
          level:
          level_name:
          logger_name:
          message:

grafana / loki

Why my log entry causes 400 BAD_REQUEST? #9140