fluent / fluent/fluentd

0.14.* regression: Records jumbled by fluentd + better tolerance for failed log entries

Open
#1,516 11 comments 2 reactions 0 assignees View on GitHub
bug v0.14
Dominant language
Ruby
Stars
13.6k
Forks
1.4k
Avg merge
1d 3h
Merged PRs (30d)
20

Description

When running the newer versions of `fluentd` (I was on 0.14.0), I started seeing persistent error in my logs to do with Date time parsing:

```
2017-03-22 15:44:32 +0000 [error]: #0 suppressed same stacktrace
2017-03-22 15:44:32 +0000 [error]: #0 unexpected error on reading data host="172.17.0.1" port=48920 error_class=Fluent::Plugin::Parser::ParserError error="invalid time format: value = column_id,events_column_value), error_class = ArgumentError, error = no time information in \"column_id,events_column_value)\""
2017-03-22 15:44:32 +0000 [error]: #0 suppressed same stacktrace
2017-03-22 15:44:32 +0000 [error]: #0 unexpected error on reading data host="172.17.0.1" port=48920 error_class=Fluent::Plugin::Parser::ParserError error="invalid time format: value = column_id,events_column_value), error_class = ArgumentError, error = no time information in \"column_id,events_column_value)\""
```

I assumed my `rsyslog` services must be pushing invalid date, however I then [forked this gem so that it was more tolerant to these failures](https://github.com/ably-forks/fluentd/commit/2a7a3f6ff74d8f073eee7659e5fb1ae7db63c5f5), and I see this in the logs now:

```
Warning: ParserError parsing record with error invalid time format: value = 248566.86fqA33WgA5Gik',, error_class = ArgumentError, error = argument out of range. Record: {"hostname"=>"name:", "ident"=>"'core.88fc.2.us-east-2-A.i-0408b626ded248566.86fqA33WgA5Gik',", "environment"=>"quickstatus:", "region"=>"true", "instance_id"=>"}", "instance_roles"=>"],", "data_center"=>"redisClient:", "data_center_id"=>"{", "message"=>"name: '86fqA33Wg:core.88fc.2.us-east-2-A.i-0408b626ded248566.86fqA33WgA5Gik',\r href: '/redis/clients/86fqA33Wg',\r quickstatus: true } } ],\r pendingLocate: false }"}
```

Now what's interesting here is that if you look at the fields, they are all jumbled up. `environment` is not `quickstatus:` it should be `production`, hostname is clearly not `name:` etc. So this is why the date parser was crashing out.

So ran a `sysdig` to see what was being sent to `fluentd`, and for context, a normal write on the socket looks like this:

```
2017-03-22T16:04:54+00:00 ec2-54-224-41-204.compute-1.amazonaws.com docker/frontend/frontend.cd08.1/1700db19d879/[2245]: production:foobar us-east-1 i-0c5688bf6f146d7b0 frontend,translator us-east-1-A A 2017-03-22T16:04:54.180Z | e7d-FnyewA5EIZ | warn | conn:foobar:rhqp5Vc9IC | Conn
ectionMaster.getConnectionCompatibility() | Unable to recover connection
```

Now when I find the sysdig logentry that matches the jumbled log above, I see this:

```
ESC[34m------ Write 3.25KB to ESC[34m 172.17.0.1:43660->172.17.0.5:http-alt (router)

2017-03-22T15:52:43+00:00 ec2-52-14-196-52.us-east-2.compute.amazonaws.com docker/frontend/frontend.3540.1/9939a83b713a/[2072]: production:foobar us-east-2 i-0abc1e713aaefe74d frontend,translator us-east-2-A A 2017-03-22T15:52:43.634Z | 86fCEXjOAA5GXN | error | channel:foobar:6480998872121344 | CoreClient.setReadinessError() | err = ErrorInfo {
message: 'Unable to connect to server',
code: 50000,
statusCode: 500,
nonfatal: undefined,
stack: undefined }; this = { key: 'foobar:6480998872121344',
masterHash: '87056f172ae1',
hashes: [ '87070322dba8', '87158977c866' ],
locations:
[ { node:
[ { href: '/network/core.e99c.1.us-east-2-A.i-0e1e884238647cee5.86fjReOSwA5GQb',
name: 'core.e99c.1.us-east-2-A.i-0e1e884238647cee5.86fjReOSwA5GQb',
quickstatus: true } ],
redisClient:
{ name: '86fjReOSw:core.e99c.1.us-east-2-A.i-0e1e884238647cee5.86fjReOSwA5GQb',
href: '/redis/clients/86fjReOSw',
quickstatus: true } },
{ node:
[ { href: '/network/core.88fc.2.us-east-2-A.i-0408b626ded248566.86fqA33WgA5Gik',
name: 'core.88fc.2.us-east-2-A.i-0408b626ded248566.86fqA33WgA5Gik',
quickstatus: true } ],
redisClient:
{ name: '86fqA33Wg:core.88fc.2.us-east-2-A.i-0408b626ded248566.86fqA33WgA5Gik',
href: '/redis/clients/86fqA33Wg',
quickstatus: true } } ],
pendingLocate: false }
```

So what that seems to indicate is that `fluentd` is indeed receiving the data correctly via the incoming tcp source but it is getting mangled pretty early on within fluentd. Note I have tried removing additional plugins in case they are interfering, and am left now with:

```

@type tcp
tag incoming
port <%= ENV["ACCEPT_PORT"] %>
bind 0.0.0.0
format /^(?

@type record_transformer
enable_ruby

source ${record['ident'][0..6] == "docker/" ? record['ident'].split("/")[1] : record['ident']}
container_type ${record['ident'].split("/")[1]}
container_name ${record['ident'].split("/")[2]}
container_id ${record['ident'].split("/")[3]}

@type parse_message
format /^([\w\._-]*\s*\[(?
```

I tried this again with `0.14.0` which I was previously using and the issue has gone away. Unfortunately now my ElasticSeatch indices are corrupted because time fields have now had non-time values added to them.

Few thoughts:

* Clearly there is a regression, I would be happy to try again in the future if you find the problem.
* When the log entry failed to parse, it sort of resulted in DoS situation where rsyslog kept resending
the log entry and fluent kept refusing it, neither was going to give up. Should fluentd eventually reject the same log entry and move on, at least with an option of some sort to allow that?

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.