1

I'd like to make my logs more useful. Currently they mostly contain such common columns as: timestamp, logger-name, log-level, message, exception.

They are unsearchable and unparsable and writing messages and adding some data to them is not actually helping. Consequently 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 answered are not only about why the application crashed or didn't do something correctly but also about business rules like: why did I get a bonus when ordering ABC?

So usually I need to open the IDE and get the order and debug it to find which condition prevented the bonus to be added and whether it was ok to do so. Have I had logged the data or any other criteria necessary to make this decision, I would have been able to find it in the logs and answer the question maybe within 5 minutes.

But it's not possible to do so with the default schema with the message being the main part of it.


I thought I need to completely reorganize my logs in order to be able to log more data. But I cannot just put everything into the message or additional columns because there are too many possibilities and I'd like to have a general solution that would work for any application.

This means that I need more specific fields then just the message where I can put the additional information.

In order to find those fields I categorizing every piece of data I could think of. This is my list:

  • Environment - this is the largest scope. I use this to log machine names or dev/prod environments.
  • Product(name) - runs within the environment.

  • Layer(name) - this helps me to categorize the logs by the software layer. Each of the layers has its own log-level so I have:

    • Application - for general technical data about the application itself, this is logged with the max; log-level: Debug
    • Business - which are logs about business-logic; log-level: Information
    • Presentation - logs about the UI; log-level: Trace
    • IO - logs about disk operations; log-level: Trace
    • Database - logs about database; log-level: Trace
    • Network - logs about network; log-level: Trace
    • External - logs about external devices; log-level: Trace
  • Transaction(name) - all logs must belong to some transaction so that I can group them together and see the entire process.
  • State or Event - each log is either a State log, that logs some data that I usually use to make decisions or it's an Event.

As a state I can log three types of information:

  • State(Name) - this is the name of the state that I can search for (could be a CustomerInfo, an array of active downloaders, etc.)
  • Actual(State) - this is current state; log-level: Trace
  • Excpected(State) - this is what I expected; log-level: Trace

They both usually contain small object dumps in json format.

Events can be logged together with the Elapsed field. They also end with a result. I defined four of them:

  • Undefined - when not run like invalid parameters; log-level: Warning
  • Success - everything went well; log-level: Information
  • Completed - conditions not met, no errors; log-level: Information
  • Failure - an error occurred; log-level: Error

  • Message - finally there is the old good message which I usually use to give some hints how to fix what might went wrong but I now write it very rarely.

  • Exception - here I put the stack-trace of exceptions.

As a table in a database it could look like this:

Log-Table
--------------
Id
Timestamp
---
Environment | development, production
Product | Product-v0
Logger | RepositoryXLogger
TransactionId | 123
Layer | Application, Business
Level | Debug, Information
State | like a variable name for the state
Expected | small object dumps (json)
Actual | small object dumps (json)
Event | LoadConfiguration, GetDataX
Elapsed | milliseconds
Result | Undefined, Success, Completed, Failure
Message
Exception

I don't present any code because it's not about an specific programming language also how I log this information is an implementation detail that I'd rather ask on a different site.


With this new categories it should be much easier to tell what happened and to distinguish the application logs form the business logic logs. I should also be much easier to log because now I don't have to put all this very specific and enum-like information into messages.

If now anyone asks me about what went wrong I should be able to much faster give him an answer because I wouldn't even have to open the IDE and debug the application.


My questions are:

  • Are these categories enough to easily find the information you need about your application?
  • What other useful categories could there be?
  • Can you think of any case or question about your application you would not be able to find an answer for in such log or you would not be able to efficiently log?

The goal is to be able answer questions about application failure or strange behavior more quickly and without looking at the code. Especially questions about business rules that you might know but you are sometimes not sure if it worked correctly if you don't see the data it used to make decisions.


