Methods for shutdown sequence called twice #1222

dimaqq · 2016-09-09T13:08:02Z

2016-09-09 13:05:38 +0000 [info]: shutting down output plugin type=:copy plugin_id="object:2b1675dfb4dc"
2016-09-09 13:05:38 +0000 [info]: shutting down output plugin type=:file plugin_id="turbolog"
2016-09-09 13:05:38 +0000 [info]: shutting down output plugin type=:loggly_buffered plugin_id="object:2b1676325584"
2016-09-09 13:05:38 +0000 [info]: shutting down output plugin type=:file plugin_id="turbolog"
2016-09-09 13:05:38 +0000 [info]: shutting down output plugin type=:loggly_buffered plugin_id="object:2b1676325584"
2016-09-09 13:05:38 +0000 [info]: shutting down filter plugin type=:stdout plugin_id="object:2b1675f79fac"
2016-09-09 13:05:38 +0000 [info]: closing input plugin type=:tail plugin_id="object:2b167625ca58"
2016-09-09 13:05:38 +0000 [info]: closing input plugin type=:tail plugin_id="object:2b1675f2f560"
2016-09-09 13:05:38 +0000 [info]: closing input plugin type=:tail plugin_id="object:2b1675f1c2bc"
2016-09-09 13:05:38 +0000 [info]: closing input plugin type=:forward plugin_id="docker-host"
2016-09-09 13:05:38 +0000 [info]: closing input plugin type=:http plugin_id="turbo"
2016-09-09 13:05:38 +0000 [info]: closing input plugin type=:tail plugin_id="object:2b1675f04914"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:loggly_buffered plugin_id="object:2b1676325584"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:file plugin_id="turbolog"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:file plugin_id="turbolog"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:copy plugin_id="object:2b1675dfb4dc"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:loggly_buffered plugin_id="object:2b1676325584"
2016-09-09 13:05:38 +0000 [warn]: unexpected error while closing on output plugin plugin=Fluent::FileOutput plugin_id="turbolog" error_class=IOError error="closed stream"
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer/file_chunk.rb:120:in `size'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer/file_chunk.rb:120:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:125:in `block (2 levels) in close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:124:in `each_pair'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:124:in `block in close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:116:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:449:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/event_emitter.rb:71:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:200:in `block (3 levels) in shutdown'
2016-09-09 13:05:38 +0000 [warn]: unexpected error while closing on output plugin plugin=LogglyOutputBuffred plugin_id="object:2b1676325584" error_class=IOError error="closed stream"
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer/file_chunk.rb:120:in `size'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer/file_chunk.rb:120:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:125:in `block (2 levels) in close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:124:in `each_pair'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:124:in `block in close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:116:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:449:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/event_emitter.rb:71:in `close'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:200:in `block (3 levels) in shutdown'
2016-09-09 13:05:38 +0000 [warn]: emit transaction failed: error_class=NoMethodError error="undefined method `emit_error_event' for nil:NilClass" tag="fluent.info"
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/filter_stdout.rb:46:in `rescue in block in filter_stream'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/filter_stdout.rb:42:in `block in filter_stream'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event.rb:100:in `each'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/filter_stdout.rb:41:in `filter_stream'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:171:in `block in filter_stream'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:171:in `each'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:171:in `reduce'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:171:in `filter_stream'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:152:in `emit_events'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:81:in `emit'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:165:in `block in log_event_loop'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:163:in `each'
  2016-09-09 13:05:38 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:163:in `log_event_loop'
2016-09-09 13:05:38 +0000 [error]: failed to emit fluentd's log event tag="fluent.info" event={"type"=>:copy, "plugin_id"=>"object:2b1675dfb4dc", "message"=>"shutting down output plugin type=:copy plugin_id=\"object:2b1675dfb4dc\""} error_class=NoMethodError error="undefined method `emit_error_event' for nil:NilClass"
2016-09-09 13:05:38 +0000 [warn]: emit transaction failed: error_class=NoMethodError error="undefined method `emit_error_event' for nil:NilClass" tag="fluent.info"
  2016-09-09 13:05:38 +0000 [warn]: suppressed same stacktrace

Fluentd 0.14.6
Output plugin with buffering

The text was updated successfully, but these errors were encountered:

repeatedly · 2016-09-09T15:19:31Z

Please paste your configuration.

dimaqq · 2016-09-09T15:53:35Z

<source>
    # FIXME doesn't work yet
    @type tail
    path /data/nginx/error.log
    pos_file /data/nginx-error-log.pos
    tag nginx.error
    format nginx # Do you have a custom format? You can write your own regex.
</source>

<source>
    # FIXME doesn't work yet
    @type tail
    path /data/nginx/access.log
    pos_file /data/nginx-access-log.pos
    tag nginx.access
    format json
