search

fluent / fluentd

Fluentd: Unified Logging Layer (project under CNCF)
https://www.fluentd.org
Apache License 2.0
12.82k stars 1.34k forks source link

Flushing the buffer fails with `BSON::Error::UnserializableClass error="Value does not define its BSON serialized type: 1721203518"`. #4560

Open bjg2 opened 1 month ago

bjg2 commented 1 month ago

Describe the bug

Flushing the buffer fails with BSON::Error::UnserializableClass error="Value does not define its BSON serialized type: 1721203518".

I don't think it is related to the value mentioned in the string though, probably to the value in the 'to reproduce' part: -9223372036854776000. That is just a bit under -2^63, so it cannot be represented via long long, I guess ruby is using some weird type to represent it and does not know how to map that type to BSON value.

To Reproduce

Not as easy to reproduce, however, i had this log leave my application:

{"agent":"Go-http-client/1.1","boltName":"worker","clientTime":"2024-07-17T07:16:00.310Z","height":0,"host":"------","ip":"------","level":"warning","log":"BAJKA MOJ","renderHeight":-9223372036854776000,"renderWidth":1080,"smallerEdgeSize":1080,"time":"2024-07-17T07:16:00.331Z","width":0}

and similarily, in fluentd buffer it turned into this line

2024-07-17T07:19:54.549069355Z stdout F {"agent":"Go-http-client/1.1","boltName":"worker","clientTime":"2024-07-17T07:16:00.310Z","height":0,"host":"------","ip":"------","level":"warning","log":"BAJKA MOJ","renderHeight":-9223372036854776000,"renderWidth":1080,"smallerEdgeSize":1080,"time":"2024-07-17T07:16:00.331Z","width":0}

Expected behavior

To flush the buffer.

Your Environment

Inside the kubernetes

- Fluentd version: 1.16.2
- Package version: /
- Operating system: alpine linux 3.17.4
- Kernel version: 6.1.0-21-amd64

Your Configuration

