Skip to content

Conversation

kares
Copy link
Contributor

@kares kares commented May 31, 2021

Why is this important?

Currently the plugin does not gather logs from the underlying RabbitMQ library in LS' log.
Some debug logging by the frontend (MarchHare) could be accessed (w an env property) but ends up on STDERR.
This PR integrates the underlying logging to be part of LS' logging mechanism


The first change is to redirect MachHare's logging to use the plugin.logger. This is useful for debug level logging, and respects the logging level set on the plugin.

Second logging improvement is to disable MarchHare's logging 'improvement' and simply use the RabbitMQ's ForgivingExceptionHandler to log exceptions, these are redirected (using SLF4J bridge) to LS logs and for unexpected errors include Java traces.

Finally, we slightly normalize the logging format on Ruby errors (till a proper logging support is provided by LS).

There's a few minor refactorings (HINT: we run integration specs), old option names such as
:timeout caused confusion in mapping the setting to the underlying RMQ ConnectionFactory property.

kares added 3 commits May 31, 2021 12:11
connected? is an alias to open? (which we already have)
it's confusing to have to check what they mean these map cleanly for the ConnectionFactory property names
@kares kares marked this pull request as ready for review June 1, 2021 15:23
* master: CI: keep re-using base docker-compose.yml (logstash-plugins#48)
@kares
Copy link
Contributor Author

kares commented Jun 1, 2021

... sample recovery (debug) log (also notice the com.rabbitmq.client.impl.ForgivingExceptionHandler logger) :

[2021-06-02T12:22:44,831][INFO ][logstash.javapipeline ][main] Pipeline started {"pipeline.id"=>"main"} [2021-06-02T12:22:44,885][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] Connecting to RabbitMQ {:vhost=>"/", :addresses=>["localhost:5672"], :username=>"guest", :automatic_recovery=>true, :password=>"guest", :connection_timeout=>0, :requested_heartbeat=>0} [2021-06-02T12:22:44,894][INFO ][logstash.agent ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]} [2021-06-02T12:22:45,196][INFO ][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] Connected to RabbitMQ {:url=>"amqp://guest:XXXXXX@localhost:5672/"} [2021-06-02T12:22:45,225][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] queue: declare! dur-no-policy-4 [2021-06-02T12:22:45,243][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600} [2021-06-02T12:22:45,297][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: register queue dur-no-policy-4 [2021-06-02T12:22:45,390][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: register consumer amq.ctag-0Npv9AsGT9FRmUaHjY6hfg [2021-06-02T12:23:55,962][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] session: begin automatic connection recovery #<Thread:0x7db01edf run> [2021-06-02T12:24:00,986][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] session: reconnecting_on_network_failures [2021-06-02T12:24:41,060][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] session: instantiating a new connection using a set of addresses: localhost:5672 [2021-06-02T12:24:41,063][WARN ][com.rabbitmq.client.impl.ForgivingExceptionHandler][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] An unexpected connection driver error occured (Exception message: Connection reset) [2021-06-02T12:24:46,081][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] session: instantiating a new connection using a set of addresses: localhost:5672 [2021-06-02T12:24:46,092][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] session: recover_shutdown_hooks [2021-06-02T12:24:46,097][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] session: recover_connection_block_hooks [2021-06-02T12:24:46,104][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: begin automatic connection recovery [2021-06-02T12:24:46,129][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: recover queue dur-no-policy-4 [2021-06-02T12:24:46,135][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] queue: declare! dur-no-policy-4 [2021-06-02T12:24:46,139][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: register queue dur-no-policy-4 [2021-06-02T12:24:46,144][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] Recovering binding {:exchange=>"sysmsg", :routing_key=>"#", :arguments=>nil} [2021-06-02T12:24:46,154][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: recover consumer amq.ctag-0Npv9AsGT9FRmUaHjY6hfg [2021-06-02T12:24:46,158][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: unregister consumer amq.ctag-0Npv9AsGT9FRmUaHjY6hfg [2021-06-02T12:24:46,165][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] channel: register consumer amq.ctag-0Npv9AsGT9FRmUaHjY6hfg [2021-06-02T12:24:46,172][DEBUG][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] Have 0 recovery completion hooks to run [2021-06-02T12:24:46,176][WARN ][logstash.inputs.rabbitmq ][main][bd61d256f9443030293ec15e94d8bbdb366d4b2b1365981e306c57169f19c71c] RabbitMQ connection was closed {:url=>"amqp://guest:XXXXXX@localhost:5672/", :automatic_recovery=>true, :cause=>com.rabbitmq.client.ShutdownSignalException: connection error; protocol method: #method<connection.close>(reply-code=320, reply-text=CONNECTION_FORCED - broker forced connection closure with reason 'shutdown', class-id=0, method-id=0)} 
@kares kares requested a review from andsel June 2, 2021 15:44
#
# NOTE: effectively redirects MarchHare's default std-out logging to LS
# (MARCH_HARE_LOG_LEVEL=debug no longer has an effect)
connection.instance_variable_set(:@logger, LoggerAdapter.new(logger))
Copy link
Contributor Author

@kares kares Jun 2, 2021

Choose a reason for hiding this comment

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

we do not pass :logger => logger to MarchHare directly to avoid info logging a (less-relevant) message.

Copy link

@andsel andsel left a comment

Choose a reason for hiding this comment

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

LGTM

The only concern is that MarchHare logs goes under the logstash.inputs.rabbitmq logger and this could potentially confuse the user, like in:

[2021-06-03T15:20:08,118][DEBUG][logstash.inputs.rabbitmq ][main][e78725282315e2c8afc972c397af7c336f135c4040a5c8ef1e74617e63d75b55] session: instantiating a new connection using a set of addresses: localhost:5672 

But now we can have that log the before got lost.

@kares kares merged commit fe6865e into logstash-plugins:master Jun 7, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

3 participants