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
Alvarocob
Мое почтение
Мы занимаемся изготовлением прошивок для чип тюнинга на заказ,
программное удаление систем DPF,ФАП,EGR,CAT,O2sensor,ВСА,MAF,MAP,VBA,НОкс,АДблю
убираем Valvematic TOYOTA моторов 3ZR 2ZR!
так же тюнинг прошивки stage1,стэйж2
работаем с блоками Бош,Continental,каминз,Delphi,Магнетте марелли,Delco,Hitachi,Денсо,Матсушита,Siemens,Keihin,Сагем,Валео,Visteon,Kefico и т.п.
заказы калибровки прошивки производится через email
мыло:max.autoteams@ya.ru
или через форму заказа на сайте https://clck.ru/HxdRd
ваттсап 89020109150 для оперативной связи


Индивидуальная настройка Вашего автомобиля,улучшение "тяги",снижение расхода
Перевод на нормы ЕВРО 2, ЕВРО 0, отключение датчиков кислорода лямбда, отключение клапана ЕГР EGR, сажевого фильтра DPF, удаление ошибок,удаление ADblue. Chip-tuning ECU Чип-тюнинг Абакан. тел 89235951234 89020109150 8(3902)320-456


Чип-тюнинг, прошивка под евро2, отключение катализаторов, сажевых фильтров DPF, увеличение мощности и крутящего момента, глушение клапана егр EGR, диагностика, русификация, корректировка одометров в Красноярске. Опыт более 5 лет. Сергей 8-923-393-0123 Чип-тюнинг Autoteams.
2019-11-21 20:13:57
Reply
WilliamGot
http://isch.eu/ Erarcoli
2019-11-29 20:25:19
Reply
JeremyPhomo
Здравствуйте! интересный у вас сайт!
Нашел хорошую базу кино: смотреть сериал стрела в хорошем качестве
Тут: смотреть хорошие старые вестерны http://kinofly.xyz/vestern/ рейтинг 2019
Здесь: http://kinofly.xyz/7007-shkola-mertvyakov-highschool-of-the-dead-2010.html Школа Мертвяков / Highschool of the Dead (2010) смотреть онлайн бесплатно
Тут: Продолжение «Терминатора» убрали из проката Продолжение «Терминатора» убрали из проката смотреть онлайн бесплатно
2019-12-03 10:36:42
Reply
rardzer
i am from Italy hello. Can you help me translate? /rardor
2019-12-04 11:49:23
Reply
rardzer
Hello. And Bye.
2019-07-01 11:05:49
Reply
MichaelSog
Александр Пушкин родился в Москве 6 июня 1799 г. Он рос вместе со старшей сестрой и младшим братом. Подробнее в яндексе.
2019-12-04 14:51:54
Reply
rardzer
hello everyone thanks for approve
2019-10-12 08:39:53
Reply
RichardNemia
Наша служба транспортировки была основана с целью, чтоб нашим клиентам было практично. У нас знаменитой корпорации ОАО Ажищенков Ногинск имеется штат рассыльных а также свой автопарк. Наше специализированное предприятие готово совершить доставку товара вам в комфортное время. Для этой цели вам необходимо обязательно сделаете заказ такую услугу. При таких обстоятельствах ваш товар будет доставлен максимально быстро и точно. Можно рассчитывать на отменное качество печати, персональные решения и своевременное сопровождение.
пакеты пвх


Свыше 15 лет специализированной международной фирмыОАО ГЕЛАСИЙ Кисловодск помогает предприятиям в многообразных ветвях индустрии находить образцовые решения для упаковки своей продукции. Мы предпочитаем технические нововведения, уклон на партнера и желание к неизменному модернизации. Широкий набор выпускаемой продукции (пакеты из полипропилена с прямоугольным дном ), позволяют реализовать нужды более взыскательных заказчиков. Доставка изделий происходит в разный город Российской федерации.
2019-12-06 23:47:43
Reply