如需mongoid将运作信息打印出来，可在config/application.rb作如下设置

config.mongoid.logger = Logger.new($stdout) if Rails.env.development?

不过默认输出是截断的

[2] pry(main)> Expense.where(:id.in => ids).where(:_status.in => [:checking]).limit(2).pluck(:id)
D, [2019-03-11T11:24:05.624849 #6236] DEBUG -- : MONGODB | localhost:27017 | reimbursement_development.find | STARTED | {"find"=>"expenses", "filter"=>{"_id"=>{"$in"=>[BSON::ObjectId('5c6e599a6fc4f3326b5b8aea'), BSON::ObjectId('5c7f92086fc4f33908459afa'), BSON::ObjectId('5c7f93e66fc4f33908459b11'), BSON::ObjectId('5c80b9eb6fc4f317d841a69d')]}, "_status"=>{"$in"=>[:chec…

为了查明输出是在哪里被截断的，需要对logger的打印方法进行拦截

# ruby/2.5.0/logger.rb
def add(severity, message = nil, progname = nil)
  # ...
  @logdev.write(
    format_message(format_severity(severity), Time.now, progname, message))
  true
end

为免重写$stdout的write，从format_message入手。普通的Logger.new使用的是自带的Logger::Formatter，于是对其进行一些包装，对查询语句作拦截，并打印调用栈

class MyFormatter < SimpleDelegator
  def call severity, time, progname, msg
    if msg =~ /STARTED/
      puts "--------begin #{msg}---------"
      puts caller
      puts '-----------end-------------------------'
    end
    super
  end
end

config.mongoid.logger = Logger.new($stdout, formatter: MyFormatter.new(Logger::Formatter.new)) if Rails.env.development?

再执行一次，可得

[9] pry(main)> ids = Expense.where(:id.in => ids).where(:_status.in => [:checking]).limit(2).pluck(:id)
--------begin MONGODB | localhost:27017 | reimbursement_development.find | STARTED | {"find"=>"expenses", "filter"=>{"_id"=>{"$in"=>[BSON::ObjectId('5c6e599a6fc4f3326b5b8aea'), BSON::ObjectId('5c7f92086fc4f33908459afa')]}, "_status"=>{"$in"=>[:checking]}}, "limit"=>2, "projection"=>{"_id"=>1}, "lsid"=>{"id"=>}}---------
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/2.5.0/delegate.rb:85:in `method_missing'
/Users/yuanzhipeng/Projects/rebasing/reimbursement/config/application.rb:34:in `call'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/2.5.0/logger.rb:584:in `format_message'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/2.5.0/logger.rb:472:in `add'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/2.5.0/logger.rb:493:in `debug'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/loggable.rb:36:in `log_debug'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring/command_log_subscriber.rb:58:in `started'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring.rb:228:in `block in started'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring.rb:228:in `each'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring.rb:228:in `started'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring/publishable.rb:73:in `command_started'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring/publishable.rb:45:in `publish_command'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/server/connection.rb:143:in `dispatch'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/operation/shared/executable.rb:34:in `block in dispatch_message'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/server/connection_pool.rb:110:in `with_connection'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/server.rb:251:in `with_connection'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/operation/shared/executable.rb:33:in `dispatch_message'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/operation/find/op_msg.rb:46:in `execute'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/operation/find.rb:43:in `execute'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/collection/view/iterable.rb:82:in `send_initial_query'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/collection/view/iterable.rb:42:in `block in each'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/retryable.rb:45:in `read_with_retry'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/collection/view/iterable.rb:40:in `each'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/query_cache.rb:222:in `each'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual/mongo.rb:440:in `reduce'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual/mongo.rb:440:in `pluck'
/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual.rb:20:in `pluck'
(pry):11:in `
'

先从started方法看起，可见日志的截断与否是根据options[:truncate_logs]来判断的

# mongo-2.6.2/lib/mongo/monitoring/command_log_subscriber.rb
module Mongo
  class Monitoring
    class CommandLogSubscriber
      def initialize(options = {})
        @options = options
      end

      def started(event)
        if logger.debug?
          log_debug("#{prefix(event)} | STARTED | #{format_command(event.command)}")
        end
      end

      def format_command(args)
        begin
          truncating? ? truncate(args) : args.inspect
        rescue Exception
          ''
        end
      end

      def truncate(command)
        ((s = command.inspect).length > LOG_STRING_LIMIT) ? "#{s[0..LOG_STRING_LIMIT]}..." : s
      end

      def truncating?
        @truncating ||= (options[:truncate_logs] != false)
      end
    end
  end
end

于是在initialize方法打上binding.pry，再执行一次查询并检查调用栈，得

[1] pry(#)> caller
=> [
# ...
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring/command_log_subscriber.rb:45:in `initialize'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring.rb:209:in `new'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/monitoring.rb:209:in `initialize'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/client.rb:282:in `new'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongo-2.6.2/lib/mongo/client.rb:282:in `initialize'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/clients/factory.rb:64:in `new'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/clients/factory.rb:64:in `create_client'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/clients/factory.rb:27:in `create'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/clients.rb:69:in `block in with_name'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/clients.rb:68:in `synchronize'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/clients.rb:68:in `with_name'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/persistence_context.rb:114:in `client'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/persistence_context.rb:70:in `collection'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/clients/options.rb:73:in `collection'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual/mongo.rb:342:in `initialize'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual.rb:53:in `new'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual.rb:53:in `create_context'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual.rb:35:in `context'",
"/Users/yuanzhipeng/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/mongoid-7.0.2/lib/mongoid/contextual.rb:20:in `pluck'",
"(pry):1:in `
’",

预计options应该是在client到clients之间生成，于是挑中间一个看看，就factory吧

# mongoid-7.0.2/lib/mongoid/clients/factory.rb
module Mongoid
  module Clients
    module Factory
      extend self

      def create(name = nil)
        return default unless name
        config = Mongoid.clients[name]
        raise Errors::NoClientConfig.new(name) unless config
        create_client(config)
      end

检查Mongoid.clients[name]，得

[2] pry(#)> Mongoid.clients
=> {"default"=>{"database"=>"reimbursement_development", "hosts"=>["localhost:27017"], "options"=>nil}}

看着像是config/mongoid.yml的配置，于是加上truncate_logs: false，再执行一次查询

[2] pry(main)> Expense.where(:id.in => ids).where(:_status.in => [:checking]).limit(2).pluck(:id)
D, [2019-03-11T14:20:54.923038 #9874] DEBUG -- : MONGODB | localhost:27017 | reimbursement_development.find | STARTED | {"find"=>"expenses", "filter"=>{"_id"=>{"$in"=>[BSON::ObjectId('5c6e599a6fc4f3326b5b8aea'), BSON::ObjectId('5c7f92086fc4f33908459afa'), BSON::ObjectId('5c7f93e66fc4f33908459b11'), BSON::ObjectId('5c80b9eb6fc4f317d841a69d')]}, "_status"=>{"$in"=>[:checking]}}, "limit"=>2, "projection"=>{"_id"=>1}, "lsid"=>{"id"=>}}
D, [2019-03-11T14:20:54.925215 #9874] DEBUG -- : MONGODB | localhost:27017 | reimbursement_development.find | SUCCEEDED | 0.002s
=> []

成功显示完整查询

至于其中的lsid是什么，也来看下。在started方法打上binding.pry检查caller。找了一轮，估计是数据库的session id，考虑到这个键如此独特，直接在源码搜lsid，得

# mongo-2.6.2/lib/mongo/session.rb
def add_id!(command)
  command.merge!(lsid: session_id)
end

确实是session id