Encoding::UndefinedConversionError
FraLarghi opened this issue · 2 comments
FraLarghi commented
Hi everyone,
I've a problem with my setup.
I've several input source that have as output an instance of mongo output configured like that:
<match logs.**>
@type mongo_replset
nodes localhost:27017
replica_set rset
database logs
collection ${tag}
user *******************
password ******************
ignore_invalid_record true
replace_dot_in_key_with _
replace_dollar_in_key_with _
<buffer>
@type file
path /opt/fluentd/fluentd.buffer
flush_interval 5s
flush_thread_count 8
</buffer>
</match>
A remarkable amount of logs trigger this output making the buffer busy:
2019-11-26 12:40:58 +0000 [warn]: #6 failed to flush the buffer. retry_time=2 next_retry_seconds=2019-11-26 12:41:00 +0000 chunk="59830b931c7f26bf9ee843a60f8d9f55" error_class=Encoding::UndefinedConversionError error="\"\\xE2\" from ASCII-8BIT to UTF-8"
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/bson-4.6.0/lib/bson/string.rb:49:in `encode'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/bson-4.6.0/lib/bson/string.rb:49:in `put_string'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/bson-4.6.0/lib/bson/string.rb:49:in `to_bson'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/bson-4.6.0/lib/bson/hash.rb:42:in `put_hash'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/bson-4.6.0/lib/bson/hash.rb:42:in `to_bson'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/serializers.rb:326:in `serialize'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/serializers.rb:287:in `block in serialize'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/serializers.rb:286:in `each'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/serializers.rb:286:in `serialize'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/serializers.rb:175:in `block in serialize'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/serializers.rb:168:in `each'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/serializers.rb:168:in `serialize'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/message.rb:241:in `block in serialize_fields'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/message.rb:229:in `each'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/message.rb:229:in `serialize_fields'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/message.rb:125:in `serialize'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/protocol/msg.rb:103:in `serialize'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server/connection.rb:275:in `block in write'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server/connection.rb:274:in `each'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server/connection.rb:274:in `write'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server/connection.rb:229:in `deliver'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server/connection.rb:144:in `block in dispatch'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/monitoring/publishable.rb:48:in `publish_command'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server/connection.rb:143:in `dispatch'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/operation/shared/executable.rb:34:in `block in dispatch_message'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server/connection_pool.rb:110:in `with_connection'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/server.rb:251:in `with_connection'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/operation/shared/executable.rb:33:in `dispatch_message'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/operation/insert/op_msg.rb:42:in `execute'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/operation/shared/write.rb:59:in `bulk_execute'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/bulk_write.rb:210:in `insert_one'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/bulk_write.rb:178:in `execute_operation'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/bulk_write.rb:62:in `block (3 levels) in execute'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/retryable.rb:158:in `legacy_write_with_retry'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/retryable.rb:106:in `write_with_retry'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/bulk_write.rb:61:in `block (2 levels) in execute'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/bulk_write.rb:59:in `each'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/bulk_write.rb:59:in `block in execute'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/cluster.rb:532:in `with_session'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/client.rb:550:in `with_session'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/bulk_write.rb:58:in `execute'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/collection.rb:532:in `bulk_write'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/mongo-2.6.4/lib/mongo/collection.rb:509:in `insert_many'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluent-plugin-mongo-1.3.0/lib/fluent/plugin/out_mongo.rb:265:in `operate'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluent-plugin-mongo-1.3.0/lib/fluent/plugin/out_mongo_replset.rb:40:in `block in operate'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluent-plugin-mongo-1.3.0/lib/fluent/plugin/out_mongo_replset.rb:47:in `rescue_connection_failure'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluent-plugin-mongo-1.3.0/lib/fluent/plugin/out_mongo_replset.rb:39:in `operate'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluent-plugin-mongo-1.3.0/lib/fluent/plugin/out_mongo.rb:182:in `write'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluent-plugin-mongo-1.3.0/lib/fluent/plugin/out_mongo_replset.rb:33:in `write'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:1125:in `try_flush'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:1431:in `flush_thread_run'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:461:in `block (2 levels) in start'
2019-11-26 12:40:58 +0000 [warn]: #6 /usr/lib/ruby/gems/2.5.0/gems/fluentd-1.7.4/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
I would like to have a setting or something to force these logs to be parsed skipping the non UTF-8 characters. I've already set ignore_invalid_record true but it doesn't affect this behavior.
Maybe something like text.encode('utf-8', :invalid => :replace, :undef => :replace, :replace => '').
Thank you so much for your time and support.
ganmacs commented
https://github.com/kataring/fluent-plugin-string-scrub may be helpful.
FraLarghi commented
Thank you for your tip.
Anyway it's very weird, it seems like it's not related to the conversion but with the available amount of ram.
When it has lots of ram on the machine the problem does not appear.
But when the available ram is very low (e.g. for high traffic throughput and mongodb using it to write), it suddenly starts to print this stacktrace many times (depending on the traffic), and keeps retrying to flush the chunks and eventually succeeds after a couple tries per chunk.
Maybe I'll try to reproduce the problem to be easier to understand, but here is an example of the output:
2019-11-27 15:22:05 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:06 +0000 [warn]: #3 [out_mongo] retry succeeded. chunk_id="598558ed1bbb307dfab0b5df
2019-11-27 15:22:06 +0000 [warn]: #3 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:07 +0000 chunk="598550e85de61c693db7620bd6460a58" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:06 +0000 [warn]: #3 suppressed same stacktrace
2019-11-27 15:22:06 +0000 [warn]: #2 [out_mongo] retry succeeded. chunk_id="598558edf6319e5e87c2f00d
2019-11-27 15:22:06 +0000 [warn]: #2 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:07 +0000 chunk="598550af14ff6b682e32fcc70d56ea8b" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:06 +0000 [warn]: #2 suppressed same stacktrace
2019-11-27 15:22:06 +0000 [warn]: #3 [out_mongo] failed to flush the buffer. retry_time=1 next_retry:07 +0000 chunk="598550e85de61c693db7620bd6460a58" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:06 +0000 [warn]: #3 suppressed same stacktrace
2019-11-27 15:22:06 +0000 [warn]: #6 [out_mongo] failed to flush the buffer. retry_time=1 next_retry:08 +0000 chunk="5985574f83c5f6a268a43da7bcb53ea2" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:06 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:06 +0000 [warn]: #6 [out_mongo] retry succeeded. chunk_id="598558eecc678c870f46d158
2019-11-27 15:22:07 +0000 [warn]: #6 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:08 +0000 chunk="5985574f83c5f6a268a43da7bcb53ea2" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:07 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:07 +0000 [warn]: #6 [out_mongo] retry succeeded. chunk_id="598558ef6e056d00beb08d29
2019-11-27 15:22:07 +0000 [warn]: #6 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:08 +0000 chunk="5985574f83c5f6a268a43da7bcb53ea2" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:07 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:07 +0000 [warn]: #2 [out_mongo] retry succeeded. chunk_id="598558ef03d626b2764d2c2b
2019-11-27 15:22:07 +0000 [warn]: #3 [out_mongo] retry succeeded. chunk_id="598558ef7c765f08c8bb2c30
2019-11-27 15:22:07 +0000 [warn]: #2 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:08 +0000 chunk="598550af14ff6b682e32fcc70d56ea8b" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:07 +0000 [warn]: #2 suppressed same stacktrace
2019-11-27 15:22:07 +0000 [warn]: #3 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:08 +0000 chunk="598550e85de61c693db7620bd6460a58" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:07 +0000 [warn]: #3 suppressed same stacktrace
2019-11-27 15:22:08 +0000 [warn]: #6 [out_mongo] failed to flush the buffer. retry_time=1 next_retry:09 +0000 chunk="5985574f83c5f6a268a43da7bcb53ea2" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:08 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:08 +0000 [warn]: #6 [out_mongo] retry succeeded. chunk_id="598558f0b9966ffa299091f7
2019-11-27 15:22:08 +0000 [warn]: #6 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:09 +0000 chunk="5985574f83c5f6a268a43da7bcb53ea2" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:08 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:08 +0000 [warn]: #2 [out_mongo] retry succeeded. chunk_id="598558f0ee54deedfb7c2341
2019-11-27 15:22:08 +0000 [warn]: #3 [out_mongo] retry succeeded. chunk_id="598558efe4474d8d2ea9cf0f
2019-11-27 15:22:08 +0000 [warn]: #2 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:09 +0000 chunk="598550af14ff6b682e32fcc70d56ea8b" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:08 +0000 [warn]: #2 suppressed same stacktrace
2019-11-27 15:22:08 +0000 [warn]: #3 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:09 +0000 chunk="598550e85de61c693db7620bd6460a58" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:08 +0000 [warn]: #3 suppressed same stacktrace
2019-11-27 15:22:09 +0000 [warn]: #3 [out_mongo] failed to flush the buffer. retry_time=1 next_retry:10 +0000 chunk="598550e85de61c693db7620bd6460a58" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:09 +0000 [warn]: #3 suppressed same stacktrace
2019-11-27 15:22:09 +0000 [warn]: #6 [out_mongo] failed to flush the buffer. retry_time=1 next_retry:10 +0000 chunk="5985574f83c5f6a268a43da7bcb53ea2" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:09 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:09 +0000 [warn]: #6 [out_mongo] failed to flush the buffer. retry_time=2 next_retry:11 +0000 chunk="5985574f83c5f6a268a43da7bcb53ea2" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:09 +0000 [warn]: #6 suppressed same stacktrace
2019-11-27 15:22:10 +0000 [warn]: #2 [out_mongo] failed to flush the buffer. retry_time=1 next_retry:11 +0000 chunk="598550af14ff6b682e32fcc70d56ea8b" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
2019-11-27 15:22:10 +0000 [warn]: #2 suppressed same stacktrace
2019-11-27 15:22:10 +0000 [info]: Received graceful stop
2019-11-27 15:22:10 +0000 [warn]: #3 [out_mongo] retry succeeded. chunk_id="598558f1ab0af80797adec18
2019-11-27 15:22:10 +0000 [warn]: #3 [out_mongo] failed to flush the buffer. retry_time=0 next_retry:11 +0000 chunk="598550e85de61c693db7620bd6460a58" error_class=Encoding::UndefinedConversionError er-8BIT to UTF-8"
Thank you again.