when something goes wrong I'm not able to easily find the answer by just looking at the logs and need to debug my application.
The questions that need to be asnwered are not only about why the application crashed or didn't do something correctltly but also about business rules like: why did I get a bonus when ordering ABC?
This doesn't mean that the structure of your logs is incorrect, but rather that your messages are wrong.
Look at other applications (Linux and a bunch of popular applications which come with or for Linux come to mind) and how they handle logs. Sometimes, you do get the exact idea of what was going on when the application failed to do what it was expected to do, in a very business-oriented language. You don't simply see “Application Hello World crashed at [stack trace],” but something more similar to:
[...] INFO Registering a new service at 192.168.1.54:5105 as Replica.
[...] INFO Synchronizing the primary service catalog with the remote instance.
[...] INFO Requesting metadata from the service.
[...] INFO Waiting for response from 192.168.1.54:5105.
[...] ERROR Received an unexpected response "HTTP 401 Unauthorized" from the service
Replica. The service will be paused. To resume the operation, run
`skcatalog --service Replica --resume`.
The goal of the logs is specifically to help you diagnose a problem while identifying the context in which this problem happened. All products do that—some do it well, others, not so well—and they do it with simple text messages.
Your idea to have a specific schema has several issues:
You're making it much more difficult for new developers to understand the logs. By looking at the logs, the schema is not self-explanatory, which means that the new developer would have to find and read the documentation.
Although the idea of having a schema worked in some domains, such as HTTP servers, there are several differences:
Those are well-known tools which, by the way, are often very well documented,
Schema is often standardized among the different tools in the same area; for instance, it is possible to configure nginx, Apache and IIS to use the same schema, which makes it easy to understand and to parse logs,
The schema generally used by those tools remain quite straightforward (aside the request duration field, which could look very cryptic for people unfamiliar with those logs), and:
Those tools have messages of the exact same type. For instance, HTTP servers log only request-response pairs, and every request-response has very similar information, such as its URI or the HTTP response code. When the same HTTP servers need to log events of a different topology (such as configuration errors during the startup), they do it usually in a different log file, using the plain text message format, no schema needed.
Your schema is strict. This leads to two problems. (1) As soon as you'll get a message which won't fit in this particular format, you'll be annoyed. (2) If, in a specific context, it makes no sense to use some of the fields of the schema, it will lead to a lot of null fields.
It, and this is the most important issue, won't help you write clear log messages, nor would it help putting the messages where needed. The opposite may happen: since you're forcing a specific format, it would occasionally make it more difficult/annoying to create logs, which would discourage developers to put logs when needed.
Following your very detailed comments (thank you for them, by the way), I see that my answer needs clarification. Here it comes.
You can put only a limited amout of data in the message and you cannot search for it.
Log messages can be very, very long, but length doesn't make a message clearer. The opposite is usually true: both verbosity (i.e. too many messages) and increased length of individual messages makes logs more difficult to follow. The exception would be the stack trace, which is generally long and quite unreadable, but still useful if you need to link the message to code.
As for the search aspect, I don't understand what you mean by that. grep is a nice tool, and systems such as Kibana present you with powerful search tools as well.
Note that a log message should be taken in its context. Such as a sentence extracted from a book could be interpreted incorrectly, a log message outside context becomes much less valuable. You don't need to make more detailed messages to cope with this “issue,” since it's not an issue in the first place. Just keep messages in their context. In the piece of log I put above, the final error should be put in its context: the four preceding info messages not only make it possible to understand exactly what happened, but also give valuable information, such as the name of the service, the IP address of the remote machine and the port number being used. If, instead of HTTP 401, the error was telling that the HTTP request timed out, the first thing would be to check if 192.168.1.54 is reachable, and if firewalls are configured properly. Since here, the app is facing HTTP 401, the first thing to do is to check if the credentials were configured properly.
You can't see a workflow as a whole because if logs are created by a multithreaded application they will be spagetti-logged.
This is the goal of correlation IDs—a tool which is used a lot in distributed environments or SOA. You could imagine my example above as an extract from the centralized log, given by a grep with a correlation ID as a criteria.
You are still not able to answer the question why didn't customer C get the bonus B for his order O on day D with his article A.
I'm not sure to understand your example, but I could imagine several situations:
The application knows exactly why it failed. In this case, it could simply recover from failure and resume its normal operation, or, if, for some reason, this is impossible, plainly tell in the log message what was going wrong.
The application has no idea what happened (for instance, a NullReferenceException is thrown). In this case, no matter how well you write the messages, the app won't tell you what it doesn't know, so you'll end up with a message from the exception, and the stack trace. It doesn't help much, but no log structure will be able to change that.
Meanwhile, here's a different log excerpt which should reflect your business domain closer then my original example:
[...] INFO Order O-123 created by customer C.
[...] INFO Article X added to the order O-123.
[...] INFO Article A added to the order O-123.
[...] INFO Article Y added to the order O-123.
[...] INFO Article X removed from the order O-123.
[...] INFO Quantity of article A changed from 1 to 2 in order O-123.
[...] WARNING Failed when adding bonus B to order O-123. The bonus is incompatible with
product Y.
So what happens here is that an angry customer contacts you, telling that he couldn't use his bonus. Since the customer forgot to include the order ID, you grep the logs, searching for the customer ID, which is C. You end up with the following messages for the current day:
[...] INFO [AUDIT SUCCESS] Customer C logged on.
[...] WARNING Took too long to process the current HTTP request for customer C. Spent
1,842 ms. Threshold is 500 ms.
[...] INFO Order O-112 created by customer C.
[...] INFO Customer C changed the shipment address. Previous address is stored in Redis
instance R7.
[...] INFO [AUDIT SUCCESS] Customer C logged on.
[...] INFO Order O-123 created by customer C.
Since the customer complained about the latest order, it is safe to assume that the concerned order is O-123 and not O-112. You grep for O-123 and you find the messages above. From here, you can immediately identify all the operations concerning that order, see what went wrong (incompatibility between the bonus and one of the other articles) and check that the problematic article was still in the cart at the moment when the customer was adding the bonus. Less than five minutes later after receiving the original complaint, you can call the customer back to explain the situation, thanks to the clear, easy to understand logs.
You cannot tell whether it was the application itself that didn't work and you maybe need to fix a but or it wasn't the business-logic that didn't work and you need to contact any stakeholders or whether it was a database or network issue.
As stated previously, if the application knows that, it could simply tell that. If it doesn't have this information, no log schema would help.
As soon as you are clear about the business rules and the inner workings of the application, you can write explicit, clear and helpful messages. If either one is not clear, the messages would be unclear. Necessarily. There are no options there. It's our job as developers to understand what we are developing, and writing log messages accordingly is part of the job.
I know the message-for-all logging very good and I find it's the most useless pattern in programming. You have as many messages as there are developers. As I've said, they are unsearchable and unparsable, they are also ungroupable and they give you no clue what really happened and they reveal absolutely no useful data about the application.
Of course you get as many messages as there are developers, but this is exactly the same as bitching about the fact that you don't stand others' code, because it is not written like you would write it yourself, and end up forcing extremely strict rules to how we write code, such as “You always use foreach and never for” or “Each method has six to eight lines of code” or “Every nullable parameter should be checked for nullity at the beginning of the method.” There are situations where one would use for and put twenty lines of code in a method and won't check for null parameters. It happens.
The similarity to code has a different side as well. As you enforce on a code base specific style rules (such as “Class names are capitalized”) to avoid ending up with a mess, or static analysis rules (such as “Objects which are instances of classes which inherit from IDisposable should be disposed properly”) to prevent basic mistakes, you do have to check log messages as well both for style (“A error message doesn't end with exclamation points; there is nothing to be excited about when you fail to fulfill users' needs.”) and for problematic patterns (“A log message doesn't contain users' passwords.”)
Then, it's up to the developer to be professional and to write clean code, and clean log messages.
this answer reads like: Hey!, Don't try to do that, we are all writing meaningless messages so why won't you?
Not really. This answer is more about: Hey, there is a solution to your problem which is outside the scope you imposed to yourself. Some of us are writing meaningful messages, and it works pretty well, so why won't you?
Same comparison with source code. Imagine someone coming to you, claiming that his developers are writing spaghetti code with long methods and fat classes. He's thinking about forcing the ten LOC limit on every method and ten methods limit on every class, and asking you if you could think of an example where this won't work.
What would you do?
Search for an example?
Or maybe try to explain him that the scope of his problem is too narrow, and that the actual solution has nothing to do with artificial restrictions which, at better, will not work, and will probably only decrease the quality of the code base?
We write messages to describe the data. Why? The data can describe itself. I don't want to write messages anymore and if I do, then they should not sound like Customer C could not get bonus B on his order O with article A.
Nothing prevents you from putting data in log messages, for instance objects serialized to JSON. You can even do it in two ways:
Appending JSON to a message. This is basically what happens when an application throws an exception: the error is followed by a stack trace, which is exactly that: a precise structure containing structured data (although not serialized to JSON, but to a custom format, chosen by the framework).
In this case, however, the message still has its value. Dumping a JSON and expecting a developer to understand its purpose won't make it easier to diagnose the problems.
Replacing every log message by a dynamic object. This is the Kibana approach, where you feed it with dynamic structures, and it attempts to determine the fields which should be indexed in ElasticSearch.
It seems that you're attempting to do here what Kibana did a few years ago. However, your approach is to have a strict schema, which creates all the issues I highlighted in my answer. Kibana's dynamic schema approach doesn't have those drawbacks, and this is one of the reasons why it became so popular: it has structured data with powerful search capabilities (which, IMHO, are still not as convenient as grep, but I digress), and at the same time, it allows developers to adapt the structure to the specific cases, and to evolve it through time.