# Inputs from container logs
<source>
  @type tail
  @id in_tail_container_logs
  path /var/log/containers/*.log
  exclude_path ["/var/log/containers/cilium*"]
  pos_file /var/log/fluentd.log.pos
  read_from_head
  tag kubernetes.*
  <parse>
    @type cri
  </parse>
</source>

# Merge logs split into multiple lines
<filter kubernetes.**>
  @type concat
  key message
  use_partial_cri_logtag true
  partial_cri_logtag_key logtag
  partial_cri_stream_key stream
  separator ""
</filter>

# Enriches records with Kubernetes metadata
<filter kubernetes.**>
  @type kubernetes_metadata
</filter>

# Prettify kubernetes metadata
<filter kubernetes.**>
  @type record_transformer
  enable_ruby
  <record>
    nodeName ${record.dig("kubernetes", "host")}
    namespaceName ${record.dig("kubernetes", "namespace_name")}
    podName ${record.dig("kubernetes", "pod_name")}
    containerName ${record.dig("kubernetes", "container_name")}
    containerImage ${record.dig("kubernetes", "container_image")}
  </record>
  remove_keys docker,kubernetes
</filter>

# Expands inner json
<filter kubernetes.**>
  @type parser
  format json
  key_name message
  reserve_data true
  remove_key_name_field true
  emit_invalid_record_to_error false
  time_format %Y-%m-%dT%H:%M:%S.%NZ
  time_key time
  keep_time_key
</filter>

# Mongodb keys should not have dollar or a dot inside
<filter kubernetes.**>
  @type rename_key
  replace_rule1 \$ [dollar]
</filter>

# Mongodb keys should not have dollar or a dot inside
<filter kubernetes.**>
  @type rename_key
  replace_rule1 \. [dot]
</filter>

# Outputs to log db
<match kubernetes.**>
  @type mongo

  connection_string "#{ENV['MONGO_ANALYTICS_DB_HOST']}"
  collection logs

  <buffer>
    @type file
    path /var/log/file-buffer
    flush_thread_count 8
    flush_interval 3s
    chunk_limit_size 32M
    flush_mode interval
    retry_max_interval 60
    retry_forever true
  </buffer>
</match>

Your Error Log

Repeats error like this

2024-07-17 08:15:36 +0000 [warn]: #0 failed to flush the buffer. retry_times=4 next_retry_time=2024-07-17 08:15:52 +0000 chunk="61d6c3bfefe0e8da2e643405f51a3c53" error_class=BSON::Error::UnserializableClass error="Value does not define its BSON serialized type: 1721200561"
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/bson-4.15.0/lib/bson/hash.rb:43:in `put_hash'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/bson-4.15.0/lib/bson/hash.rb:43:in `to_bson'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/protocol/caching_hash.rb:46:in `to_bson'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/protocol/msg.rb:332:in `block (2 levels) in validate_document_size!'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/protocol/msg.rb:331:in `any?'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/protocol/msg.rb:331:in `block in validate_document_size!'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/protocol/msg.rb:329:in `any?'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/protocol/msg.rb:329:in `validate_document_size!'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/protocol/msg.rb:156:in `serialize'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/sessions_supported.rb:264:in `block in build_message'
  2024-07-17 08:15:36 +0000 [warn]: #0 <internal:kernel>:90:in `tap'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/sessions_supported.rb:257:in `build_message'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/executable.rb:97:in `dispatch_message'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/insert/op_msg.rb:38:in `get_result'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/executable.rb:34:in `block (3 levels) in do_execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/response_handling.rb:108:in `add_server_diagnostics'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/executable.rb:33:in `block (2 levels) in do_execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/response_handling.rb:54:in `add_error_labels'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/executable.rb:32:in `block in do_execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/response_handling.rb:94:in `unpin_maybe'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/executable.rb:31:in `do_execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/executable_no_validate.rb:28:in `execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/write.rb:74:in `bulk_execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:247:in `insert_one'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:195:in `block in execute_operation'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/operation/shared/response_handling.rb:94:in `unpin_maybe'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:191:in `execute_operation'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:70:in `block (3 levels) in execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/retryable.rb:244:in `block in write_with_retry'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/server/connection_pool.rb:667:in `with_connection'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/server.rb:448:in `with_connection'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/retryable.rb:232:in `write_with_retry'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/3.1.0/forwardable.rb:238:in `write_with_retry'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:69:in `block (2 levels) in execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:66:in `each'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:66:in `block in execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/client.rb:1132:in `with_session'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/bulk_write.rb:64:in `execute'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/collection.rb:831:in `bulk_write'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/mongo-2.18.3/lib/mongo/collection.rb:806:in `insert_many'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/fluent-plugin-mongo-1.6.0/lib/fluent/plugin/out_mongo.rb:355:in `operate'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/fluent-plugin-mongo-1.6.0/lib/fluent/plugin/out_mongo.rb:205:in `write'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/fluentd-1.16.2/lib/fluent/plugin/output.rb:1225:in `try_flush'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/fluentd-1.16.2/lib/fluent/plugin/output.rb:1538:in `flush_thread_run'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/fluentd-1.16.2/lib/fluent/plugin/output.rb:510:in `block (2 levels) in start'
  2024-07-17 08:15:36 +0000 [warn]: #0 /usr/lib/ruby/gems/3.1.0/gems/fluentd-1.16.2/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

Additional context

Since logging that line almost none other logs were sent to the database. I have retry_forever set to true, not to lose logs if database is unreachable or in some kind of problem, but I would like to retry only on database and connection issues, not on this kind of issues.

I would like to be able to drop the logs that are problem with separate setting than database insert retrying (similar question here as well https://github.com/fluent/fluentd/issues/4258),

daipom commented 1 month ago

@bjg2 Thanks for the report. Sorry I haven't made time for #4258.

Looks like this is an issue of fluent-plugin-mongo.

4258 could possibly be the same.

I would like to be able to drop the logs that are problem with separate setting than database insert retrying (similar question here as well https://github.com/fluent/fluentd/issues/4258),

Fluentd has the feature: https://docs.fluentd.org/buffer#handling-unrecoverable-errors

However, looks like fluent-plugin-mongo does not handle the error BSON::Error::UnserializableClass as unrecoverable.

bjg2 commented 1 month ago

Thanks!

So, as far as I understand, these are probably issues for fluent-plugin-mongo (at least to tag the errors as unrecoverable)? But also, as far as I can see their github is not responsive https://github.com/fluent/fluent-plugin-mongo Any idea on the best next steps?

Thanks again!