search

hybridgroup / gobot

Golang framework for robotics, drones, and the Internet of Things (IoT)
https://gobot.io
Other
8.96k stars 1.04k forks source link

Override the default log with logrus? #508

Open ferventgeek opened 6 years ago

ferventgeek commented 6 years ago

Is there a method to override the default import "log"? It would be really handy to ship framework log messages off to an IoT agitator along with my app logging, rather than have them inaccessible out on the device. Centralized logging may be out of scope, but I thought I'd ask.

trevrosen commented 6 years ago

I’ve actually wanted to do this for awhile. @deadprogam what say ye? There are a lot of good things we could do with better logging, but I’d want to make sure we deliberate a bit first on the best approach.

deadprogram commented 6 years ago

I think it is an excellent idea.

ferventgeek commented 6 years ago

Thanks. Easy may just be to allow drop in replacement Logs. Combining them into a logging interface would be cool, but as a start, just a method on a few of the major objects to update the log object. Thanks for this project. Oh, also I added a webhook to the API host, and overrode the "/" path. Super simple, so good. Gobot Metal, FTW.

trevrosen commented 6 years ago

528 might not be the final word here. But I thought it'd be valuable to write something up that helps to start a conversation toward some more intuitive leveled logging.

I'm thinking that it could be interesting to have the platforms (even maybe drivers?) adopt a convention for leveled logging such that there's always log in scope.

Honestly it could make sense to have this just be dot imported into gobot as long as the resulting API is small enough...

ferventgeek commented 5 years ago

Thanks, I'll test for #528.

gm42 commented 5 years ago

528 has been closed.

If moving to logrus is a too big task, can we consider allowing injection of a logger through an interface instead?

andygrunwald commented 5 years ago

Any push on this? Can we help somehow?

trevrosen commented 5 years ago

We can inject with an interface - but Gobot is a big lib and has several different "modes" of usage. How are you guys envisioning this would work?

gm42 commented 5 years ago

Most other libraries/frameworks allow to override the default logging mechanism with a call like SetLogger(...); so for gobot it could be either that or an option specified with a .WithOption(...) syntax.

trevrosen commented 5 years ago

Yup. I'm asking basically the scope you're trying to get to w/ this logger. In the robot abstraction? Common to all drivers?

