Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

When log line from fluentd contains non-UTF-8 characters, the whole log line is dropped in Loki #5099

Closed
saadnabs opened this issue Jan 11, 2022 · 1 comment · Fixed by #5107 or #5163

Comments

@saadnabs
Copy link
Contributor

Describe the bug
A customer is running into an issue where a Cisco device sends a log line that contains non UTF-8 characters into fluentd, when that is forwarded to Loki (using the fluentd-loki-output plugin), Loki drops the whole log line

Debugging steps
Customer debugging and troubleshooting involved the following steps:

1.

After activating logforwarding to Loki fluentd regularly (every minute) logs following error:
Fluentd Error "invalid byte sequence in UTF-8"
2021-12-08 07:43:51 +0100 [warn]: #0 got unrecoverable error in primary and no secondary error_class=ArgumentError error="invalid byte sequence in UTF-8"
2021-12-08 07:43:51 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.16/lib/fluent/plugin/out_loki.rb:282:in `gsub'
2021-12-08 07:43:51 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.16/lib/fluent/plugin/out_loki.rb:282:in `block in record_to_line'
2021-12-08 07:43:51 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.16/lib/fluent/plugin/out_loki.rb:280:in `each'

2
They came back with specific excerpts of the log lines that were causing trouble

Excerpt of fluentd chunk output:
<92>×^@a±<98>¨
È×<8a>§Unified Audit[277897]: LENGTH: '199' TYPE:"9" DBID:"263689621" SESID:"879601414" CLIENTID:"'©#004A " ENTRYID:"0" STMTID:"605" DBUSER:"SYS" CURUSER:"" ACTION:"47" RETCODE:"0" SCHEMA:"" OBJNAME:"" PDB_GUID:"BDEB1E2377C11BD2E0537AA2B60A85E6" ©timestampª1639028904\(ö£tag¢na

Inside Graylog (using another another output plugin, not fluentd loki output plugin, to transfer identical) we see following message:
Unified Audit[277897]: LENGTH: '199' TYPE:"9" DBID:"263689621" SESID:"879601414" CLIENTID:"'�#004A " ENTRYID:"0" STMTID:"605" DBUSER:"SYS" CURUSER:"" ACTION:"47" RETCODE:"0" SCHEMA:"" OBJNAME:"" PDB_GUID:"BBED1E2377E11BD2E0537AA2B60A85E6"

3
Suggested the customer to use fluentd plugin to force valid encoding but they weren't comfortable with using it in production due to the last commit being over a year ago and not looking like an officially supported plugin which may cause future fluentd migration issues.

4
Finally, customer tried the following different configurations with fluent-plugin-record-modifier to address the problem:

<filter **>
  @type record_modifier
  char_encoding utf-8
  char_encoding ASCII-8BIT:utf-8
</filter>

<filter **>
  @type record_modifier
  char_encoding utf-8
  char_encoding ASCII-8BIT:utf-8
</filter>

<filter **>
  @type record_modifier
  char_encoding ASCII-8BIT:utf-8
</filter>

But none of these worked always returning the same error messages regarding invalid chars by loki output plugin: „got unrecoverable error in primary and no secondary error_class=ArgumentError error="invalid byte sequence in UTF-8"“

Customer notes that the official fluent documention states:

Fluentd and almost [all] plugins treat the logs as a ASCII-8BIT by default but some libraries assume the log encoding is UTF-8. This is why this error happens.“

Could this be a loki-output-plugin issue/

Expected behavior
If any non UTF-8 characters are seen, they should be replaced and the log line should be saved rather then having the whole log line get dropped.

Environment:

  • Single binary deployment of Loki (during POC)
  • Fluentd -> fluentd-loki-output -> Loki
chaudum added a commit that referenced this issue Jan 12, 2022
When a log line in hash format contains non UTF-8 characters fluentd
would drop the complete line because it failed to convert the line in
key-value format.

By forcing UTF-8 encoding and replacing non UTF-8 characters with empty
strings the log line will not be dropped but only contain the valid
UTF-8 characters.

Fixes #5099

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>
cyriltovena pushed a commit that referenced this issue Jan 12, 2022
…utf-8 characters (#5107)

* fluentd: Remove non utf-8 characters from log lines

When a log line in hash format contains non UTF-8 characters fluentd
would drop the complete line because it failed to convert the line in
key-value format.

By forcing UTF-8 encoding and replacing non UTF-8 characters with empty
strings the log line will not be dropped but only contain the valid
UTF-8 characters.

Fixes #5099

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>

* Bump fluent-plugin-grafana-loki to version 1.2.17

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>

* fixup! fluentd: Remove non utf-8 characters from log lines

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>

* fixup! fluentd: Remove non utf-8 characters from log lines

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>
@saadnabs
Copy link
Contributor Author

The customer has come back that this fix changed the error but did not resolve it fully:

Deployed fluent-plugin-grafana-loki-1.2.17.gem with no success. Now we get a similar (not same) error message for specific logs:

2022-01-14 18:20:54 +0100 [warn]: #0 got unrecoverable error in primary and no secondary error_class=NoMethodError error="undefined method `encode' for 0.63:Float"
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:282:in `block in record_to_line'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:280:in `each'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:280:in `record_to_line'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:323:in `line_to_loki'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:349:in `block in chunk_to_loki'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/event.rb:315:in `each'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/event.rb:315:in `block in each'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/buffer/memory_chunk.rb:81:in `open'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/buffer/memory_chunk.rb:81:in `open'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/event.rb:314:in `each'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:347:in `chunk_to_loki'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:203:in `generic_to_loki'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:150:in `write'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:1138:in `try_flush'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:1450:in `flush_thread_run'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:462:in `block (2 levels) in start'
2022-01-14 18:20:54 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-01-14 18:20:54 +0100 [warn]: #0 bad chunk is moved to /tmp/fluent/backup/worker0/object_c44/5d58e05e4987a38ad4a77fa1c320df29.log
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:282:in `block in record_to_line'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:280:in `each'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:280:in `record_to_line'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:323:in `line_to_loki'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:349:in `block in chunk_to_loki'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/event.rb:315:in `each'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/event.rb:315:in `block in each'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/buffer/memory_chunk.rb:81:in `open'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/buffer/memory_chunk.rb:81:in `open'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/event.rb:314:in `each'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:347:in `chunk_to_loki'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:203:in `generic_to_loki'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-grafana-loki-1.2.17/lib/fluent/plugin/out_loki.rb:150:in `write'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:1138:in `try_flush'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:1450:in `flush_thread_run'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin/output.rb:462:in `block (2 levels) in start'
2022-01-14 18:21:16 +0100 [warn]: #0 /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluentd-1.13.3/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-01-14 18:21:16 +0100 [warn]: #0 bad chunk is moved to /tmp/fluent/backup/worker0/object_c44/5d58e072d2154a0b48fd15988012be8f.log

@saadnabs saadnabs reopened this Jan 17, 2022
chaudum added a commit that referenced this issue Jan 17, 2022
This change fixes a bug that is caused by incorrectly trying to encode
any values other than string.
This bug was a regression introduced with #5107 and caused
`NoMethodError` errors.

Fixes #5099

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>
cyriltovena pushed a commit that referenced this issue Jan 17, 2022
* Fix encoding error in fluentd client

This change fixes a bug that is caused by incorrectly trying to encode
any values other than string.
This bug was a regression introduced with #5107 and caused
`NoMethodError` errors.

Fixes #5099

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>

* Bump fluent-plugin-grafana-loki to version 1.2.18

Signed-off-by: Christian Haudum <christian.haudum@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
1 participant