Fine tune logging granularity

TonyBrobston commented 4 years ago

Is your feature request related to a problem? Please describe. When I look at my logs, there's a bit more information then I find useful for day-to-day usage. The current functionality seems to: 1. Seeing details about what deepstack-ai see's for objects in the image, regardless of whether these objects are in your trigger.json, 2. Seeing details about what deepstack-ai see's for the objects in the image and the relationship between that and your configuration in triggers.json. I do think both of these are useful, if I'm considering detecting more objects; it's interesting to see what deepstack-ai sees. However, for day-to-day usage number 1 creates a lot of noise.

Describe the solution you'd like I would like to propose having more granular logging options.

Describe alternatives you've considered I have considered trying to write a grep statement to reduce which logs are shown, but that seems like a difficult thing to do and a hack at best.

Additional context Here are some logs; I don't have truck in my triggers.json, so this is a bit noisy:

2020-11-05T10:07:08-06:00 [Trigger House East Person detector] /aiinput/house_e_snap.20201105_100705316.jpg: Found at least one object in the photo. (292 ms)
2020-11-05T10:07:08-06:00 [Trigger House East Person detector] /aiinput/house_e_snap.20201105_100705316.jpg: Matched triggering object person
2020-11-05T10:07:08-06:00 [Trigger House East Person detector] /aiinput/house_e_snap.20201105_100705316.jpg: Confidence 64.95408 wasn't between threshold 80 and 100
2020-11-05T10:07:08-06:00 [Trigger House East Person detector] /aiinput/house_e_snap.20201105_100705316.jpg: Not triggered by person (64.95408)
2020-11-05T10:07:08-06:00 [Trigger House East Person detector] /aiinput/house_e_snap.20201105_100705316.jpg: Detected object truck is not in the watch objects list [person]
2020-11-05T10:07:08-06:00 [Trigger House East Person detector] /aiinput/house_e_snap.20201105_100705316.jpg: Not triggered by truck (82.023203)

neilenns commented 4 years ago

What messages that are missing that you'd like to see when verbose is off? Rather than introduce a new logging level it might be as easy as just switching one or two messages from verbose to normal.

TonyBrobston commented 4 years ago

@danecreekphotography

Right, that is certainly an option and probably the easiest.

I will probably change the naming of my triggers to help shorten the log line.

As I think through this, in the working world I recall seeing an approach that used fixed characters to keep things lined up. Here's a rough idea:

2020-11-05T10:07:08|SKIP|House Northeast|Person|conf:64.95408|min:80|max:100|292ms
2020-11-05T10:07:08|TRIG|House East     |Person|conf:93.62421|min:80|max:100|292ms

Explanation left to right:

I'm not sure timezone helps; the last part of the time: -06:00.
It would be nice to have a "triggered" and "not triggered" option that is a consistent number of characters. Maybe TRIG and SKIP?
Find the largest trigger name and pad right with spaces to keep things lined up.
Deepstack handles object detection, so I think if we just put the name of the object, it will be clear to the person reviewing the logs. I was tempted to make this person or Person. I think we'll also have to grab the largest object and pad right with spaces to keep these lined up also.
For the next three (conf, min, max) I struggle to come up with a solution I really like. I wish the node-deepstackai-trigger didn't have a maximum option. In my implementation I've set max to 100 on all triggers; I may be missing something here, but I can't think of a scenario where I'd want anything else, is there one? If we deprecated maximum I could see this turning into 64.95408 < 80 or 93.62421 > 80 or maybe with labels:conf:64.95408 < min:80 or conf:93.62421 > min:80 .
292ms I think is pretty self-explanatory.

When running something like docker-compose logs -f trigger deepstack-ai this should all read really nicely. deepstack-ai also seems to keep there stuff to one line. We could also tailor our log line to match theirs if you're interested, here is an example: [GIN] 2020/11/05 - 20:28:47 | 200 | 697.103006ms | 192.168.80.4 | POST /v1/vision/detection

neilenns commented 4 years ago

I'd say there's two things at play here:

There's really only two options: firehose or nothing. Firehose is fine for debugging but too noisy for day-to-day running and nothing is, for some people, not enough for day-to-day running.
The structure of the logs could be better.

The first is pretty easily solvable just by moving one or two items out of the verbose category. Would just moving actual detection messages be sufficient there, so you can see when the system did detect an object?

The second... eh. All of a sudden we're designing a fancy console logging system. At that point why not just log structured JSON somewhere? I wonder if there's some sort of open source logging system that could just be spun up as another container in the docker-compose. Hmmm....

neilenns commented 4 years ago

It's probably way overkill, but... fluentd maybe?

neilenns commented 4 years ago

Chatted with a friend, he suggested looking at just using a standard logging library like Winston: https://www.npmjs.com/package/winston. Probably should have done that in the first place.

neilenns commented 4 years ago

Or this, even simpler: https://www.npmjs.com/package/bunyan

neilenns commented 4 years ago

Winston is the way to go. Steps that have to happen:

Change log.ts to configure Winston using the design pattern shown here: https://stackoverflow.com/questions/14531232/how-to-use-winston-in-several-modules. All other modules simply import winston.
Create a type for the log JSON blob
Replace all uses of log with winston
Reclassify all the log messages to the appropriate level
Figure out how to control output log level via the settings.json file

TonyBrobston commented 4 years ago

@danecreekphotography This sounds good.

I think the main thing I'm wondering about is the fifth step on your list. I'm wondering, what will this output look like?

neilenns commented 4 years ago

Once I've switched to Winston a custom formatter can get written to update what the output string looks like. I'll let you know when I get that far.

TonyBrobston commented 4 years ago

@danecreekphotography Sounds good. Let me know if you would like my help at all.

I'm going to poke around and look at custom formatters.

neilenns commented 4 years ago

I got the basics of Winston integrated and proved it works. Pull https://github.com/danecreekphotography/node-deepstackai-trigger/tree/danecreekphotography/issue393.

A few startup messages in main.ts and the lone message in settings.ts now log with Winston
You can change the log level through the LOG_LEVEL environment variable. Set it to either info or debug. You can put a .env file with this in dist\src and it'll get picked up when you F5.

Output formatting right now is pretty printed JSON.

I'll spend some time over the weekend going through and updating all the rest of the places to use Winston instead since that's just grunt work. There should be enough here though for you to play with formatting. If you look at the Winston github repo they have an examples folder with some examples.

One thing I haven't figured out yet is how to handle dynamically changing the log level. I need this because I gotta support the verbose setting from settings.json for backwards compatibility reasons. I'll play with that more this weekend maybe too.

neilenns commented 4 years ago

I did a bunch of playing around and got this up and running and the custom format to be basically what I started with.

Having done all that I kinda think this whole effort to integrate Winston was a waste of time and I'm going to throw it out. All that's really necessary is to move a handful of log messages from verbose to info.

neilenns commented 4 years ago

@TonyBrobston can you the Docker image tagged issue393-simple and give it a try? I did a bunch of cleanup just using the existing basic logging framework:

All errors now log as log.error
log.info is reserved for basic startup success information and any time a trigger is triggered successfully
log.warn is used for cases where an action was requested but couldn't be done due to some sort of configuration error
Triggers now log with just their name and no longer have Trigger in front
The subsystem name is padded out to 20 characters
Changed timestamp format to YYYY-MM-DD HH:mm:ss

Here's what logs look like now with verbose off:

2020-11-07 05:54:56 [Main]               ****************************************
2020-11-07 05:54:56 [Main]               Starting up version 5.5.1
2020-11-07 05:54:56 [Settings]           Loaded settings from /run/secrets/settings
2020-11-07 05:54:56 [MQTT]               Connected to MQTT server mqtt://mqtt:1883
2020-11-07 05:54:56 [Triggers]           Loaded configuration from /run/secrets/triggers
2020-11-07 05:54:56 [Triggers]           Loaded configuration for Cat detector
2020-11-07 05:54:56 [Triggers]           Loaded configuration for Dog detector
2020-11-07 05:54:56 [Web server]         Listening at http://localhost:4242
2020-11-07 05:54:56 [Main]               Up and running!
2020-11-07 05:54:59 [Dog detector]       /aiinput/Dog_20200523-075000.jpg: Triggered by dog (96.81682)
2020-11-07 05:54:59 [Web request]        /aiinput/Dog_20200523-075000.jpg: Failed to call trigger uri http://localhost:81/admin?trigger&camera=Dog&memo=dog%20(97%25): RequestError: Error: connect ECONNREFUSED 127.0.0.1:81

TonyBrobston commented 4 years ago

@danecreekphotography I'll grab issue393-simple and run it. Sorry that I've been slow to reply, lots of stuff going on.

TonyBrobston commented 4 years ago

@danecreekphotography After having it running for a few minutes and watching the logs, this definitely helps reduce the noise. I still think there's a bit more than I'd like to see, but this is a definite improvement.

neilenns commented 4 years ago

I probably missed a few. What other ones should I remove from info and make verbose?

TonyBrobston commented 3 years ago

@danecreekphotography I personally would prefer ending up somewhere like I mentioned before, but I realize that's a lot to ask for, especially when I haven't contributed on this feature.

2020-11-05T10:07:08|SKIP|House Northeast|Person|conf:64.95408|min:80|max:100|292ms
2020-11-05T10:07:08|TRIG|House East     |Person|conf:93.62421|min:80|max:100|292ms

In the case of continuing down the path we're on, I think logging detected objects that are not in the watch objects list and logging objects that did not cause a trigger and are also not in the watch list, is still a bit noisy. So I'm thinking something like:

2020-11-11 20:24:08 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Analyzing
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Found at least one object in the photo. (384 ms)
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Detected object truck is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Not triggered by truck (47.901678)
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Detected object train is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Not triggered by train (49.797323)
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Detected object car is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Not triggered by car (60.190310000000004)
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Matched triggering object person
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Confidence 67.85708 wasn't between threshold 85 and 100
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Not triggered by person (67.85708)
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Detected object car is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Not triggered by car (88.0154)
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Detected object car is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Not triggered by car (88.02111000000001)

Would become:

2020-11-11 20:24:08 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Analyzing
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Matched triggering object person
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Confidence 67.85708 wasn't between threshold 85 and 100
2020-11-11 20:24:09 [Garage East]        /aiinput/garage_e_snap.20201111_202406141.jpg: Not triggered by person (67.85708)

However, I did just realize that this:

2020-11-11 20:24:13 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Analyzing
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Found at least one object in the photo. (355 ms)
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Detected object train is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Not triggered by train (40.39956)
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Detected object car is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Not triggered by car (56.156932999999995)
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Detected object car is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Not triggered by car (66.642416)
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Detected object car is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Not triggered by car (87.89326)
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Detected object car is not in the watch objects list [person, cat, dog]
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Not triggered by car (90.155)

Would become:

2020-11-11 20:24:13 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Analyzing
2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: Found at least one object in the photo. (355 ms)

Which is a bit confusing, so I wonder if we should add one high level log message saying like:

2020-11-11 20:24:14 [Garage East]        /aiinput/garage_e_snap.20201111_202411141.jpg: One detected object is not in the watch objects list [person, cat, dog]

But I do think it's worth saying, things are better. I appreciate your help and time working on this repo! I've been brainstorming some other ideas/features and may see about making some more contributions as I have the time/desire.

neilenns commented 3 years ago

Closing old issues.

neilenns / node-deepstackai-trigger

Fine tune logging granularity #393