Disclaimer I'd like to kindly ask you not to comment about how to write a better message. There are already more then enough such questions on SE and I've tried them all and it does not work. My question is about how not to write a message at all. I find it is not necessary if the data we log is properly segmented/categorized. This question is about breaking the so called universally valid rules about logging. If you are not open to new ideas then please just ignore this question.

  • This question is almost word-for-word duplicate of your previous question, which you just deleted. Why didn't you edit it instead? – amon Nov 19 '17 at 21:57
  • @amon what I've learned in all this years on SE sites... delete, rewrite, reask mostly works better then any edit. – t3chb0t Nov 20 '17 at 5:11
  • I'm rather surprised that file name isn't included in your logging. Is "Event" just the function name? If not, I'd log that as well. But it looks like you're going to create an application whose primary job is to create gigabytes of logging. Anything else it does will be a handy side-effect. And don't assume that the place where the application detected an error is the place where the error actually occurred. You might be wading through vast numbers of "success" lines to find where it really went wrong. – Simon B Nov 20 '17 at 8:46
  • @SimonB actually there is a file name, I have added it just a few hours ago and did not update the question yet... there are additional colums, CallerMemberName, CallerLineNumber and CallerFilePath that the C# compiler provides for free. The event does not necesserily have to be a method name. It can be any checkpoint like ApplicationStart. Sure, there should be a lot of Successes ;-) As one of the answers about logging said: disk-space is cheep so I'd rather log too much then spend hours debugging the application to tell someone that he's forgotten the business rules. – t3chb0t Nov 20 '17 at 8:51
  • 2
    Adding a hierarchy to logs is a reasonable thing; Log4J (and, I would expect, Log4Net) have the Nested Diagnostic Context and Mapped Diagnostic Context for just that purpose. But to make that useful, you'll probably also want a better tool for searching your logs, such as the ELK stack. – kdgregory Nov 20 '17 at 18:53
8

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:

    1. Those are well-known tools which, by the way, are often very well documented,

    2. 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,

    3. 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:

    4. 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.

  • Unfortunately your example logs show exactly all the issues I'm speaking of and that I want to get rid of. You can put only a limited amout of data in the message and you cannot search for it. You can't see a workflow as a whole because if logs are created by a multithreaded application they will be spagetti-logged. 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. If you write all this stuff in a message it'll be as long as book and you won't be able to find it without a lot of effort because there is no pattern. – t3chb0t Nov 20 '17 at 5:00
  • Then, you don't know where the logs come from. 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. You cannot find this in messages because they are about everything and nothing. – t3chb0t Nov 20 '17 at 5:02
  • 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. If I log bonus could not be granted... well, why couldn't it? If granting a bonus was dependent on 8 other variables? Where should log all this data if not as a state object dump like json? I won't have to debug my app later to know why it didn't work. – t3chb0t Nov 20 '17 at 5:07
  • Thank you for your answer but I find it's not helping. It just confirms my point of view about all the issues that I mentioned. Unfamiliar developers are not a reason to make up something new. If this was a reason for not making any progress then we would still live in caves. – t3chb0t Nov 20 '17 at 5:14
  • You write that the standarized schama can be parsed... wow, into log-level, timestamp and well... the old good message. I wouldn't call this parsing. You are still not able to find anything useful because it's just prosa without any technically relevant information. Maybe it's good when someone writes a book but never for debugging. – t3chb0t Nov 20 '17 at 5:17
2

We use the following:

  • System
  • Operation
  • Command

This gives us good granularity on what information to retrieve. Also, every request should be tagged with the Correlation Id so you can follow the data as it progresses through the layers or services of your application.

Any other application specific fields should be stored as name/value (dictionary) so that give you the flexibility to log any data point.

I would suggest taking your logs and ingesting them into a database or 3rd party application like Splunk so one can query them easily. Going through them by hand will be a nightmare.

One may need more logging if you can't find an answer. We use 3 log destinations:

  • Error
  • Info
  • Debug

Errors go into error. Information like timing and metrics go into information along with important business events, and everything else goes into debug. Debug logs are not indexed.

If you really don't know what's going on, write a few test cases to verify behavior if possible. Or, add more logging to the area in question.

  • I see that I'm not crazy after all by wanting to log more data then just a message (or not the only one) ;-) – t3chb0t Nov 20 '17 at 20:44
  • Could you explain what are the criteria for using any of the System/Operation/Command categories? Are you using them in a similar way to my Application/Business/IO..etc Layers? – t3chb0t Nov 20 '17 at 20:46
  • 1
    @t3chb0t - System would be application name, operation could be public/major/entry point type of method/operations. Commands could be sub/child method/operations. So many operations under System, many commands under a single Operation. Criteria would be subjective. But as general rule, public methods could be operations, and commands could be private. – Jon Raynor Nov 20 '17 at 20:56
  • I wish more answers were like this one. It's actually the only one on-topic - all other answers just advertise the message. This shows how many devs still use the relict of the passt and try to fit everything into a single text field. – t3chb0t Nov 23 '17 at 10:25
