Cheap But Effective Solution for Logging in a private rest microservices backend api

Question

I've created a backend following a microservices architecture and now I need to implement logging.

my understanding

After reading some articles about this topic, I've listed below some "pretty good practices" (correct me if I'm wrong):

• each service logs to the standard output
• In a single microservice, logging must happen only once, and only in the controller layer (not in the repository or the service layer).
• Error must be wrapped by upper layers up to the controller to keep track of the execution path
• A correlation ID needs to be created by the gateway and passed to any other subsequent service involved in the creation of the request to keep track of the execution path (service 1 method X called service 2 method Y etc.)
• The backend only logs unusual error responses, i.e. having a status >= 500. The rest ( access logs and performance analysis I guess) would be performed through telemetry (that I know nothing about yet).
• logs are sent to a central server using something like rsyslog, or beats and probably a few others. Here I don't know if the logs are just sent or if they can be sorted chronologically as well by rsyslog or a similar tool.
• when the structured logs are received on a central server, a couple of options are possible depending on the requirements, cost, etc ... I know they can be parsed by logstash which would feed Elastic Search, and then Kibana would create nice beautiful graphs on that. Datadog, graylog, loggly are apparently other well-known solutions.

In my situation, I can't afford to rent a big server to meet the requirements that an ELK stack requires (3 nodes, 64 GB of RAM ...). My very first requirement is just being able to keep track of the execution path to be able to troubleshoot unusual errors with ease, no matter if I need to go through some old-school grep searches (if it's something possible btw).

For performance analysis, I thought I could rely on a good load-testing plan for the beginning. I'll implement telemetry and add other cool stuff later on if the project reaches the expectations.

Current implementation

So today, in my little backend, only the gateway is logging errors, other services just return errors to the calling service, up to the gateway using this go structure:

type restErr struct {     
    // sent to the frontend
    ErrStatus  int    `json:"status"`  // HTTP Status Code
    ErrTitle   string `json:"title"`   // The string representation of the Status Code like "bad_request"
    ErrMessage string `json:"message"` // An optional message send to the front_end

    // never sent to the frontend, only used for logging
    ErrError    error  `json:"error"`     // Raw error returned by a DB, another Servive or whatever
    ErrErrorMsg string `json:"error_msg"` // String representation of ErrError
    ErrCode     string `json:"code"`      // Raw error code from the DB or another service
}

The errors are wrapped by each layer like this restErr.Wrap("microX.serviceY.MethodZ:"). This is just adding a bit of context to keep track of the call chain when an error occurs. If so, the caller method wrap the errors through each layer of each microservice up to the gateway which logs an error and returns an HTTP response to the browser, abstracting both the details of the original error and the execution path.

When the gateway receives a wrapped error from another service, it logs the error like below:

2023-04-29T09:14:44+04:00 ERR | can't do what you want me to | error="gw.controllerX.MethodX: gw.httpclientY.MethodY: service1.controllerX.MethodX: service1.serviceY.MethodY: service2.controllerX.MethodX: service2.serviceY.MethodY: service2.repositoryY.MethodY: error 9009 in database" code=9009 correlationID=cgva1dg3lcjadv69n180 service=gw status=500

...and returns an HTTP response like this:

HTTP/1.1 500

{
 "status": 500,
 "title": "internal_server_error"
 "msg": "can't do what you want me to"
}

As you can see I have a correlation id that is just assigned to an incoming request. But I don't need to pass from a caller service to a receiver service cause other services don't log so it's not needed to keep track of the execution path. Except for sending emails cause I use RabbitMq, so it's much more a fire-and-forget style in which the service that sends the emails also needs to log to its stdout.

diagrams

Here is a link to the diagram for better legibility:

https://drive.google.com/file/d/1x6cZmGsRICZ313IQcQBIhGQjZ-HWTpt-/view

Questions/feedback

