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
EJsS
In year 2019 there are lot of films coming out. Obviously, there are Avengers part 2, new Star Wars Episode nine and many others. These are films that every person wants to see, but sometimes you can miss it.That's where apps come in handy you can watch a movies for free. Btw, looking for the best app to watch free movies on your iOS phone? Then your should check Showbox APK. This is the most famous app today that has a big library of shows and movies. This app is also available for iMac users. But your need to download it first to enjoy free films download Showbox APK for PC
2019-01-20 20:16:08
Reply
KimerS
Interested in HARD ROCK? How about Kiss band? The band is on a tour at the moment all across Canada and USA. Click on KISS Tour 2019 concert tickets to know more about KISS tour in 2019.
2019-02-05 00:45:13
Reply
CarrieS
Carrie Underwood is my favourite US singer. She is young, beautiful and charming woman in her 30s. Her strong voice takes me away from all troubles of this planet so I start enjoy my life and listen songs created by her voice. Now the singer is on a Cry Pretty 360 Tour started in May of 2019. The concerts scheduled for this year, up to the 31st of October. Tickets are available for all men and women with different income. If you love contry music, then you must visit at least one Carrie's concert. All tour dates are available at the Carrie Underwood tour Houston. Visit the website and make yourself familiar with all powerful Carrie Underwood concerts in 2019!
2019-03-13 04:09:46
Reply
zciwtn
cialis online american express http://canadian-pharmacyn.com
order cialis online usa
2019-04-16 18:44:42
Reply