ALEMIL

Welcome to a blog about application and game development

How logging can simplify complex problems

How logging can simplify complex problems 2018-07-01 20:43:56
Est. read time: 5 minutes, 32 seconds

Working with logs is a very significant part of software development. Logging means writing messages to a file (or console) describing what is happening in the application. It allows monitoring of complex systems and step by step description of its behavior.

What problems does logging solve


When you develop simple systems, you might not need to implement logging. All you need is a debugger for your language of choice and move from breakpoint to breakpoint analyzing what is going on, how values of your variables are changing.

Sometimes you will implement a bit more complex features and logging can help to simplify them. Lately, I had some issues when working with pathfinding for a 2d tile based game. From time to time the algorithm would freeze the whole game, eating too much CPU. Can you imagine pinpointing this situation with a debugger if you had about 50 AI agents that might want to go anywhere in a 192x192 grid? Well, that would be a nightmare.

Instead of debugging you could insert logging in specific points of your codebase and write proper messages describing what is going on. In the example above we might want to start by writing something like this to a text file:

[2018-07-01 12:21:05.608] [ai_path] [info] Entity 840 is moving: from 36,41 to 30,41
[2018-07-01 12:21:05.608] [ai_path] [info] Shortest path calculated in 34 ms: 6 tiles, last tile 30,41

By logging these 2 lines we can now understand where our entities want to go and how long is the path they want to take. We also identify when the last tile of the calculated path is different than what we expect.

Now when we happen to have a freeze again, we can check our log file and find which entity is breaking our game. It turned out that an entity could not get to a specific tile on the map, because there was no way available. About 36863 tiles were scanned for a potential path, but with no luck. The solution was to change the action planner to not allow picking unavailable targets and throw an exception when this situation happens again.

There is another interesting use case for logs that I stumbled upon a few months back. I had to implement an algorithm determining advertisement emission. Which ad, at which place should be displayed, given many different conditions. Even with multiple unit tests covering the codebase ensuring specific calculations return proper results, there is a risk that a whole system combining these components will not work properly.

In such case, especially when writing TDD, it's possible to test if logs are created exactly as we expect, given a specific input. It allows us to implement big features partially while testing along the way. To do this, we need to parse logs created in the test, finding if message exists.

// handler is pointing to a file holding log messages
this->checkLogExist(handler, 'Entity 4 action picked: Fishing');

The same solution can be applied when maintaining a monolithic project that doesn't work as intended and is difficult to unit test because of too many dependencies. Adding logging and some automated feature tests to old codebase can simplify it and serve as a data flow explanation.

How to write useful log messages


When writing log messages you should try to provide answers to some or all of the below questions:

  • When was the message collected? Write time and/or date depending on your needs. In production, the date might inform you if the bug happened before or after the recent patch.

  • Where was the message broadcasted? Write thread name, hostname, web application route, or class name the logger is working on.

  • What is the log level of the message? Is it a debug, info or error message? Is it critical - did your application break?

  • Why was the message produced? What conditions had to be matched for this message to be logged, what values are being held by variables that affect the state of your code?


Apart from the above, if you distribute your application to multiple machines, you might want to write the system and hardware information at the beginning of the file.

