Structured logging

[Darkclainer]

I think this project can hugely benefit from structured logging.
User should be able to see what request server handled and how (maybe why they haven't handled by supposed handler, what errors of validation happened. It can be difficult to inspect this manually).
So structured logging can help to deal with possibly huge logs that current project can generate.

We can use some dependency for this functionality such as:
https://github.com/sirupsen/logrus (very user friendly, also can be used instead of standard log)
https://github.com/uber-go/zap

[joanlopez]

Yeah, a verbose mode (-v / --verbose) with that kind of logs is a really good idea.

Could you share with us how these logs would looks like?

Thanks!

[Darkclainer]

I've just realized it can be not so easy, as I thought.

Nevertheless, this is example of output:

We can add more context, like actual body (and it will be almost unreadable) and other things.

The actual problem is that to log everything nicely, we need to make our router because of how gorilla's works. For example, current router can reject some url because it has not some parameters, and we will never know about it.

[joanlopez]

IMHO, logging everything isn't the best approach. We might provide some useful data (imposter file, path, params or the satisfied regex) instead, in order to let the user know why or why not it has matched.

What do you think?

[aperezg]

I think that an approach like the middleware of gin-gonic will be fine, I'm agree with Joan that logging everything could be a little messy, instead of that logging all http request and loading file is a better approach

[Darkclainer]

So, everything should stay as it is in case of logging?

[euzu]

I miss the log functionality as well. I would like to be able to see the requests in the logs. For this, log levels could be specified for the respective path. This way the log level can be set in config. As an example, if LogLevel of the path is set to "Trace" but in the config the LogLevel is set to "Error" no log is written. This can reduce the amount of logs. This is even supported by the log frameworks. There is nothing to reinvent.

[joanlopez]

I miss the log functionality as well. I would like to be able to see the requests in the logs. For this, log levels could be specified for the respective path. This way the log level can be set in config. As an example, if LogLevel of the path is set to "Trace" but in the config the LogLevel is set to "Error" no log is written. This can reduce the amount of logs. This is even supported by the log frameworks. There is nothing to reinvent.

We're already working and discussing it, but looks like we're going to introduce multiple levels of verbosity. However, the idea is to start by adding verbosity levels at program scope instead of imposter, as you suggested. You can find more information at #100 and #101.

[tateexon]

Sorry to reply to an old topic. I have a need for this or #100. Basically anything that makes it easier to get access to specific requests. Was this work dropped at this point or was it completed in a different way?

[joanlopez]

Sorry to reply to an old topic. I have a need for this or #100. Basically anything that makes it easier to get access to specific requests. Was this work dropped at this point or was it completed in a different way?

hey @tateexon,

I think there has been no news since then, but contributions are welcome! :)

[tomp21]

hey @joanlopez , i'd like to lend a hand on this, can i get this assigned to me?

[joanlopez]

Hey, @tomp21!

Yeah, sure! I assigned you! Thanks for engaging! 🙇🏻

Just to be clear, I'd expect you to come with a more or less formal proposal before starting to write some lines of code, as I think the challenge here is having a clear idea on what levels of verbosity the logger should have, and what amount of information to print on each.

[tomp21]

hey @joanlopez i just took a look at the codebase and gave it a thought, IMO having the full request logged could be useful in limited scenarios, I'd have that at debug level logs, and keep the useful data you proposed before at normal info level logging, which would be the default, having an error log level available for quieter runs.

I'm not sure we can give much info on why something matched or not, but we definitely could have a catch all handler to log whatever hasn't matched, which could be useful to see the dropped ones, which I'd also include at info loglevel

WDYT?

[tateexon]

@tomp21 I have a PR that is sitting out there to add some logging of requests: #170

It got left in review limbo waiting for the original owner of killgrave to approve. At this point I have given up on it so feel free to rip any code from it that you find helpful.

[joanlopez]

Hey @tomp21,

IMO having the full request logged could be useful in limited scenarios

I think having that as a separate feature, as @tateexon suggested is better because:

• We don't mix/pollute logs and standard log levels (debug, info, warn...) with dumping requests.
  • We can always do that, but perhaps at a later stage, once we have all the rest of the logs in a better shape.
• We could have more flexibility, and eventually choose to dump more or less details (whether the body is included or not), and what's the destination of the dumping (stdout vs file).

WDYT?

I'd suggest something like:

• DEBUG =>
  • Print details of each imposter loaded, maybe not everything, but the more relevant details (method, path, etc).
  • Print details of each request received, and its result (match or not), again not everything (body of the request, etc) but a subset of information.
• INFO => (more or less what exists now)
  • File name of the imposters loaded, address where the server is listening to, and perhaps a couple of more relevant details from config, like if proxy/secure mode is enabled, for instance.
• WARN =>
  • Any error that doesn't cause the application to stop; e.g. if there's any error reading imposters or similar.
• ERROR =>
  • Any error that cause the application to stop; so replacing calls to log.Fatal by proper structured logging with call to os.Exit(1), for instance.

At time of introducing that, I'd also add support for filtering by log level.
And later, we could also add support for things like:

• Logging format: e.g. json, logfmt, etc
• Logging destination: e.g. stdout, file, etc

To do it, I'd suggest to follow an incremental approach, instead of trying to code all at once.

For instance, we could start by defining some basic structure, with the standard levels, a logger that can be filtered by level, and replacing the existing calls to log.Print and log.Fatal by calling that logger.
Then, we could introduce more log lines as described above, or even refine the existing ones (more than one PR, if needed).
And finally, add the extra support (format, destination, etc), also in PRs as small as possible, to make changesets more digestible.

What you think? How do you see it? Would you be happy to contribute with that?
I'd suggest doing PRs as small as possible because: will be much easier for me to review, thus the reviews will be faster and less likely to introduce bugs, and because if at some point you get tired of contributing, no longer have time or whatever, we can ship small portions that bring value.

Thanks! 🙇🏻

[joanlopez]

@tomp21 I have a PR that is sitting out there to add some logging of requests: #170

It got left in review limbo waiting for the original owner of killgrave to approve. At this point I have given up on it so feel free to rip any code from it that you find helpful.

Hey @tateexon,

I'm sorry to read that you contributing experience hasn't been good, apologies. But let me state what I think have happened:

1. You came excited with a very large PR, that involves adding new features, new flags and things that require design and approval in advance (I reserve the doubts I have for some), without that agreement. That's what I basically suggested to @tomp21 , to avoid the same. We can design what would be nice to have, then code it.
   • To mention one, for instance, is the use of non-standard log levels (0, 1, 2..).
2. I suggested you to start splitting things, you started, but the you gave up.
   • For instance, I left you some feedback on make it easier to build the image and run the tests #172, and you never came back.
   • There's some other things that could be easily split into different PRs, like the refactor of the configuration, requests dumping vs the leveled logging, etc.

That said, if you are still interested in contributing, I'd be happy to follow on reviewing your PRs, once you have some ready, with the feedback applied. For instance, if @tomp21 is going to focus on improvement the logging, we could try to extract the changes for dumping requests from your PR and get that in shape, ready to get merged. As I said to @tomp21, I think that would be a nice feature to add to Killgrave, and that some users would be appreciate.

Up to you! And anyway, thanks for your efforts and interest so far! 🙇🏻

[tateexon]

@joanlopez The company I was working for that needed my changes used my fork until they implemented their own mock server solution. So all of my PRs at this point can be closed. I didn't have a bad experience, you were doing the right thing and keeping the code base clean and I needed additional functionality fast to meet deadlines. I didn't have time to break up to smaller change sets as requested because I was already onto my next task. In short I was a crappy contributor and my PR ended up in limbo for good reasons.