If not Logrus, then what standard logger? (Unfortunately there's not a logger interface in the log package from stdlib to use as a standard)

andygrunwald commented 5 years ago

@gm42 Do you have a (code) example/project with the .WithOption API?

My goal is to use structured logging for gobot. By this, I can analyze the logs better / machine-readable.

In terms of scope: I believe this can be incremental though the gobot project. It doesn't need a big bang.

A detail/implementation question that comes to my mind: The stdlib log package offers log.Printf.... method. This is also often used by gobot in the form like log.Printf("my message %s foo %s bar", foo, bar). logrus great power comes with structured logging by providing foo and bar as structured fields.

How do we add the feature of structured logging without breaking the logging format of the stdlogger? Do we implement two "logging modes? standard and structured? How would this have an effect on the code?

trevrosen commented 5 years ago

I could perhaps be convinced to resurrect something along the lines of this old PR of mine that I wrote w/out merging: https://github.com/hybridgroup/gobot/pull/528

andygrunwald commented 5 years ago

@trevrosen I saw this PR, but this just replaces log with logrus, but keeps the logs unstructured. Hence my question on the structured implementation. Do you have an idea?

trevrosen commented 5 years ago

@andygrunwald yeah I was just pointing out that you'd need to plumb it all the way into the driver level. Something like the above PR would be part of this afaik. As for structured, once you have log as being actual Logrus, you can just use WithFields, no?

I'm still not understanding completely what you want to do wrt structured logging that you couldn't just do in your own code when you're making a Robot's function for Work. Afaict the only real issue here is being able to have the same logging lib/instance in place whether the call site is in your Work (where you have control of what's emitted), or in a driver/adaptor, (where you don't). In any case, you'd want those legacy calls to log to use the same configuration as the more sophisticated stuff in your Work function.

Do you have examples of call sites in drivers or adaptors or whatever that you'd like to see converted to some particular structured calls? Many of the calls in Gobot (nearly all?) would need significant re-working to conform to some structured output.

andygrunwald commented 5 years ago

@trevrosen

I was just pointing out that you'd need to plumb it all the way into the driver level

True. I am not 100% aware of the internal structure of gobot (yet).

As for structured, once you have log as being actual Logrus, you can just use WithFields, no?

Yes, 100%. I thought the goal is also to have it configurable if you want to use the current (log) structure or the "new" / structured logging approach. If this would be the case, it leads to a lot of adjustments.

Usecase

I have a small golang application (things-with-buzzers-websocket) that listens to the GPIO of raspberry pi, get the signals and pushes those out via a WebSocket. In the master branch, I have traditional logging (see https://github.com/andygrunwald/things-with-buzzers-websocket/blob/master/buzzer.go#L55).

I have also a branch prepared with structured logging, see https://github.com/andygrunwald/things-with-buzzers-websocket/blob/logrus/buzzer.go#L99-L101

When I start gobot, it outputs a lot of logging (which is great), but having my app + gobot outputting different styles of logs (structured and unstructured) makes it hard to read the logs and operate it in case of issues.

My use case is, (right now) not tailored for consuming the logs, but this would be a nice benefit with modern tools like Prometheus/Kibana. Does this make more sense for you?

trevrosen commented 5 years ago

@andygrunwald sure your description definitely makes sense. There's no structured logging in driver messages tho (most of those are relatively rare). I think that once we get Logrus in place, it's easy for you to emit structured events out of your own biz logic, and that's about as good as it's going to get here. I'm not personally able to invest the time to invent a new structure and back-port it to various log messages emitted throughout Gobot's drivers and adapters, but I'm not against a proposal from the community for that if you want to take a swing at it. 😄

andygrunwald commented 5 years ago

Thanks. I understand. Right now, I also don't have time for this, but maybe someone from the community picks it up. I think it is essential to clarify the use cases here. And this is what we did.

Regarding structured logging in driver messages, here is a quick example. I am using raspi.NewAdaptor, gpio.NewButtonDriver and finally gobot.NewRobot. Sourcecode can be found here: https://github.com/andygrunwald/things-with-buzzers-websocket/blob/master/buzzer_hardware.go Here are the logs from the small app:

[...]
2019/11/02 09:55:18 Initializing connections...
2019/11/02 09:55:18 Initializing connection RaspberryPi-4FB3E01F6643C509 ...
2019/11/02 09:55:18 Initializing devices...
2019/11/02 09:55:18 Initializing device Button-16F7866257F69CC ...
2019/11/02 09:55:18 Initializing device Button-2EDC0CA5D4ED71EF ...
2019/11/02 09:55:18 Initializing device Button-54BEE31520E875E ...
2019/11/02 09:55:18 Initializing device Button-4EBBE40A02E8C49A ...
2019/11/02 09:55:18 Robot buzzerBot initialized.
2019/11/02 09:55:18 Starting Robot buzzerBot ...
2019/11/02 09:55:18 Starting connections...
2019/11/02 09:55:18 Starting connection RaspberryPi-4FB3E01F6643C509...
2019/11/02 09:55:18 Starting devices...
2019/11/02 09:55:18 Starting socket broadcast
2019/11/02 09:55:18 Starting device Button-16F7866257F69CC on pin 40...
2019/11/02 09:55:18 Starting device Button-2EDC0CA5D4ED71EF on pin 38...
2019/11/02 09:55:18 Starting device Button-54BEE31520E875E on pin 36...
2019/11/02 09:55:18 Starting device Button-4EBBE40A02E8C49A on pin 32...
[...]

As you can see, there are a couple of information available that can be better transformed into structured logging like the Button-ID (e.g. Button-4EBBE40A02E8C49A), the Pin (e.g. 32) and more.