Util.logger log messages level logic is total mess

[piavlo]

Some logger messages log level do not make any sense
just a few examples from Worker class implementation:

Util.logger.error "GearmanRuby: Got job_assign with handle #{handle} and #{data.size} byte(s) " + ...
It should probably be debug or info, but certainly not and error.

Util.logger.debug "GearmanRuby: Sending work_fail for #{handle} to #{hostport}"
Util.logger.debug "GearmanRuby: Sending work_exception for #{handle} to #{hostport}"
Util.logger.debug "GearmanRuby: Exception: #{e}\n#{e.backtrace.join("\n")}\n"
Those should be error and certainly not debug

There are many more

do I get something wrong here?

Thanks

[bcobb]

I agree with that first one, for sure. The others I don't, though I'd be curious to hear what @raskchanky thinks. Gearman is designed to propagate failures and exceptions back to the server, so their occurrence is not indicative of an error -- at least, not of an error in gearman-ruby. This fits with Alex Miller's logging philosophy, which I think is quite sound.

Are there any other examples you've noticed? This is one area of many that really ought to be cleaned up, and I'm glad you started the discussion!

[raskchanky]

In general, my opinion is that if the client or worker is sending a valid gearman message, even if that message is work_fail or work_exception, then "error" is not the correct log level to use: "info" is probably most appropriate for those cases. "debug" should be reserved for excessively verbose logging that's not necessary unless the person viewing it is a developer trying to debug the library itself. Ruby exceptions should be logged as "error".

[piavlo]

Well I did check only the worker.rb code since this is where i needed to look in order to check exceptions handling, where exceptions sent back to gearmand server were never recieved on the clients runing foreground jobs - and thus never knew a job had failed.

In the following code of handle_job_assign

    exception = nil
    begin
      ret = ability.run(data, Job.new(sock, handle))
    rescue Exception => e
      exception = e
      Util.logger.debug "GearmanRuby: Exception: #{e}\n#{e.backtrace.join("\n")}\n"
    end

    cmd = if ret && exception.nil?
      Util.logger.debug "GearmanRuby: Sending work_complete for #{handle} with #{ret.to_s.size} byte(s) " +
        "to #{hostport}"
      [ Util.pack_request(:work_complete, "#{handle}\0#{ret.to_s}") ]
    elsif exception.nil?
      Util.logger.debug "GearmanRuby: Sending work_fail for #{handle} to #{hostport}"
      [ Util.pack_request(:work_fail, handle) ]
    elsif exception
      Util.logger.debug "GearmanRuby: Sending work_exception for #{handle} to #{hostport}"
      [ Util.pack_request(:work_exception, "#{handle}\0#{exception.message}") ]
    end

it catches an exception at writes at debug level not error.
Later it checks the return code from job and also checks if there was exception.
1)if job ended ok it sends work_complete and logs with debug level
2)If there was non ok return code and no exception it sends work_fail and log with debug level - of course this is not error in gearman-ruby - but the logged massage should be more like "warning" level
3)if there was exception to it sends work_exception(which is never received on the client side) and logs with debug level - afaiu this should be logged with "error" level. Though again exception does not mean there is a problem in gearman-ruby, for example I through exceptions in worker code then it receives wrong data in the job.

Still I think that cases 2) & 3) should logged at higher level than "info" - since I have a monitoring of the logs and want to receive alerts then there are "warnings" or "errors" so that I know there was a problem in worker doing some job. Of course if the client this a foreground jobs it can discover that there was a problem by a client itself, then it receives work_fail or work_exception (again which are never actually received from gearmand) , but for background jobs there is not simple way to get alerted then job fails.

Now regarding client not receiving work_exception there is an old invalid bug
https://bugs.launchpad.net/gearmand/+bug/405732
and specially the following comment
https://bugs.launchpad.net/gearmand/+bug/405732/comments/6
according to which gearman-ruby was changed to send work_warning & work_fails then worker code throws exception
since this is the correct behaviour, but according to the code i pasted above this never happens.
So I have made the following commit
piavlo@6089166
which does it - with this commit I get the wished behavior there I can discover on client side that job has failed.
So i'd be glad if this can be commited.