Below you can find some example logs for world creation I used in a roguelike game:
[07/01/18 20:22:03] [thread 10152] [info] Registered world locations 47, designs loaded 47
[07/01/18 20:22:03] [thread 10152] [info] Loading organizations for world maps:
[07/01/18 20:22:03] [thread 10152] [info] [1] Kabula - map 30,30,0
[07/01/18 20:22:03] [thread 10152] [info] [2] Kar Laduhr Dwarves - map 33,30,0
[07/01/18 20:22:03] [thread 10152] [info] [3] Forest folk I - map 29,29,0
[07/01/18 20:22:03] [thread 10152] [info] [4] Animals I - map 30,29,0
[07/01/18 20:22:03] [thread 10152] [info] [5] Anheluna Elves - map 29,28,0
[07/01/18 20:22:03] [thread 10152] [info] [6] Mountain Pass - map 32,30,0
[07/01/18 20:22:03] [thread 10152] [info] Starting world creation thread
[07/01/18 20:22:03] [thread 9980] [info] Starting design 30, 30, 0
[07/01/18 20:22:03] [thread 9980] [info] Adding map Kabula to world
[07/01/18 20:22:04] [thread 9980] [info] Player entity spawned at 30, 28
[07/01/18 20:22:04] [thread 9980] [info] Created 839 entities on local map
[07/01/18 20:22:04] [thread 9980] [info] Spawning organization id 1
[07/01/18 20:22:04] [thread 9980] [info] Entity [840] Human woodcutter spawned at position 35, 58
[07/01/18 20:22:04] [thread 9980] [info] Entity [843] Human woodcutter spawned at position 4, 37
[07/01/18 20:22:04] [thread 9980] [info] Entity [846] Human woodcutter spawned at position 56, 57
[07/01/18 20:22:04] [thread 9980] [info] Entity [849] Human woodcutter spawned at position 33, 40
[07/01/18 20:22:04] [thread 9980] [info] Entity [852] Human woodcutter spawned at position 36, 24
[07/01/18 20:22:04] [thread 9980] [info] Entity [855] Human fisherman spawned at position 55, 49
[07/01/18 20:22:04] [thread 9980] [info] Entity [858] Human fisherman spawned at position 21, 3
[07/01/18 20:22:04] [thread 9980] [info] Entity [862] Human fisherman spawned at position 24, 52
[07/01/18 20:22:04] [thread 9980] [info] Entity [866] Human blacksmith spawned at position 27, 11
[07/01/18 20:22:04] [thread 9980] [info] Entity [868] Magnus the Magnificent spawned at position 49, 19
[07/01/18 20:22:04] [thread 9980] [info] Local map created and saved
[07/01/18 20:22:04] [thread 9980] [info] Starting design 31, 30, 0
[07/01/18 20:22:04] [thread 9980] [info] Adding map Mountain Pass to world
[07/01/18 20:22:04] [thread 9980] [info] Created 594 entities on local map
[07/01/18 20:22:04] [thread 9980] [info] Local map created and saved
[07/01/18 20:22:04] [thread 9980] [info] Starting design 32, 30, 0
[07/01/18 20:22:04] [thread 9980] [info] Adding map Yelling cavern to world
[07/01/18 20:22:04] [thread 9980] [info] Created 3300 entities on local map
[07/01/18 20:22:04] [thread 9980] [info] Spawning organization id 6
[07/01/18 20:22:04] [thread 9980] [info] Entity [4941] Troglodyte spawned at position 45, 30
[07/01/18 20:22:04] [thread 9980] [info] Entity [4943] Troglodyte spawned at position 14, 32
[07/01/18 20:22:04] [thread 9980] [info] Entity [4945] Troglodyte spawned at position 27, 38
[07/01/18 20:22:04] [thread 9980] [info] Entity [4947] Troglodyte spawned at position 26, 50
[07/01/18 20:22:04] [thread 9980] [info] Local map created and saved
[07/01/18 20:22:04] [thread 9980] [info] Starting design 32, 30, -1
[07/01/18 20:22:04] [thread 9980] [warning] Skipping map design 32, 30, -1: no name
[07/01/18 20:22:07] [thread 9980] [info] Finished world creation, loaded player map
[07/01/18 20:22:07] [thread 10152] [info] Closing world creation thread

Conclusion


Logging messages can help you with debugging complex systems, describing how they work, applying monitoring, or even help with automated testing. When implemented correctly, you can follow the flow of your application step by step, like a diary.

On the last note, you don't have to implement logging on your own. Most languages will have libraries that can speed up the process. For C++ I can recommend spdlog, for PHP Monolog and for Java - logback. These libraries have already multiple potential issues solved for you, like thread-safety, logging to multiple files, splitting files by dates, writing different variable types and many more. If you are ever in doubt of what is happening in your application - log it.



Comments +

MAkCorps API
Breakpoints is a best alternative of logging.
2018-07-01 21:21:07
Reply