Promtail: "error parsing syslog stream" when rsyslog omfwd set to "octet-counted"

[ghost]

Describe the bug
I have set up promtail with rsyslog.
If I set rsyslog "omfwd" to "octet-counted" I see a lot of weird errors using journalctl -f. E.g.:

omfwd: TCPSendBuf error -2027, destruct TCP Connection to localhost:5514 [v8.37.0-13.el8 try http://www.rsyslog.com/e/2027 ]
Jun 17 14:11:20 <hostname> rsyslogd[13259]: action 'action-7-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.37.0-13.el8 try http://www.rsyslog.com/e/2007 ]
Jun 17 14:11:20 <hostname> rsyslogd[13259]: action 'action-7-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.37.0-13.el8 try http://www.rsyslog.com/e/2359 ]
Jun 17 14:11:20 <hostname> promtail-linux-amd64[11621]: level=warn ts=2020-06-17T12:11:20.305979589Z caller=syslogtarget.go:174 msg="error parsing syslog stream" err="found EOF after \"...." msg=\"error parsing syslog stream\" err=\"found EOF after \\\"
...
"error parsing syslog stream\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\" err=\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"found EOF after \\
....
\\\\\\\\\\\", expecting a SYSLOGMSG containing 14469 octets

(The slashes are really there, not just a censorship.)
Also, some logs are not collected this way but the ones that arrive to promtail are in turn properly labeled.
Now if I set "omfwd" to "traditional" then the error messages are gone but so are some of the labels (most of the labels set in pipeline_stages, the ones added by rsyslog are just fine). But log collection works more reliably in "traditional" mode.
E.g.: A part of the pipeline_stages is in the config below. It works with "octet-counted" but some logs are missing. When I switch to traditional, labeling stops working but all logs are there.
To Reproduce
Steps to reproduce the behavior:

1. Set up logging: rsyslog > promtail > loki
   promtail version:

promtail, version 1.5.0 (branch: HEAD, revision: 12c7eab8)
  build user:       root@9873e604c08a

rsyslog version:

rsyslogd 8.37.0-13.el8

2. Connect rsyslog to promtail
3. Observe error messages

Expected behavior
Proper labeling and log collection should work at the same time, preferable using "octet-counted" setting.

Environment:

• Infrastructure: VM
• Deployment tool: binary file

Screenshots, Promtail config, or terminal output
If applicable, add any output to help explain your problem.
Promtail config:

server:
  http_listen_port: 9080
  grpc_listen_port: 0

positions:
  filename: /tmp/positions.yaml

client:
  url: http://localhost:3100/api/prom/push


scrape_configs:
  - job_name: syslog
    syslog:
      listen_address: 0.0.0.0:5514
      idle_timeout: 60s
      label_structured_data: yes
      labels:
        job: "syslog"
    pipeline_stages:
...
    - match:
        selector: '{app="nginx"}'
        stages:
        - regex:
            expression: 'remote_addr:(?P<nginx_remote_addr>(25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)(\.(25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)){3}).*\srequest:"(?P<nginx_header>(\w+)).*status:(?P<nginx_status>([0-9]{3})).*http_x_forwarded_for:"(?P<nginx_http_x_forwarded_for>((25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)(\.(25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)){3})|\-)"'
        - labels:
            nginx_remote_addr:
            nginx_header:
            nginx_status:
            nginx_http_x_forwarded_for:
...
    relabel_configs:
      - source_labels: ['__syslog_connection_ip_address']
        target_label: 'ip_address'
      - source_labels: ['__syslog_message_severity']
        target_label: 'severity'
      - source_labels: ['__syslog_message_facility']
        target_label: 'facility'
      - source_labels: ['__syslog_message_app_name']
        target_label: 'app'
      - source_labels: ['__syslog_message_hostname']
        target_label: 'host'

Rsyslog config:

action(type="omfwd" protocol="tcp" port="5514" Template="RSYSLOG_SyslogProtocol23Format" TCP_Framing="octet-counted" Target="localhost")

[adityacs]

@g574 The error from octet-counted is because it expects the message to be of the exact size mentioned in it's prefix. In your case it expects the log message to be of 14469 bytes but it got EOF before that.

[adityacs]

We should support bestEffort mode as well and make it user's choice

@cyriltovena WDYT?

[ghost]

@adityacs, is promtail supposed to work with the omhttp module? Or is there a way to use it with traditional framing?

[adityacs]

@g574 omhttp is currently not supported. traditional framing is just nontransparent framing and definitely we support that.

Also, whichever the framing, labelling should just work fine. Could you please need more details on what labels you are expecting and what is missing?

[ghost]

Hi @adityacs , thanks for clarifying that.
Yes, I understood so, as well that labeling should be independent from the TCP framing but in my case it is not. This labeling only works with octet-counted (but then I get those EOF issues):

    - match:
        selector: '{app="nginx"}'
        stages:
        - regex:
            expression: 'remote_addr:(?P<nginx_remote_addr>(25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)(\.(25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)){3}).*\srequest:"(?P<nginx_header>(\w+)).*status:(?P<nginx_status>([0-9]{3})).*http_x_forwarded_for:"(?P<nginx_http_x_forwarded_for>((25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)(\.(25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)){3})|\-)"'
        - labels:
            nginx_remote_addr:
            nginx_header:
            nginx_status:
            nginx_http_x_forwarded_for:

Regarding EOF, I have some long log lines so I had to increase the maxMessageSize in rsyslog. Can it be that I also have to increase some parameter in promtail to match that? Is there a message size limit?

[adityacs]

8192 is the default size(reference), anything more than that should be fine. No settings required for that and we don't have any limit. Just that in octet-counted mode it has to meet the criteria that prefix message length and the actual message length should be same.

[ghost]

OK, I'm getting more and more confused. If I run journalctl -u promtail -f I see lines like this, exactly every 60 seconds:

promtail-linux-amd64[20082]: level=warn ts=2020-06-23T07:26:55.024182369Z caller=syslogtarget.go:164 msg="error initializing syslog stream" err=EOF

Does it refer to the config file being wrong, e.g. missing } character or is it the incoming log?

