Bug 1857206
| Summary: | [logforward]error_class=ArgumentError error="time must be a Fluent::EventTime (or Integer): Float" | |||
|---|---|---|---|---|
| Product: | OpenShift Container Platform | Reporter: | Anping Li <anli> | |
| Component: | Logging | Assignee: | Vimal Kumar <vimalkum> | |
| Status: | CLOSED ERRATA | QA Contact: | Anping Li <anli> | |
| Severity: | high | Docs Contact: | ||
| Priority: | unspecified | |||
| Version: | 4.6 | CC: | aos-bugs, ewolinet, periklis, qitang, tmicheli, vimalkum | |
| Target Milestone: | --- | |||
| Target Release: | 4.6.0 | |||
| Hardware: | Unspecified | |||
| OS: | Unspecified | |||
| Whiteboard: | ||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | ||
| Doc Text: | Story Points: | --- | ||
| Clone Of: | ||||
| : | 1901505 (view as bug list) | Environment: | ||
| Last Closed: | 2020-10-27 16:14:38 UTC | Type: | Bug | |
| Regression: | --- | Mount Type: | --- | |
| Documentation: | --- | CRM: | ||
| Verified Versions: | Category: | --- | ||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | ||
| Cloudforms Team: | --- | Target Upstream Version: | ||
| Embargoed: | ||||
| Bug Depends On: | ||||
| Bug Blocks: | 1901505 | |||
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. Verified using PR. 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 |
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: