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.

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

Adapt Console::Logger to Fluent::Log #3987

Merged
merged 13 commits into from
Jan 23, 2023
Merged

Adapt Console::Logger to Fluent::Log #3987

merged 13 commits into from
Jan 23, 2023

Conversation

ashie
Copy link
Member

@ashie ashie commented Dec 14, 2022

Which issue(s) this PR fixes:
N/A

What this PR does / why we need it:
The log mechanism of Async gem was changed as of async-1.17. Async gem is used in http_server helper of Fluentd. From async-1.17 it uses Console::Logger of Console gem which isn't compatible with Ruby's standard Logger. So we need to adapt it to our logger mechanism to output Async's log correctly.

For example sometimes following error is occurred on CI without this patch:
#3842 (comment)

2022-07-01T01:29:37.2657850Z 	from /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:242:in `fail!'
2022-07-01T01:29:37.2658430Z Failure: test: with insecure in transport section(HttpHelperTest::Create a HTTP server::create a HTTPS server::#http_server_create_https_server)
2022-07-01T01:29:37.2694380Z 	from /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:267:in `rescue in block in make_fiber'
2022-07-01T01:29:37.2694980Z /Users/runner/work/fluentd/fluentd/test/plugin_helper/test_http_server_helper.rb:296:in `block (5 levels) in <class:HttpHelperTest>'
2022-07-01T01:29:37.2786170Z 	from /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:264:in `block in make_fiber'
2022-07-01T01:29:37.2786710Z      293:             assert_equal('200', resp.code)
2022-07-01T01:29:37.2820540Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-io-1.33.0/lib/async/io/generic.rb:216:in `accept_nonblock': SSL_accept returned=1 errno=0 state=error: tlsv1 alert unknown ca (OpenSSL::SSL::SSLError)
2022-07-01T01:29:37.2821140Z      294:             assert_equal('hello get', resp.body)
2022-07-01T01:29:37.2823720Z 	from /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-io-1.33.0/lib/async/io/generic.rb:216:in `async_send'
2022-07-01T01:29:37.2824260Z      295: 
2022-07-01T01:29:37.2826690Z 	from /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-io-1.33.0/lib/async/io/generic.rb:62:in `block in wrap_blocking_method'
2022-07-01T01:29:37.2827090Z   => 296:             assert_raise OpenSSL::SSL::SSLError do
2022-07-01T01:29:37.2828630Z 	from /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-io-1.33.0/lib/async/io/ssl_socket.rb:143:in `block in accept'
2022-07-01T01:29:37.2830080Z      297:               secure_get("https://127.0.0.1:#{@port}/example/hello")
2022-07-01T01:29:37.2903090Z 	from /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:261:in `block in make_fiber'
2022-07-01T01:29:37.2903440Z      298:             end
2022-07-01T01:29:37.2974280Z      299:           end
2022-07-01T01:29:37.2980450Z /Users/runner/work/fluentd/fluentd/test/plugin_helper/test_http_server_helper.rb:36:in `on_driver'
2022-07-01T01:29:37.2983740Z /Users/runner/work/fluentd/fluentd/test/plugin_helper/test_http_server_helper.rb:66:in `on_driver_transport'
2022-07-01T01:29:37.2984210Z /Users/runner/work/fluentd/fluentd/test/plugin_helper/test_http_server_helper.rb:286:in `block (4 levels) in <class:HttpHelperTest>'
2022-07-01T01:29:37.2984460Z 
2022-07-01T01:29:37.2987480Z <OpenSSL::SSL::SSLError> expected but was
2022-07-01T01:29:37.2989170Z <ArgumentError(<wrong number of arguments (given 3, expected 0..1)>)
2022-07-01T01:29:37.2989610Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/2.7.0/logger.rb:536:in `warn'
2022-07-01T01:29:37.2990540Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:242:in `fail!'
2022-07-01T01:29:37.2991210Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:267:in `rescue in block in make_fiber'
2022-07-01T01:29:37.2992000Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:264:in `block in make_fiber'
2022-07-01T01:29:37.2992290Z >
2022-07-01T01:29:37.2992390Z 
2022-07-01T01:29:37.2992450Z diff:
2022-07-01T01:29:37.2992690Z ? Op   enSSL::SSL::SSLError                                                      
2022-07-01T01:29:37.2992980Z ? Argum  t                 (<wrong number of arguments (given 3, expected 0..1)>)
2022-07-01T01:29:37.2993260Z ? ??  ?????????????                 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
2022-07-01T01:29:37.2993530Z + /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/2.7.0/logger.rb:536:in `warn'
2022-07-01T01:29:37.2994060Z + /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:242:in `fail!'
2022-07-01T01:29:37.2994730Z + /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:267:in `rescue in block in make_fiber'
2022-07-01T01:29:37.2995800Z + /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/gems/2.7.0/gems/async-1.30.3/lib/async/task.rb:264:in `block in make_fiber'

