job_worked logs unavailable unless level is debug

[bgentry]

It seems that it's not possible to get Que to output logs when jobs are worked, unless the level is set to debug. Unfortunately this also makes my logs very verbose including all SQL queries.

I believe this used to be part of the default logging setup pre-1.0. Maybe these can be altered to be :info level logs, or offer some way to get these to see that the queue is processing even if nothing goes wrong?

Or would you recommend that this be done by extending the job class?

[chanks]

Hmm, I'm not sure... I definitely get the desire to see some logging output, but my tendency these days is to be pretty stringent with logs, and only log to INFO something that I expect someone to take notice of. For instance, I have a bit of generic job tooling right now that looks like:

# As general goals, try to have jobs finish in under ten seconds...
def log_warn_runtime_threshold
  10
end

# And preferably in under five.
def log_info_runtime_threshold
  5
end

def run(*args)
  start = Time.now
  super # run job
  elapsed = Time.now - start

  log_level =
    if elapsed > log_warn_runtime_threshold
      :warn
    elsif elapsed > log_info_runtime_threshold
      :info
    end

  if log_level
    LOGGER.send log_level, "#{self.class} finished in #{elapsed.round(2)}s (#{args.inspect})"
  end
end

I do this because I feel like I'd want to be generally aware if this job were creeping up past five seconds, and then get an even stronger warning if it passed ten. That said, I haven't actually deployed this yet, so it may wind up being impractical to treat the INFO level that way.

On the other hand, if this feature seems useful, I could see integrating it into the core library and making those log levels/thresholds configurable - that way it'd be simple to set the INFO threshold to 0 and get a notice at that level every time a job ran.

I'm not sure, it's worth thinking about.

[bgentry]

Yeah, I could totally see the argument for this being separate from the main library in order for it to be more flexible. The only decent argument I have to keep it in Que is that you're already doing this job timing work, so why make users do it themselves? But I'll concede it's a weak point.

I'm fine with adding my own logging + instrumentation if you think that's the right path.

[chanks]

I don't know, I think if nothing changes this will be a common complaint. And it feels pretty reasonable.

Tomorrow is my open source day at work, and I'll be looking at bit at the single-worker case in the other issue you brought up. I'll also look through the logging logic and see what feels right, I suppose.

[chanks]

Sorry for the delay, work's been crazy, but I'm on vacation next week and wanted to wrap this up before then 😄

I just added a log_level job method to support configuring this log level, see the logging docs for info on how to use it. It may still make sense to change the default from DEBUG to INFO, but we'll see what people think about it. Anyway, that change is in 1.0.0.beta3, which was just released.