shoryukenでログを出力するにはRailsのloggerではなくshoryukenのloggerを使います。
Shoryuken.logger.info 'info message!'
出力はこんな感じ
2018-05-31T12:20:32Z 15481 TID-os902jxf0 ActiveJob/XxxWorker/xxxxx/0bf40d6f-e5a7-4459-bb8d-15b52d7632ea INFO: info message!
DEBUGログ
ちなみにshoryukenのDEBUGログを出すには起動時に-v
オプションをつけます。
bundle exec shoryuken -v -L ./log/shoryuken.log
DEBUGログを出力するようにすると、shoryukenがどのキューをとりに行ってどれくらい時間がかかったのかなどがわかります。
2018-05-30T08:02:29Z 23758 TID-owmmtcdr4 DEBUG: Ready: 25, Busy: 0, Active Queues: [["queue08", 1], ["queue07", 1], ["queue06", 1], ["queue05", 1], ["queue04", 1], ["queue03", 1], ["queue02", 1], ["queue01", 1], ["queue00", 1]]
2018-05-30T08:02:29Z 23758 TID-owmmtcdr4 DEBUG: Looking for new messages in queue00
2018-05-30T08:02:34Z 23758 TID-owmmtcdr4 DEBUG: Fetcher for queue00 completed in 5038.010815 ms
2018-05-30T08:02:34Z 23758 TID-owmmtcdr4 DEBUG: Paused queue00
2018-05-30T08:02:34Z 23758 TID-owmmob4i8 DEBUG: Unpaused queue00
2018-05-30T08:02:34Z 23758 TID-owmmob4i8 DEBUG: Firing 'dispatch' lifecycle event
2018-05-30T08:02:34Z 23758 TID-owmmob4i8 DEBUG: Ready: 25, Busy: 0, Active Queues: [["queue07", 1], ["queue06", 1], ["queue05", 1], ["queue04", 1], ["queue03", 1], ["queue02", 1], ["queue01", 1], ["queue00", 1], ["queue08", 1]]
2018-05-30T08:02:34Z 23758 TID-owmmob4i8 DEBUG: Looking for new messages in queue08
2018-05-30T08:02:39Z 23758 TID-owmmob4i8 DEBUG: Fetcher for queue08 completed in 5039.439127 ms
2018-05-30T08:02:39Z 23758 TID-owmmob4i8 DEBUG: Paused queue08
2018-05-30T08:02:39Z 23758 TID-owmmtcdr4 DEBUG: Unpaused queue08
2018-05-30T08:02:39Z 23758 TID-owmmtcdr4 DEBUG: Firing 'dispatch' lifecycle event