Docs Changes:
N/A

Release Note:

  • http_server helper, in_monitor_agent: Fix a crash when outputting Async gem's log

@ashie
Copy link
Member Author

ashie commented Dec 14, 2022

It's still early draft.

@ashie ashie changed the title Add a wapper for Console::Serialized::Logger to output Async's log Adapt Console::Logger to Fluent::Log Jan 2, 2023
@ashie ashie marked this pull request as ready for review January 3, 2023 09:08
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
@ashie
Copy link
Member Author

ashie commented Jan 17, 2023

CI errors on Ruby Head aren't concerned with this PR.

@ashie ashie requested review from daipom and removed request for daipom January 17, 2023 02:30
@daipom
Copy link
Contributor

daipom commented Jan 17, 2023

I'll see this today!

@ashie
Copy link
Member Author

ashie commented Jan 17, 2023

I'm not sure exactly which versions of async, cosole and td-agent are affected yet.

Copy link
Contributor

@daipom daipom left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm seeing this fix, the async gem, and the console gem.

It certainly looks like the async is starting to use the console as of async-1.17, but at that point, the async seems to be using directly the logger passed in the constructor.

I don't know for sure, but from the code, it seems like the behavior would be doubtful as of async-1.29.0.

socketry/async@d0546a4

Anyway, I understand the overall situation. I will see some more.

@ashie
Copy link
Member Author

ashie commented Jan 17, 2023

I don't know for sure, but from the code, it seems like the behavior would be doubtful as of async-1.29.0.

socketry/async@d0546a4

Anyway, I understand the overall situation. I will see some more.

Yeah, it's been about half a year since I noticed such behaviour change.
So probably the changed version is not so old like 1.17.

@daipom
Copy link
Contributor

daipom commented Jan 17, 2023

Even though the async was using directly the logger passed, it was using the logger in this way.

https://github.com/socketry/async/blob/v1.17.1/lib/async/reactor.rb#L201

logger.debug(self) {"Exiting run-loop because #{$! ? $! : 'finished'}."}

So, as the fluentd logger, it would log something like this.
(logger.info(self) { "message" })

2023-01-17 17:27:35 +0900 [info]: #0 [Hoge] #<Fuga:0x0000...>message

@ashie
Copy link
Member Author

ashie commented Jan 17, 2023

Ah, I got it.
It might be only a test's issue.

In the failed test, the test passes Ruby's Logger to Async::Reactor.new:

NULL_LOGGER = Logger.new(nil)

The signature of Logger#warn is warn(progname = nil) { ... }, therefore it can't receive 2 or more arguments:
https://docs.ruby-lang.org/ja/latest/class/Logger.html#I_WARN

But the signature of Fluent::Log is warn(*args, &block):

def warn(*args, &block)

Although the failed test passes incompatible logger, it should pass Fluent::Log.

@ashie
Copy link
Member Author

ashie commented Jan 17, 2023

But strictly speaking, the signature of Fluent::Log isn't compatible with Console::Logger too.
So this patch might be better than before in anyway.

@daipom
Copy link
Contributor

daipom commented Jan 17, 2023

In the failed test, the test passes Ruby's Logger to Async::Reactor.new:

NULL_LOGGER = Logger.new(nil)

Wow!! Indeed!!

But strictly speaking, the signature of Fluent::Log isn't compatible with Console::Logger too. So this patch might be better than before in anyway.

I agree! The current implementation could be an error in the future.

Signed-off-by: Takuro Ashie <ashie@clear-code.com>
Signed-off-by: Takuro Ashie <ashie@clear-code.com>
@daipom
Copy link
Contributor

daipom commented Jan 19, 2023

We can confirm the behavior as following.

config

<source>
 @type monitor_agent
</source>

Run Fluentd and the following command.

$ curl http://localhost:24220/api/plugins

The logs being outputted through acync are as follows.

  • master
[debug]: #0 fluent/log.rb:309:debug: Async::IO::SocketBinding to #<Addrinfo: 0.0.0.0:24220 TCP>
[info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0
[debug]: #0 fluent/log.rb:309:debug: #<Async::HTTP::Server:0x0000561ac9236380>Incoming connnection from #<Addrinfo: 127.0.0.1:40486 TCP> to Async::HTTP::Protocol::HTTP1
  • this PR
[debug]: #0 fluent/log.rb:309:debug:   0.0s: Async::IO::Socket
      | Binding to #<Addrinfo: 0.0.0.0:24220 TCP>
[info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0
[debug]: #0 fluent/log.rb:309:debug:  5.15s: Async::HTTP::Server
      | Incoming connnection from #<Addrinfo: 127.0.0.1:43824 TCP> to Async::HTTP::Protocol::HTTP1

@daipom
Copy link
Contributor

daipom commented Jan 19, 2023

I think this implementation is fine, but I have one question about using Console::Terminal::Logger.

It seems that we can create the adapter without it, such as the following.

require 'console/logger'

module Fluent
  class Log
    # Async gem which is used by http_server helper switched logger mechanism to
    # Console gem which isn't complatible with Ruby's standard Logger (since
    # v1.17). This class adapts it to Fluentd's logger mechanism.
    class ConsoleAdapter
      def self.wrap(logger)
        _, level = Console::Logger::LEVELS.find { |key, value|
          if logger.level <= 0
            key == :debug
          else
            value == logger.level - 1
          end
        }
        Console::Logger.new(ConsoleAdapter.new(logger), level: level)
      end

      def initialize(logger)
        @logger = logger
      end

      def verbose!; end

      def call(subject = nil, *arguments, name: nil, severity: 'info', **options, &block)
        if subject
          @logger.send(severity, *(["#{subject} "] + arguments), &block)
        else
          @logger.send(severity, *arguments, &block)
        end
      end
    end
  end
end

This can output logs similar to the conventional form.

[debug]: #0 fluent/log.rb:309:debug: Async::IO::Socket Binding to #<Addrinfo: 0.0.0.0:24220 TCP>
[info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0
[debug]: #0 fluent/log.rb:309:debug: #<Async::HTTP::Server:0x000055f607d47b20> Incoming connnection from #<Addrinfo: 127.0.0.1:49932 TCP> to Async::HTTP::Protocol::HTTP1

In terms of simply connecting to the fluentd logger, it could look like this.

On the other hand, through the Terminal::Logger, there seems to be an advantage to connecting to the fluentd logger more safely.

@ashie
Copy link
Member Author

ashie commented Jan 19, 2023

It seems that we can create the adapter without it, such as the following.

Console::Terminal::Logger formats arguments of call in their own way.
I'm not sure Fluent::Log can treat all of such complex things properly or not.
So I think using Terminal::Logger as-is is safer for it.

@daipom
Copy link
Contributor

daipom commented Jan 19, 2023

It seems that we can create the adapter without it, such as the following.

Console::Terminal::Logger formats arguments of call in their own way. I'm not sure Fluent::Log can treat all of such complex things properly or not. So I think using Terminal::Logger as-is is safer for it.

I understand!

Copy link
Contributor

@daipom daipom left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM!

@ashie
Copy link
Member Author

ashie commented Jan 19, 2023

[debug]: #0 fluent/log.rb:309:debug:   0.0s: Async::IO::Socket
      | Binding to #<Addrinfo: 0.0.0.0:24220 TCP>
[info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0
[debug]: #0 fluent/log.rb:309:debug:  5.15s: Async::HTTP::Server
      | Incoming connnection from #<Addrinfo: 127.0.0.1:43824 TCP> to Async::HTTP::Protocol::HTTP1

The last remaining concern for me is whether we should add our header to each line or not.
(for aligning indent of original message)

Signed-off-by: Takuro Ashie <ashie@clear-code.com>
@daipom
Copy link
Contributor

daipom commented Jan 19, 2023

[debug]: #0 fluent/log.rb:309:debug:   0.0s: Async::IO::Socket
      | Binding to #<Addrinfo: 0.0.0.0:24220 TCP>
[info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0
[debug]: #0 fluent/log.rb:309:debug:  5.15s: Async::HTTP::Server
      | Incoming connnection from #<Addrinfo: 127.0.0.1:43824 TCP> to Async::HTTP::Protocol::HTTP1

The last remaining concern for me is that we should add our header to each line or not. (for aligning indent of original message)

Like this?

[debug]: #0 fluent/log.rb:309:debug:   0.0s: Async::IO::Socket
[debug]: #0 fluent/log.rb:309:debug:      | Binding to #<Addrinfo: 0.0.0.0:24220 TCP>
[info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0
[debug]: #0 fluent/log.rb:309:debug:  5.15s: Async::HTTP::Server
[debug]: #0 fluent/log.rb:309:debug:      | Incoming connnection from #<Addrinfo: 127.0.0.1:43824 TCP> to Async::HTTP::Protocol::HTTP1

Is there any advantage in aligning the logs, destroying the original meaning of a single log as multiple lines?

@ashie
Copy link
Member Author

ashie commented Jan 19, 2023

Is there any advantage in aligning the logs, destroying the original meaning of a single log as multiple lines?

Fluent::Log adds header to each lines of stack trace (with indent):

fluentd/lib/fluent/log.rb

Lines 474 to 476 in 8df759b

backtrace.each { |msg|
puts [" ", line, msg].join
}

This is the motivation I thought it (but probably I won't do it for this).

@daipom
Copy link
Contributor

daipom commented Jan 19, 2023

Is there any advantage in aligning the logs, destroying the original meaning of a single log as multiple lines?

Fluent::Log adds header to each lines of stack trace (with indent):

fluentd/lib/fluent/log.rb

Lines 474 to 476 in 8df759b

backtrace.each { |msg|
puts [" ", line, msg].join
}

This is the motivation I thought it (but probably I won't do it for this).

I see!!

@ashie ashie requested a review from cosmo0920 January 20, 2023 00:03
@ashie
Copy link
Member Author

ashie commented Jan 20, 2023

There are also cases that output multiple lines without header in Fluentd's log, such as dumping Fluentd's config.
So I think we don't need to output header for this.

Copy link
Contributor

@cosmo0920 cosmo0920 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks reasonable for me. And added a nitpick comment. Just getting merged is OK for me.

test/log/test_console_adapter.rb Show resolved Hide resolved
@cosmo0920
Copy link
Contributor

@ashie @daipom Can we merge this? I'm OK for merging as-is.

@daipom
Copy link
Contributor

daipom commented Jan 22, 2023

Sure! I'm OK too.

@ashie ashie merged commit c48ca04 into master Jan 23, 2023
@ashie ashie deleted the console-logger-adapter branch January 23, 2023 04:07
@ashie
Copy link
Member Author

ashie commented Jan 23, 2023

Thanks for your review!

@ashie ashie added this to the v1.16.0 milestone Feb 9, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants