Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

in_tail: Skip setup failed watcher to avoid resource leak and log blo… #1752

Merged
merged 1 commit into from
Nov 16, 2017
Merged

in_tail: Skip setup failed watcher to avoid resource leak and log blo… #1752

merged 1 commit into from
Nov 16, 2017
+34 −5

Conversation

mururu
Copy link
Member

@mururu mururu commented Nov 15, 2017

…at. Backport #1742

@mururu
Copy link
Member Author

mururu commented Nov 15, 2017

@repeatedly After raising WatcherSetupError (by inserting io.seek(10000000000000000)) with this patch, stopping fluentd process by Ctrl-C takes too long time. @thread.join seems to be blocking.
I'll continue to investigate it, but if you have any idea, please let me know.

logs

$ bundle exec bin/fluentd -c s.conf
2017-11-15 20:54:24 +0900 [info]: reading config file path="s.conf"
2017-11-15 20:54:24 +0900 [info]: starting fluentd-0.12.40
2222222222222
2017-11-15 20:54:24 +0900 [info]: gem 'fluentd' version '0.12.40'
2017-11-15 20:54:24 +0900 [info]: adding match pattern="test" type="stdout"
2017-11-15 20:54:24 +0900 [info]: adding source type="tail"
2017-11-15 20:54:24 +0900 [warn]: 'pos_file PATH' parameter is not set to a 'tail' source.
2017-11-15 20:54:24 +0900 [warn]: this parameter is highly recommended to save the position to resume tailing.
2017-11-15 20:54:24 +0900 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    path /tmp/s.log
    format none
    read_from_head true
    tag test
  </source>
  <match test>
    @type stdout
  </match>
</ROOT>
2017-11-15 20:54:24 +0900 [warn]: Skip /tmp/s.log because unexpected setup error happens: seek error with /tmp/s.log: file_position = 0

sigdump result

Sigdump at 2017-11-15 20:56:15 +0900 process 53444 (bin/fluentd)
  Thread #<Thread:0x007fde5c07f070> status=run priority=0
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:34:in `block in dump_all_thread_backtrace'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /Users/yito/ruby/fluentdev/lib/fluent/root_agent.rb:132:in `join'
      /Users/yito/ruby/fluentdev/lib/fluent/root_agent.rb:132:in `block in shutdown'
      /Users/yito/ruby/fluentdev/lib/fluent/root_agent.rb:132:in `each'
      /Users/yito/ruby/fluentdev/lib/fluent/root_agent.rb:132:in `shutdown'
      /Users/yito/ruby/fluentdev/lib/fluent/engine.rb:241:in `shutdown'
      /Users/yito/ruby/fluentdev/lib/fluent/engine.rb:212:in `run'
      /Users/yito/ruby/fluentdev/lib/fluent/supervisor.rb:570:in `run_engine'
      /Users/yito/ruby/fluentdev/lib/fluent/supervisor.rb:162:in `block in start'
      /Users/yito/ruby/fluentdev/lib/fluent/supervisor.rb:366:in `main_process'
      /Users/yito/ruby/fluentdev/lib/fluent/supervisor.rb:339:in `block in supervise'
      /Users/yito/ruby/fluentdev/lib/fluent/supervisor.rb:338:in `fork'
      /Users/yito/ruby/fluentdev/lib/fluent/supervisor.rb:338:in `supervise'
      /Users/yito/ruby/fluentdev/lib/fluent/supervisor.rb:156:in `start'
      /Users/yito/ruby/fluentdev/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
      bin/fluentd:5:in `require'
      bin/fluentd:5:in `<top (required)>'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli/exec.rb:74:in `load'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli/exec.rb:74:in `kernel_load'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli/exec.rb:27:in `run'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli.rb:335:in `exec'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor.rb:359:in `dispatch'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli.rb:20:in `dispatch'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor/base.rb:440:in `start'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli.rb:11:in `start'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/exe/bundle:32:in `block in <top (required)>'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/friendly_errors.rb:121:in `with_friendly_errors'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/exe/bundle:24:in `<top (required)>'
      /Users/yito/.rbenv/versions/2.4.1/bin/bundle:22:in `load'
      /Users/yito/.rbenv/versions/2.4.1/bin/bundle:22:in `<main>'
  Thread #<Thread:0x007fde5d0d1ef0> status=sleep priority=0
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/cool.io-1.5.1/lib/cool.io/loop.rb:88:in `run_once'
      /Users/yito/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/cool.io-1.5.1/lib/cool.io/loop.rb:88:in `run'
      /Users/yito/ruby/fluentdev/lib/fluent/plugin/in_tail.rb:314:in `run'
  Thread #<Thread:0x007fde5d0ea5e0> status=sleep priority=0
      /Users/yito/ruby/fluentdev/lib/fluent/plugin/in_tail.rb:161:in `join'
      /Users/yito/ruby/fluentdev/lib/fluent/plugin/in_tail.rb:161:in `shutdown'
      /Users/yito/ruby/fluentdev/lib/fluent/root_agent.rb:126:in `block (2 levels) in shutdown'
  GC stat:
      count: 37
      heap_allocated_pages: 280
      heap_sorted_length: 297
      heap_allocatable_pages: 17
      heap_available_slots: 114129
      heap_live_slots: 107973
      heap_free_slots: 6156
      heap_final_slots: 0
      heap_marked_slots: 72650
      heap_eden_pages: 280
      heap_tomb_pages: 0
      total_allocated_pages: 280
      total_freed_pages: 0
      total_allocated_objects: 577057
      total_freed_objects: 469084
      malloc_increase_bytes: 3774736
      malloc_increase_bytes_limit: 16777216
      minor_gc_count: 32
      major_gc_count: 5
      remembered_wb_unprotected_objects: 419
      remembered_wb_unprotected_objects_limit: 838
      old_objects: 68259
      old_objects_limit: 136520
      oldmalloc_increase_bytes: 8476112
      oldmalloc_increase_bytes_limit: 16777216
  Built-in objects:
   114,129: TOTAL
    41,578: T_STRING
    22,679: T_IMEMO
    18,183: T_NODE
    15,200: T_ARRAY
     6,080: FREE
     2,825: T_CLASS
     2,434: T_OBJECT
     1,958: T_HASH
     1,455: T_DATA
       806: T_REGEXP
       224: T_SYMBOL
       219: T_ICLASS
       206: T_MODULE
       117: T_STRUCT
        64: T_FILE
        59: T_RATIONAL
        25: T_MATCH
         9: T_FLOAT
         7: T_BIGNUM
         1: T_COMPLEX

@repeatedly
Copy link
Member

stopping fluentd process by Ctrl-C takes too long time

Maybe, it is caused by refresh_interval. Old implementation raises an error and it stops callback execution.
But new implentation catches an error so callback works normally.

@repeatedly
Copy link
Member

To avoid it, original TimerWatcher is one way.

https://github.com/treasure-data/fluent-plugin-td-monitoring/blob/0202443ab9cf82d5ad0becf1a7114143a13caf1a/lib/fluent/plugin/in_td_monitor_agent.rb#L33

@repeatedly
Copy link
Member

Ah, wait. I noticed the in_tail's run calls Loop#run without blocking timeout.
Adding timeout value should resolve the problem like @loop.run(1).

@repeatedly
Copy link
Member

See https://github.com/fluent/fluentd/blob/v0.12/lib/fluent/plugin/in_forward.rb#L120

@mururu
Copy link
Member Author

mururu commented Nov 16, 2017

@repeatedly Thanks you for pointing out. Could you check it again?

@repeatedly repeatedly merged commit d2582c5 into v0.12 Nov 16, 2017
@repeatedly repeatedly deleted the backport-1742-to-v0.12 branch November 16, 2017 05:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@mururu @repeatedly