2

I mostly agree with you that using formatted messages doesn't make much sense in your use case. They're necessary for someone without access to the source code or not supposed to bother with it (e.g., Linux users), but for the developer the formatting makes things only worse.

You can't see a workflow as a whole because if logs are created by a multithreaded application they will be spagetti-logged.

This seems to be the cause of your confusion. You can automatically augment each log line with the thread id or alike (your TransactionId) and then you can easily find out what belongs together (plain grep may not be enough, but it's easily doable).

If every log message should contain all your fields, the I'd say, you're having far too many fields. Moreover, a lot of information gets repeated needlessly. For example, the Environment and Product can't change during a transaction, so logging it just once must be enough. Similarly, Elapsed can be computed easily assuming each entry has a timestamp (which it really should have).

The format you're proposing looks like a database table schema. As usual, some columns are often unused and some would need to be split. To continue the analogy, look at "key-value store". The log could look like

01:23:45.100 t5555 ... environment=production, version=v1.2.3, request=createOrder
01:23:45.106 t5555 ... orderId=778899
01:23:45.108 t5555 ... whatever={a: 123, b: 234, c:345}
01:23:45.133 t5555 ... mood=bad
01:23:45.136 t5555 ... customerId=444, customerKind=wellKnown
01:23:45.138 t5555 ... bonus=0

interleaved with an arbitrary amount of messages from other threads. In place of the ellipses imagine any easily obtainable information like the logger name.

To answer the question, why the order 778899 was granted no bonus, you'd find the orderId=778899 string, the corresponding transaction id t5555, gather all lines having this transaction id and find out that the bonus was denied because of the server being in bad mood.

If you're sure about wanting a fixed set of columns, then consider logging into a database.

  • Are these categories enough to easily find the information you need about your application?

Nobody knows as that's all application specific. For example, I could make use of hardly half of your fields.

  • What other useful categories could there be?

You have to write a few logging lines to find it out and then do the searches which motivated you to this question.

  • Can you think of any case or question about your application you would not be able to find an answer for in such log or you would not be able to efficiently log?

With such a more machine-oriented logging, it's essential to be able to find the corresponding logging line in the source code quickly, otherwise you may get lost (and your colleagues probably will).

1

I cannot accept any of the provided answers as they are too message-oriented. Logging with messages is a very common misconception that is totaly useless.

No matter how good your messages are they are always garbage and now with parallel processing and logging, even more.

You nearly never ever want a message. The only case when you really need it is when you want to say why you did something. Everything else is just data that when stored as a message cannot be sought and must be parsed which is costly too. Such a waste of time...

Now, with my data-oriented logging I don't have to parse anything and I can easily use my logs for reporting or monitoring and with correlation-ids I can follow any path and reconstruct any predefined (nested)scope. This wouldn't be possible with messages or would be achievable with a lot of unnecessary effort.

  • "My data oriented logging:" do you care to elaborate? – Frank Hileman Feb 15 at 17:05
  • @FrankHileman sure, I'll expand this part and will let you know when I'm done... – t3chb0t Feb 15 at 17:09
-1

Logging is slow. Writing anything to disk is a lot slower than just doing calculations. The more you log, the slower the application runs. That's why so many servers run at minimal logging levels, where they just log things that went wrong.

If you log too infrequently, then things can go wrong between logs, and you won't know why. If you log everything, then the program will just spend all its time writing gigabytes of logs that nobody will ever look at. Ultimately, everything could mean writing a log entry every time the program makes a decision or performs a calculation.

  • Not necesserily slow. I measured it many times and compared to the processing that my services need to perform, the impact of logging is barely noticeable but the data that gets logged is invaluable when something goes wrong and the service needs to run 24/7. I of course don't long everything like really everything, this would be crazy ;-) Just enough to be able to take proper measures if necessary. I have the impression that the message-only-logging is just a relict of some old times when you only had text files. Now with super-fast json/sql-databases etc why shouldn't I log more useful data? – t3chb0t Nov 20 '17 at 17:43
  • Yes, I can have gigabytes of logs and I really hope never have to read them (like you hope never have to make use of your insurance policy) but when something happens, you are glad you have it and you can bring it back online within minutes and not hours or days which sometimes would be a catasthropic scenario. Logging doesn't cost a penny nowadays ;-] – t3chb0t Nov 20 '17 at 17:46

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.