Логирование как способ отлаживать код

Почему так важно запретить самому себе отладку руками?

Когда вы отлаживаете программу, то вы, сами того не осознавая, думаете что за один отладочный сеанс исправите все проблемы, возникшие в рамках этой задачи. Но наша недальновидность не хочет верить в то, что на самом деле там не одна проблема, а несколько. И за один отладочный сеанс не получится решить все эти проблемы.

Поэтому вам надо будет несколько раз запускать этот код в отладочном режиме, проводя часы отладки над одним и тем же куском кода. И это только вы один столько времени потратили над этой частью программы. Каждый член команды, кому «посчастливится» работать с этим кодом, будет вынужден прожить ту же самую историю, которую прожили вы.

Я уже не говорю о том, что люди в командах меняются, команды меняются и так далее. Человеко-часы уходят на одно и то же. Перестаньте делать это. Я серьёзно. Возьмите ответственность за других людей на себя. Помогите им не переживать тот же самый участок вашей жизни.

Проблематика: Сложно отлаживать составной код

Возможный алгоритм решения проблемы:

1. Разбить на отдельные части
2. Выкидываем отладку, просто запрещаем пользоваться режимом Debug
3. Анализируем отдельные части (придумываем для них невалидные ситуации, граничные случаи)
4. Пишем тесты на каждую отдельную часть всего алгоритма
5. В тестах иногда приходится узнавать промежуточные данные, но…
   Отладка нам боле недоступна, поэтому втыкаем Trace в те части, где возникает подозрение на некорректное выполнение алгоритма
6. По трассировке нужно понять причину проблемы
7. Если не понятно, то чаще всего либо стоит написать ещё тест, либо выполнить трассировку на один этап раньше

Решением является автоматизированное тестирование с использованием логирования. Вы пишите тесты на все (или почти все) ситуации, которые приводят к проблемам. Плюс, если возникает потребность в отладке, то вы трассируете до тех пор, пока не разберётесь в проблеме.

Таким образом, вы избавляете других людей от отладки этого кода, т.к. если возникнет проблема, то человек посмотрит ваши логи и поймёт в чём причина. Логировать стоит только важные участки алгоритма.

Давайте посмотрим пример. Вы знаете, что по отдельности все реализации интерфейсов работают (т.к. написаны тесты, доказывающие это). Но при взаимодействии всего вместе возникает некорректное поведение. Что вам нужно? Нужно логировать ответы от «корректных» интерфейсов:

void Register(User user)
{
	// на этом участке не нужно ничего логировать,
        // т.к. всё будет понятно из исключения
	var isExists = _userRepository.IsUserExists(user);
	if (isExists)
	{
		throw new InvalidOperationException($"User already exists: {user}");
	}

	// а вот это уже можно и залогировать, 
        // т.к. от этого зависят дальнейшие детали алгоритма
	var roleInOtherService = _removeService.GetRole(user);
	_log.Trace($"Remote role: {roleInOtherService}")

	switch (roleInOtherService)
	{
		case "...":
			break;
		...
	}

	// тут нам не критично, если пользователю не добавили 
        // определённые привелегии в каком-то удалённом сервисе,
        // но мы бы хотели знать об этом
	foreach (var privilege in Privileges)
	{
		var isSuccess = _privilegeRemoteService.Grant(user, privilege);
		if (isSuccess)
		{
			_log.Trace($"Add privilege: {privilege} to User: {user}");
		}
		else
		{
			_log.Trace($"Privilege: {privilege} not added to User: {user}");
		}
	}

	...
}

В этом примере видно, как мы трассируем отдельные части алгоритма для того, чтобы можно было зафиксировать тот или иной этап его выполнения. Посмотрев на логи, станет ясно в чём причина. В реальной жизни весь этот алгоритм стоило бы разбить на отдельные методы, но суть от этого не меняется.

Всё это в разы ускоряет написание кода. Вам не нужно бежать по циклу с F10 для того, чтобы понять на какой итерации цикла возникла проблема. Просто залогируйте состояние нужных вам объектов при определённых условиях на определённой итерации цикла.

В конечном итоге вы оставляете важные логи и удаляете побочные логи, например, где вы узнавали состояние объекта на определённой итерации цикла. Такие логи не помогут вашим коллегам, т.к. вы, скорее всего, уже поняли проблему некорректного алгоритма и исправили её. Если нет, то ведите разработку в вашей ветке до тех пор, пока не найдёте в чём причина и не исправите проблему. А вот логи, которые записывают важные результаты от выполнения других алгоритмов, понадобятся всем. Поэтому их стоит оставить.

Что если нам не нужен этот мусор? В таком случае выполняйте трассировку только в рамках отладки, а затем подчищайте за собой.

Плюсы	Минусы
Есть возможность проследить выполнение алгоритма без отладки	Приходится писать код трассировки
В production логи будут собирать иногда нужные данные	В production логи будут собирать иногда ненужные данные
Время на отладку сокращается, т.к. вы часто запускаете код и тут же видите результаты его выполнения (всё как на ладони)	Нужно подчищать за собой. Это иногда приводит к повторному написанию кода трассировки
Коллеги могут прослеживать выполнение алгоритма по логам	Коллегам приходится смотреть не только на сам алгоритм, но и на трассировку его выполнения
Логирование — единственный способ отладки недетерминированных сценариев (например, многопоточность или сеть)	В production уменьшается производительность из-за операций I/O и CPU

Напоследок хотелось бы сказать вот что: думайте своей головой. Не нужно прыгать из крайности в крайность. Порой отладка руками действительно быстрее решит проблему здесь и сейчас. Но как только вы заметили, что что-то быстро, здесь и сейчас не получается, пора переключиться на другой режим.