Custom logging middleware

[charneykaye]

I'm building a Golang app that implements a Sidekiq-compatible jrallison/go-workers work queue and a custom logging wrapper around Sirupsen/logrus for marshaled JSON logs.

Now, all of my app (except for go-workers so far) uses my logger-wrapper in a central place to ensure that 100% of its output is JSON compatible.

Note that lines #1 and #2 are proper JSON from our central logger, but when go-workers initializes we see line #3 come from the wrong logger in plain text.

{"db":{"Mapper":{}},"instance_id":"1","level":"info","msg":"Db: Connected to MySQL","time":"2015-05-27T04:15:15-04:00"}
{"concurrency":10,"instance_id":"1","level":"info","msg":"Worker: Commencing work","time":"2015-05-27T04:15:15-04:00"}
workers: 2015/05/27 04:15:15.211217 processing queue contact with 10 workers.

And when we send the signal to close the program, we see first on line #1 the wrong logger in plain text, followed by the proper JSON from our central logger on line #2.

^C
workers: 2015/05/27 04:15:17.197504 quitting queue contact (waiting for 0 / 10 workers).
{"instance_id":"1","level":"info","msg":"Closed correctly","time":"2015-05-27T04:15:17-04:00"}

I cannot seem to get this custom MiddlewareLogging to replace the go-workers default logging middleware.

func (a *App) ConfigureWorkers() {
  workers.Middleware = workers.NewMiddleware(
    &WorkMiddleware{ App: a },
    )
}

type WorkMiddleware struct{
  App *App
}

func (m *WorkMiddleware) Call(queue string, message *workers.Msg, next func() bool) (acknowledge bool) {
  // before each message is processed:
  job_json := message.Args().GetIndex(0).MustString()
  job := ContactJob{}
  err := json.Unmarshal([]byte(job_json), &job)
  if err != nil {
  m.App.Log.WithFields( log.Fields{
    "job_json": job_json,
    }).Fatal("Worker: Could not Unmarshal job JSON")
    return
  }
  SetMessageJob(message, job)
  start := time.Now()
  m.App.Log.WithFields( log.Fields{
    "job_id": message.Jid(),
    "queue": queue,
    "args": message.Args(),
    }).Print("Work: Job Starting")
  defer func() {
    if e := recover(); e != nil {
      buf := make([]byte, 4096)
      buf = buf[:runtime.Stack(buf, false)]
      m.App.Log.WithFields( log.Fields{
          "job_id": message.Jid(),
          "queue": queue,
          "duration": time.Since(start),
          "error": e,
          "stack": buf,
        }).Fatal("Work: Job Failed")
    }
  }()
  acknowledge = next()
  result := GetMessageResult(message)
  m.App.Log.WithFields( log.Fields{
    "job_id": message.Jid(),
    "result": result,
    "queue": queue,
    "duration": time.Since(start),
    }).Print("Work: Job Done")
  return
}

Is it actually possible to replace the default go-workers logging middleware for those lines?

[charneykaye]

Posted http://stackoverflow.com/questions/30476990/golang-go-workers-custom-logging-middleware

[jrallison]

Hey @nickckaye ,

It looks like you're replacing the worker logging middleware (which logs information about each and every message processed by your workers).

The only logging I see in your output is the processing/quitting log entries from the manager which are logged on startup and shutdown.

go-workers/manager.go

Line 47 in 571e6b3

Logger.Println("processing queue", m.queueName(), "with", m.concurrency, "workers.")

If you'd like these to not be logged, you may want to replace workers.Logger with an object that meets the WorkersLogger interface, but doesn't actually log anything (... or perhaps for your use-case, logs it in JSON format).

type WorkersLogger interface {
    Println(...interface{})
    Printf(string, ...interface{})
}

Something like this would simply remove those log entries (assuming it compiles):

type MyLogger struct {
}

func (l *MyLogger) Println(v ...interface{}) {
  // noop
}
func (l *MyLogger) Printf(fmt string, v ...interface{}) {
  // noop
}

workers.Logger = &MyLogger{}

Hope that helps!

[jrallison]

Also note that the default logging middleware uses workers.Logger itself:

https://github.com/jrallison/go-workers/blob/2aae4d367bfac8d2c9267d3212300df400599717/middleware_logging.go

So, simply replacing workers.Logger with something that formats the information as JSON before logging may be an option for you as well.

[charneykaye]

Thanks @jrallison ! Quote on http://stackoverflow.com/questions/30476990/golang-go-workers-custom-logging-middleware/30493680#30493680 for future wanderers.