[ghost]

I started to truncate the config files to find the line that causes this.
Now I have this promtail.yml:

server:
  http_listen_port: 9080
  grpc_listen_port: 0

positions:
  filename: /tmp/positions.yaml

client:
  url: http://localhost:3100/loki/api/v1/push

scrape_configs:
  - job_name: syslog
    syslog:
      listen_address: 0.0.0.0:5514
      label_structured_data: yes
      labels:
        job: "syslog"

And this rsyslog.conf:

global(
workDirectory="/var/lib/rsyslog"
)

module(load="builtin:omfile" Template="RSYSLOG_TraditionalFileFormat")
include(file="/etc/rsyslog.d/*.conf" mode="optional")

*.info;mail.none;authpriv.none;cron.none                /data/var/log/messages
authpriv.*                                              /data/var/log/secure
mail.*                                                  /data/var/log/maillog
cron.*                                                  /data/var/log/cron
*.emerg                                                 :omusrmsg:*
uucp,news.crit                                          /data/var/log/spooler
local7.*                                                /data/var/log/boot.log

# Forward logs to Promtail
action(Type="omfwd" Protocol="tcp" Port="5514" Template="RSYSLOG_SyslogProtocol23Format" Target="localhost" TCP_Framing="octet-counted")

And I still get these errors:

promtail-linux-amd64[22077]: level=warn ts=2020-06-23T07:58:26.634484803Z caller=syslogtarget.go:164 msg="error initializing syslog stream" err=EOF

There's not much I can remove from the config. What can be the issue?
The error is there regardless of the framing.

[ghost]

If I stop rsyslog (i.e. no logs fed into promtail) and restart promtail the error still stays there.

[adityacs]

msg="error initializing syslog stream" err=EOF

Not sure why this error is occurring. I tried both octet and traditional framing and I don't see this.
What version of rsyslog you are using? I tried with 8.32.0

For the other error you mentioned, you can test sending your log lines to Promtail using netcat.

Example

echo "60 <13>1 2018-10-01T12:00:00.0Z example.org root - - - testlog" | nc 127.0.0.1 5514

One thing I tried was below log lines

This works correctly without any errors

echo "60 <13>1 2018-10-01T12:00:00.0Z example.org root - - - testlog" | nc 127.0.0.1 5514

This throws error found EOF after \"<13>1 2018-10-01T12:00:00.0Z test.com root - - - test\n\", expecting a SYSLOGMSG containing 57 octets. All the fields are correct but the actual length of message is only 57 which is less than 60.

echo "60 <13>1 2018-10-01T12:00:00.0Z test.com root - - - testlog" | nc 127.0.0.1 5514

I guess this is what is happening in your case. Not sure though

[ghost]

Hi @adityacs , thank you for the hints.
I am using this version: rsyslogd 8.1911.0-3.el8 (aka 2019.11)

I think I have solved some of the problems by cleaning up the rsyslog config - the weird '///////' error messages are gone now.
However, promtail keeps throwing error messages (caller=syslogtarget.go:164 msg="error initializing syslog stream" err=EOF) even after I've stopped rsyslog (the only stream I have is syslog). So there are no logs going into promtail.
The current config looks like this:

server:
  http_listen_port: 9080
  grpc_listen_port: 0

positions:
  filename: /tmp/positions.yaml

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


scrape_configs:
  - job_name: syslog
    syslog:
      listen_address: 0.0.0.0:5514
      idle_timeout: 60s
      label_structured_data: yes
      labels:
        job: "syslog"
    relabel_configs:
      - source_labels: ['__syslog_connection_ip_address']
        target_label: 'ip_address'
      - source_labels: ['__syslog_message_severity']
        target_label: 'severity'
      - source_labels: ['__syslog_message_facility']
        target_label: 'facility'
      - source_labels: ['__syslog_message_app_name']
        target_label: 'app'
      - source_labels: ['__syslog_message_hostname']
        target_label: 'host'

What can be wrong here?

[adityacs]

The config is fine. If you try to send empty message to promtail you will get error initializing syslog stream" err=EOF. I just tried this and I get EOF error.

printf ""| nc 127.0.0.1 5514

Not sure why you are getting EOF error message even when rsyslog is stopped.

[ghost]

🤦 OhMy
That was my monitoring. Thanks for the hint, it helped me a lot.

Sorry for mixing so many things in one case but I didn't know if they are related or not.

• So the '//////' messages are gone after redesigning rsyslog config.
• The error initializing syslog stream" err=EOF problem is solved by adjusting the monitoring stuff.
• octet-counted works now with proper labeling. But labels from the regex stage are not applied when using traditional framing. (I will just keep using octet-counted.)
  Thanks a lot again.

[adityacs]

@g574 Glad that your issue got fixed.

octet-counted works now with proper labeling. But labels from the regex stage are not applied when using traditional framing.

Kindly verify that the log messages you are receiving from traditional as well as octed-counted has same format. It's just that regular expression should match.

[chancez]

FWIW, if you see "error initializing syslog stream" periodically and your promtail/syslog is behind a loadbalancer, it could also be the loadbalancer health checks.