</source>

<source>
    # FIXME doesn't work yet
    @type tail
    path /data/apache/error.log
    pos_file /data/apache-error-log.pos
    tag apache.error

    # per http://docs.fluentd.org/articles/common-log-formats
    # +tid +errorcode
    format /^\[[^ ]* (?<time>[^\]]*)\] \[((?<module>[^:\]]*):)?(?<level>[^\]]*)\] \[pid (?<pid>[^:\]]*)(:tid (?<tid>[^:\]]*))\] (\[client (?<client>[^\]]*)\] )?(?<errorcode>[A-Za-z0-9]*)?: (?<message>.*)$/
</source>

<source>
    @type tail
    path /data/apache/access.log
    pos_file /data/apache-access-log.pos
    tag apache.access

    # https://github.com/fluent/fluentd/blob/d8a40cdfc97c3f0197feff8ddfbb1a9df51bfd1b/lib/fluent/plugin/parser_apache2.rb
    # +requestid +ms
    # format /^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) \[(?<time>[^\]]*)\] (?<requestid>[^ ]+) (?<ms>[^ ]+) "(?<method>\S+)(?: +(?<path>[^\"]*?)(?: +\S*)?)?" (?<code>[^ ]*) (?<size>[^ ]*)(?: "(?<referer>[^\"]*)" "(?<agent>[^\"]*)")?$/
    format json
    # FIXME millisoconds are tricky, but are available now; alternatively we could leave that parsing to cloud
</source>

<source>
    @type  forward
    @id    docker-host
    port  24224
</source>

<source>
    @type http
    @id   turbo
    port 8080
    bind 0.0.0.0
    body_size_limit 32m
    keepalive_timeout 10s
</source>

<filter **>
    @type stdout
</filter>

<match **>
    @type copy
    <store>
        @type file
        @id   turbolog
        path         /data/data.*.log
        symlink_path /data/data.log
        append       true
        time_slice_format %Y%m%d
        time_slice_wait   10m
        time_format       %Y%m%dT%H%M%S%z
    </store>
    <store>
        @type loggly_buffered
        loggly_url https://logs-01.loggly.com/bulk/xxx-xxx-xxx-xxx-xxx/tag/fluentd
        time_precision_digits 6
        buffer_type file
        buffer_path /data/loggly-buffer
        flush_interval 5s
    </store>
</match>

repeatedly · 2016-09-10T17:06:08Z

I noticed your log contains duplicated close call.

2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:file plugin_id="turbolog"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:file plugin_id="turbolog"

Could you paste your entire fluentd log? I want to know setup log together.

tagomoris · 2016-09-12T07:22:05Z

There are two lines for "closing" loggly_buffered too, and twice for shutdown.

2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:loggly_buffered plugin_id="object:2b1676325584"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:file plugin_id="turbolog"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:file plugin_id="turbolog"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:copy plugin_id="object:2b1675dfb4dc"
2016-09-09 13:05:38 +0000 [info]: closing output plugin type=:loggly_buffered plugin_id="object:2b1676325584"

It is the reason why @repeatedly want to see the entire log to check the log messages of launching Fluentd process.

dimaqq · 2016-09-12T07:27:21Z

will do.

dimaqq · 2016-09-12T09:47:44Z

https://gist.github.com/dimaqq/d65aea5d7e4f3fcb54fcc55747cf363e

stack traces are different, but plugin is still closed twice.

repeatedly added the v0.14 label Sep 9, 2016

repeatedly assigned tagomoris Sep 9, 2016

tagomoris mentioned this issue Sep 12, 2016

Ensure strict mode is used for Oj parser. #1147

Merged

tagomoris changed the title ~~stack traces on shutdown~~ Methods for shutdown sequence called twice Sep 13, 2016

tagomoris mentioned this issue Sep 26, 2016

Lifecycle method called correctly once #1242

Merged

tagomoris closed this as completed in #1242 Sep 28, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Methods for shutdown sequence called twice #1222

Methods for shutdown sequence called twice #1222

dimaqq commented Sep 9, 2016

repeatedly commented Sep 9, 2016

dimaqq commented Sep 9, 2016

repeatedly commented Sep 10, 2016

tagomoris commented Sep 12, 2016

dimaqq commented Sep 12, 2016

dimaqq commented Sep 12, 2016

Methods for shutdown sequence called twice #1222

Methods for shutdown sequence called twice #1222

Comments

dimaqq commented Sep 9, 2016

repeatedly commented Sep 9, 2016

dimaqq commented Sep 9, 2016

repeatedly commented Sep 10, 2016

tagomoris commented Sep 12, 2016

dimaqq commented Sep 12, 2016

dimaqq commented Sep 12, 2016