Bug 1857206 - [logforward]error_class=ArgumentError error="time must be a Fluent::EventTime (or Integer): Float"
Summary: [logforward]error_class=ArgumentError error="time must be a Fluent::EventTime...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Logging
Version: 4.6
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
: 4.6.0
Assignee: Vimal Kumar
QA Contact: Anping Li
URL:
Whiteboard:
Depends On:
Blocks: 1901505
TreeView+ depends on / blocked
 
Reported: 2020-07-15 13:01 UTC by Anping Li
Modified: 2020-11-26 16:45 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1901505 (view as bug list)
Environment:
Last Closed: 2020-10-27 16:14:38 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github openshift cluster-logging-operator pull 605 0 None closed Bug 1857206: Use fluentd event time for processing logs to kafka 2021-02-09 14:27:16 UTC
Red Hat Product Errata RHBA-2020:4196 0 None None None 2020-10-27 16:14:57 UTC

Description Anping Li 2020-07-15 13:01:40 UTC
Description of problem:
Forword audit logs to kafka report the following errors:

2020-07-15 12:42:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="time must be a Fluent::EventTime (or Integer): Float" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:825:in `metadata'" tag="linux-audit.log". 



How reproducible:
 Always

Steps to Reproduce:
1. Forward audit logs to kafka 

apiVersion: logging.openshift.io/v1
kind: ClusterLogForwarder
metadata:
  name: instance
  namespace: openshift-logging
spec:
  outputs:
    - name: kafka
      url: tls://my-cluster-kafka-bootstrap.amq.svc.cluster.local:9092/topic-logging-audit
      type: kafka
  pipelines:
    - name: test-audit
      inputRefs:
      - audit
      outputRefs:
      - kafka

2. Check the fluentd pod logs
   oc logs fluentd-b7ndc

Actual results:

Setting each total_size_limit for 1 buffers to 19242572390 bytes
Setting queued_chunks_limit_size for each buffer to 2293
2020-07-15 12:42:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="time must be a Fluent::EventTime (or Integer): Float" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:825:in `metadata'" tag="linux-audit.log"
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:825:in `metadata'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:973:in `block in handle_stream_with_standard_format'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event.rb:196:in `block in each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event.rb:195:in `each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event.rb:195:in `each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:972:in `handle_stream_with_standard_format'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:882:in `execute_chunking'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:808:in `emit_buffered'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event_router.rb:97:in `emit_stream'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_relabel.rb:29:in `process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:797:in `emit_sync'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:61:in `block in process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:59:in `each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:59:in `each_with_index'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:59:in `process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/multi_output.rb:148:in `emit_sync'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event_router.rb:97:in `emit_stream'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_relabel.rb:29:in `process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:797:in `emit_sync'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:61:in `block in process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:59:in `each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:59:in `each_with_index'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_copy.rb:59:in `process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/multi_output.rb:148:in `emit_sync'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event_router.rb:97:in `emit_stream'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/out_relabel.rb:29:in `process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:797:in `emit_sync'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event_router.rb:160:in `emit_events'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/event_router.rb:97:in `emit_stream'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:451:in `receive_lines'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:569:in `wrap_receive_lines'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:803:in `block in handle_notify'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:847:in `with_io'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:783:in `handle_notify'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:779:in `block in on_notify'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:779:in `synchronize'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:779:in `on_notify'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:599:in `on_notify'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:573:in `attach'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:322:in `setup_watcher'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:353:in `block in start_watchers'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:339:in `each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:339:in `start_watchers'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:316:in `refresh_watchers'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/in_tail.rb:226:in `start'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/root_agent.rb:200:in `block in start'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/root_agent.rb:189:in `block (2 levels) in lifecycle'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/root_agent.rb:188:in `each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/root_agent.rb:188:in `block in lifecycle'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/root_agent.rb:175:in `each'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/root_agent.rb:175:in `lifecycle'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/root_agent.rb:199:in `start'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/engine.rb:248:in `start'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/engine.rb:147:in `run'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/supervisor.rb:592:in `block in run_worker'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/supervisor.rb:823:in `main_process'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/supervisor.rb:586:in `run_worker'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/command/fluentd.rb:338:in `<top (required)>'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/share/rubygems/rubygems/core_ext/kernel_require.rb:59:in `require'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/share/rubygems/rubygems/core_ext/kernel_require.rb:59:in `require'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/bin/fluentd:8:in `<top (required)>'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/bin/fluentd:23:in `load'
  2020-07-15 12:42:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/bin/fluentd:23:in `<main>'
2020-07-15 12:42:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="time must be a Fluent::EventTime (or Integer): Float" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:825:in `metadata'" tag="linux-audit.log"
  2020-07-15 12:42:06 +0000 [warn]: suppressed same stacktrace
2020-07-15 12:42:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="time must be a Fluent::EventTime (or Integer): Float" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:825:in `metadata'" tag="linux-audit.log"
  2020-07-15 12:42:06 +0000 [warn]: suppressed same stacktrace
2020-07-15 12:42:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="time must be a Fluent::EventTime (or Integer): Float" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.9.2/lib/fluent/plugin/output.rb:825:in `metadata'" tag="linux-audit.log"
  2020-07-15 12:42:06 +0000 [warn]: suppressed same stacktrace


Expected results:
The subscription status turns to 'Stale' after lose telemetry 3 hours
Additional info:

Comment 1 Periklis Tsirakidis 2020-07-16 09:11:20 UTC
FWIW, this issue is not related to kafka, but to fluentd collection of audit logs. Fluentd expected nanosecond granularity for event times. Maybe one of the plugins - listed above in the stacktrace - is misbehaving.

Comment 4 Anping Li 2020-07-23 17:27:19 UTC
Verified using PR.

Comment 6 errata-xmlrpc 2020-10-27 16:14:38 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (OpenShift Container Platform 4.6 GA Images), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:4196


Note You need to log in before you can comment on or make changes to this bug.