• Do you think that I can only rely on grep at the beginning to troubleshoot (don't know the limitations)?

• Do you think this solution is something reasonable to put live?

• I'm wondering if the go struct that mixes http response data and logging data is something commonplace or if there are better ways to handle this.

• I just want feedback on this cause I'm a lone dev, and this is a very wide topic to cover.

Thank you so much.

Answer 1

As I mentioned in the comments, I would challenge some of the assertions in your question. Mainly this:

The backend only logs unusual error responses, i.e. having a status >= 500. The rest (access logs and performance analysis I guess) would be performed through telemetry

For starters, let's discuss the definition of telemetry:

Telemetry is the in situ collection of measurements or other data at remote points and their automatic transmission to receiving equipment (telecommunication) for monitoring.

In other words, telemetry is really just logging that is sent somewhere else. There are some connotations about this term in software and IT which imply a specific type of logging but to think of this as something fundamentally different than logging is a misconception, IMO. Telemetry is very useful, especially in large complex environments where the logs can be aggregated together and there are projects such as Open Telemetry which can provide a lot of value with little effort. But the use of these techniques is a somewhat orthogonal to the question of what information you should log for troubleshooting bugs.

There are a couple of bad assumptions with your assertion above:

1. All defects in your code will result in a 500 error.
2. The error code and/or description will illuminate the root problem.

For #1, a lot of bugs never produce an error at all. It's also possible that an error your code treats as user error be your defect e.g.: treating a valid user action as invalid.

Think about it this way: if you were capable of correctly identifying and categorizing your errors with 100% accuracy, you should be able to build a system with no defects at all. In other words, defects are the things that you haven't accounted for or have implemented incorrectly. It doesn't really make sense to think you know how the system will behave when it is not behaving as you expected. The key thing with 500 errors is making sure you aren't exposing details about your implementation to the client such as writing a stacktrace into the response.

With regard to #2, in the cases that you do capture the error as 500, you will likely need more than just a short description of the event that was captured as an error. Often the last thing that happens will be something really unhelpful like a null pointer error or an invalid parameter to a DB query. The problem is that you might not know what was passed to the DB or where that bad value came from and then you will be grasping at straws trying to figure out how to reproduce a scenario with limited information about the state of things. It may be obvious most of the time but, because these are specifically scenarios you've failed to account for properly, you will likely run into an issue which you are unable to figure out by just by looking at an error message and thinking about it.

Logging is an art. It's something that I think most everyone struggles with getting right. There's a fine line between logging the relevant info and polluting your logs with useless detail. But, in general, more is better. I (generally) wouldn't log every execution of a loop, but I would log all the parameters to a function, DB lookup, or service call along with what call was being made.

'Telemetry' tools can help with this kind of thing. These tools can do things like log every function call along with its parameters and ship it to some logging sink. The question is: why you would log errors in a different way? What's the value of having the errors logged separately? It seems to me that the simplest thing would be to have all your data in one place organized in a way that allows you to trace back to the source of the issue easily and in a straightforward way.

As far as the resources related to this go, if you are already going to be capturing telemetry, the error information is an insignificant addition. I'm not seeing any real reason for sectioning them off.

There are two big considerations when logging details (whether you use telemetry or not) is the target can handle the volume of logging and how much storage you use. The meeting the first constraint tends to lead to some sort of asynchronous processing i.e.: a solution that has high-availability and minimal latency on writes to the logging sink. The good news on the second constraint is that storage is relatively cheap but you will most likely need to consider how far back you maintain the full logs.

Lastly, be sure to track a timestamps on all the logging events at the source due to the fact that the time an event was handled by the logging sink may be very different from the time it occurred. Using some sort of correlation Id for your transactions is also a really good idea. On all responses to the client, you should include that Id. That way, if your client runs into an issue, you can easily find the logs associated with it. This Id will also be a primary way to isolate transactions when looking at the logs. You may find that you need sub-correlation Ids to really make sense of the data as you put things in place.

I wish you luck on your endeavor. If you have questions, let me know in the comments.