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

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

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

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

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

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


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

  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

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

Комментарии 70

    +5
    Поддерживаю автора, умение писать исчерпывающие трейсы в действительно важных местах дорогого стоит.
    Хочу дополнить по тому когда стоит применять подход — если логика вашего приложения зависит от большого количества точек возможного отказа + получить логи намного проще чем воспользоваться удаленной отладкой/собрать краш дамп.

    В качестве альтернативы 2 минусу «в продакшене много логов» — можно применить подход «ключ/опция для включения трейс-логов». Если проблема воспроизводится, но только в среде клиента — просим его запустить с определенной опцией.

    4 минус вообще не понял — речь о ревью?
      +4
      4 минус о том, что есть строчка _log.Trace("..."), которая сама по себе не является частью алгоритма, но в коде присутствует. Это немного захламляет код. Иногда лечится AOP.
      Спасибо за мнение.
        0
        в С/С++ вполне успешно решается дефайнами. в других ЯП — сложнее
          0

          В C# тоже дефайны есть.


          Но для C# есть и другой вариант: писать Log.Trace?.Text(...)
          Если объект Log.Trace == null, то выражение не будет вычисляться, тем самым сохраняя драгоценное cputime.

            0
            а проверка компилтайм или рантайм?
              0
              Проверка рантайм.
            0

            А как дефайны решают эту проблему?

              0
              для продакшина делаешь пустой дефайн для лога.
              для дебага — не делаешь.
                +3

                Проблему захламлённости кода это не решает, код как был захламлённым, так и остался.

                  0
                  многие IDE умеют фолдить код по маске
                    0

                    Фолдить так, чтобы от кода оставалась только одна строчка и можно было щёлкнуть на плюсик рядом с ней, чтобы раскрыть весь блок?

                      0
                      типа того. по разному.
                      мне нравится, когда просто полоска со значком.

                      вот например так в jetbrains продуктах:
                      blog.jetbrains.com/idea/2012/03/custom-code-folding-regions-in-intellij-idea-111
                      www.jetbrains.com/help/idea/code-folding.html
                        +1

                        Макрос с трейсом как правило и занимает одну строку, так что в данном конкретном случае фолдинг мало чем поможет.

                          0
                          непомню где, но видел что скрывалось совсем.
                          просто серая полоска между строчками. возможно в VS
          0
          При написании кода на компилируемых языках имеет смысл компилировать код с учётом «максимально допустимого уровня отладки». Т.е. оставлять пользователю возможность менять уровень логирования, но -лишь в определённых пределах. Именно уровень trace следует убирать условной компиляцией в первую очередь: это не только не должно быть нужно заказчику, если, конечно, он не является вашей «лабораторной мышью» для экспериментов, но и запросто может скомпрометировать ваш код или даже послужить источником весьма впечатляющих дыр в безопасности приложения (элементарный пример дампа в лог с неверно настроенными правами доступа структуры, содержащей заботливо расшифрованный пароль из конфига, я думаю, приводить не надо). К сожалению, есть и некий гипотетический негативный эффект от компиляции с «вырезанием» всего ненужного конечному покупателю кода: в многопоточных и асинхронных приложениях это может приводить к неприятному эффекту смещения таймингов исполнения, проявляющемуся в том, что при «правильно заклинивших в одном положении закрылках», т.е. в режиме отладки со включенными log.trace'ами всё будет работать отлично и всегда, а вот в режиме, когда отдельные участки многопоточного кода перестанут вдруг синхронизироваться на записи в один и тот же файл — 1 раз на 100 приложение вдруг начнёт вываливаться «в корку».
          В целом давно ждал подобную статью, сам довольно много размышлял над подходами к отладке — и выбрал для себя именно отладку логированием.
          +7
          Почему-то нет в минусах уменьшения производительности на продакшене. Запись ненужных данных это не только место на диске, но и время CPU, и время iowait.
            0
            Спасибо, дополнил.
              +2
              Это лечится логированием по флагу, которым можно как-то управлять извне. Возникла странная ситуация — перекинул флаг, посмотрел логи.
                0
                Это уже мало отличается от изменения исходников.
                  0
                  Простите, не понял. Каким именно образом «мало отличается от изменения исходников»?
                    0
                    Ну какой-то флаг устанавливать в, например, environment переменных процессов и рестартовать их.
                      0
                      А при изменении исходников их еще и пересобирать надо перед рестартом. А иногда — еще и деплоить.
                        0
                        Ну в том-то и дело, что по нынешним временам облак и контейнеров изменение env-переменной очень вероятно что приведёт к передеплою многих инстансов
                          –1
                          При чем тут изменение исходников? Этот флаг должен быть взводимым извне.
                            –1
                            При том что выше VolCh сравнивает изменение окружения с изменением исходников.
                              –1
                              И что? Разговор начался с
                              Запись ненужных данных это не только место на диске, но и время CPU, и время iowait.

                              И я предложил:
                              Это лечится логированием по флагу,

                              В ответ на что и было дано то сравнение с изменением исходников, которое мне и показалось некорректным. Что перекомпиляция, что изменение env — все не то, о чем я говорил изначально, это ложная дихотомия. Указанием на это и является мое «при чем тут».
                                0
                                Ну так и задавайте свое «при чем тут» тому кто дал это сравнение! Я-то тут при чем?
                                  0
                                  Просто досада от того, что разговор пошел по этому пути, и ваш комментарий, будучи последним, под горячую руку попал.
                                    0
                                    В ответ на что и было дано то сравнение с изменением исходников, которое мне и показалось некорректным. Что перекомпиляция, что изменение env — все не то, о чем я говорил изначально

                                    Это не я писал про изменения исходников, но…

                                    На самом деле, флаги, изменяющие поведения продакшена, по хорошему всегда опасны. Даже всего-то включение логирования может привести к замедлению работы (из-за большого оферхеда на запись логов), переполнению памяти (из-за создаваемых отладочных объектов), другую работу многопоточности и т.п. В чем-то изменение исходников предпочительнее, передеплой, по крайне мере, достаточно заметная процедура и требует прохождения тестов и проверок.

                                    Представьте — один программист включил логирование для поиска мелкой баги, а второй программист (может совсем в другой команде) получил супер критичную багу о том что продакшен стал работать в десять раз медленее. И пока одни в мыле пытаются понять, что же с продакшеном случилось, другие не торопясь разбирают логи.

                                    Конечно, может быть ситуация когда критическая бага, которая воспросизводится только на проде и такое логирование меньшее из зол, но это лечится хорошим кодом, правильной отладкой и архитектурой. В конце концов, тестовой копией продакшена, куда копируются все запросы.
                          0
                          В конфиге демона меняется «log.level»:«error» на «log.level»:«debug» и процессу шлётся kill -s HUP, демон загружает новый конфиг, запускает с ним новые процессы, если они запустились без проблем, останавливает старые… Ни чего не перезагружается, ни какие соединения не теряются…
                            0
                            А есть конфиг и демон?
                              –1
                              Есть, но дать не смогу, не имею права. Сделано по аналогии с nginx, можете там посмотреть…
                                0
                                Я к тому, что вы исходите из того, что есть демон и есть конфиг у него. То есть для каких-то задач приложение уже демонизировано, управляется сигналами и конфигурируется через конфиги. Сейчас в тренде другие варианты: приложение не демонизируется (в том числе nginx), конфигурируется через env (для nginx — динамическая генерация файловых конфигов из них), из сигналов максимум SIGTERM обрабатывает для graceful shutdown
                                  0
                                  У вас есть пруфы на этот тренд? То, что демон, в том числе и nginx можно запустить без демонизации — это понятно, демонизацию на себя возмёт какой-нибудь systemd. Генерация из конфигов переменных env для последующего их использования в демоне — это какое-то особое извращение, видимо следствие хайпа по докерам и т.п.

                                  Объясните, пожалуйста, как вы с помощью одного SIGTERM перезапустите процесс без сброса открытых соединений?
                                    0
                                    Например 12factor.net/ru

                                    И, да, сильно с докером коррелирует. Явной причинно-следственной связи нет, но докер чаще всего используется в реализациях подхода. И этот подход не предполагает перезапуска процесса на той же физической или виртуальной машине. Может даже в другом датацентре она запустится в среде не предполагающей перкидывание соединений с хоста на хост.
                                      0
                                      По ссылке документация по реализации некоторой концепции коих в разработке тысячи, если не миллионы. Наличие этого документа говорит не о тренде, а о наличии концепции.

                                      Но мы уже ушли от темы. Я вам ответил как я в своей среде реализую включение вывода в лог нужной информации, без перезапуска демона. Вы работаете в другой среде, у вас другой механизм.
                                        0
                                        Не в среде дело, а в самом приложении обычно. Реализовывать демонизацию, чтение конфигов и перечитывание их после SIGHUP только для того, чтобы уровень отладки изменить… Ну, может быть когда-то имеет смысл.

                            0
                            Можно и иначе решить вопрос. Тут все от специфики самой программы зависит.
                            Навскидку, просто в лоб — есть watchdog, который с некоей периодичностью проверяет наличие файла с определенным именем и при обнаружении оного взводит глобальную логическую переменную.
                      +1
                      Почему-то нет в минусах уменьшения производительности на продакшене.

                      Грамотно сделанные логи практически не влияют на производительность. Для Java — см. log4j2 в асинхронном режиме. Для .Net — NLog (тоже в асинхронном режиме). Что важно — часть используют для той же Java slf4/log4 (не log4j2, это важно), которые просто не умеют в асинхронность. А значит каждый вызов log.info приведет к записи на диск.


                      Более того, если мы делаем Web сервис, то легко можно организовать систему, когда логи копятся в памяти, пока работает request. И сбрасываются на диск после него. Тут одновременно и буфферизация и асинхронность. Однако важно — это для .Net/Java, по остальным платформам не подскажу.

                        0
                        Грамотно сделанные логи практически не влияют на производительность.

                        В некоторых случаях влияют, если их ставить не подумав. У меня как попало логирование в цикл где перебирались миллиарды и триллионы записей (данные были очень близки к BigData, но все-таки за ночь успевали обработаться на одном сервере), деградация производительности оказалось раза в 3, просто никакая асинхроность не поместит такую массу данных в памяти (мы данные специально брали в архиве, на лету разархивировали, обрабатывали и снова архивировали — это давала значительные прирост в скорости за счет записи и чтения на диск, а логи, естественно, писались без архивирования).

                        В общем, при реально высокопроизводительном приложении ( не при обычных web servic'ах) — нужно быть очень внимательным с логированием, оно, кстати, и место на диске забивает влет, если не подумать.
                          0
                          В высокопроизводительных приложениях в принципе нужно быть очень внимательными, можно же не только логированием убить производительность… А вот возможность включить вывод отладочной информации в лог на работающем демоне меня не раз спасала. Это очень редко требовалось, но очень ускоряло поиск и решение проблемы.
                          0
                          используют для той же Java slf4/log4 (не log4j2, это важно), которые просто не умеют в асинхронность.

                          Насчёт log4j согласен, но чего ради slf4j обвиняется в неумении?

                          slf4f — это просто фасад, набор интерфейсов, за которыми может скрываться какая угодно их имплементация. Например, авторский logback умеет быть асинхронным.
                            0

                            Я имел ввиду те библиотеки, которые пишут непосредственно в файл.

                        +7
                        Ещё стоит отметить, что логирование — чуть ли не единственный способ отладки недетерминированных сценариев, например, многопоточность, работа с сетью.
                          0
                          Благодарю, отметил.
                            –3
                            Если ошибка воспроизводится, то достаточно брейкпойнт поставить.
                              +1
                              И что вы в этом случае увидите? Предположим вы увидели мусор в данных — вам интересен не сам факт того, что на входе мусор, а почему он там возник. А возник он там из-за того, что соседний поток данные попортил. Если он это записал в лог, то последовательность событий вы худо-бедно восстановите, а вот если у вас только бряк, то увы…
                                –3
                                Ну ставим бряк в соседнем потоке на код, изменяющий данные, в Watch\Evaluate смотрим данные. Не вижу принципиальных отличий от логирования. Вот в логах как раз будет мусор, но непонятно почему он там возник, а в отладке можно по шагам проверить, как данные изменяются.
                                  +3
                                  В том-то и дело, что в случае многопоточного приложения вы не можете отлаживать по шагам.
                                    +1
                                    Можете описать какой-то конкретный кейс?
                                    Не раз делал отладку в приложениях с несколькими потоками, например при взломе денег/здоровья/оружия в играх. Расставляем брекпойнты, в пределах одной-двух функций шагаем по F10, потом запускаем по F9 до следующего брекпойнта. Хардварные брекпойнты на запись тоже полезная штука.
                                      0
                                      Не всегда получается локально в песочнице решить проблему. Например, демон, который обрабатывает тесячи запросов в секунду и иногда, раз в час, почему-то падает… Т.е. это примерно один запрос на 10 миллионов создал проблему… Логи позволяют найти этот запрос и повторить у себя в песочнице, не останавливая при этом работу прода.
                                        +5
                                        Я с этим и не спорю, я же написал «Если ошибка воспроизводится». Плавающие баги конечно лучше логами искать.
                                        0
                                        Можете описать какой-то конкретный кейс?

                                        Например, попытка понять, почему при обработке изображения в 1 поток всё хорошо, а в при использовании parallel_for на изображении иногда появляется мусор. Точнее, почему — ответ очевидный (второй поток начал использовать ещё не вычисленные значения), а нужно понять, что сделать, чтобы этого избежать, не потеряв при этом в производительности.


                                        Или другой пример: отладка протокола общения с какой-нибудь железкой, которая шлёт пинг-пакеты, на которые клиент должен сразу же отвечать. Если начать отлаживать по шагам, то возникнут большие задержки, и железка решит, что вы отвалились по таймауту.


                                        Расставляем брекпойнты, в пределах одной-двух функций шагаем по F10, потом запускаем по F9 до следующего брекпойнта.

                                        Дело в том, что пока вы шагаете по функции, остальные потоки тоже работают.
                                        И если вы работаете с общими данными, то возможно всякое.

                                      0
                                      Простите, но вы прям уверены, что можете «поставить бряк в соседнем потоке»? А как вы этот поток найдете? Как узнаете какое из множества мест, в которых мутируют данные вам нужно? Это не говоря уже про то, что к моменту ошибки данные УЖЕ изменены, и бряк ставить просто некуда, вы это место уже покинули.
                                        0
                                        А как вы этот поток найдете?
                                        Примерно вот так:


                                        Как узнаете какое из множества мест, в которых мутируют данные вам нужно?
                                        А как вы узнаете, в какое из множества мест логирование добавить? Если точное место возникновения ошибки неизвестно, можно поставить на все места. Туда же, куда мы бы добавили логирование.
                                        Но вообще я говорил о случае, когда ошибка стабильно воспроизводится. То есть можно сказать, что в этом месте ошибки еще нет, а в этом уже есть. Ставим несколько точек в разных местах, между ними запускаем, чтобы работали все потоки. Если есть возможность поставить брекпойнт на изменение данных, то еще лучше, остановится сразу в нужном потоке.

                                        к моменту ошибки данные УЖЕ изменены, и бряк ставить просто некуда
                                        Извините, эту часть я не понял. Код никуда не девается, ставить надо заранее.
                                          0
                                          Примерно вот так

                                          Сдается мне этот способ настолько трудозатратен, что всерьез его рассматривать банально не стоит :)

                                          А как вы узнаете, в какое из множества мест логирование добавить?

                                          В том и дело, что логгирование добавляется при написании кода, а не после возникновения ошибки. То есть я не буду узнавать «в какое из множества мест добавить лог» — я его просто добавлю во множество мест, и получу вполне ясную, хоть и весьма объемную картину происходящего.

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

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

                                          Извините, эту часть я не понял. Код никуда не девается, ставить надо заранее.

                                          Так куда заранее? Данные пришли, скажем по сети, в виде websocket-сообщения, были преобразованы, разложены в разные структуры данных, которые прошли многопоточный конвеер обработки и преобразования, протиснулись сквозь разные очереди и преобразователи, и на выходе вы обнаруживаете, что там, где ожидается не ноль — у вас ноль. При чем не всегда, а в одном случае на миллион входных сообщений. Имея лог вы возьмете id поломанного сообщения, и сможете отследить весь процесс преобразования в обратную сторону, и найдете место, где возник этот ноль. В этом месте может быть даже ошибки не будет — ошибка будет еще раньше. И вы продолжите идти по логу вверх… Как в таком виде будет выглядеть разбор бряками? Поставил бряк с условием «если ноль», запустился, дождался останова, пошел смотреть, что на входе в метод, пошел выше, поставил бряк с условием… смыть, повторить. Или не так?
                                            0
                                            Сдается мне этот способ настолько трудозатратен, что всерьез его рассматривать банально не стоит

                                            Я там специально активировал окно со списком потоков. Что там трудозатратно? Посмотреть список, переключиться двойным кликом? В Visual Studio такое же окно есть, в других отладчиках думаю тоже.


                                            То есть я не буду узнавать «в какое из множества мест добавить лог» — я его просто добавлю во множество мест, и получу вполне ясную, хоть и весьма объемную картину происходящего.

                                            С брекпойнтами абсолютно аналогично. Ставим везде где надо, проверяем значения переменных.


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

                                            То, что вы описали, это и есть стандартная работа с отладчиком. Он можно сказать и предназначен, чтобы делать такие вещи проще. Стабильность воспроизведения наоборот важна, она дает возможность перезапустить выполненение, поставив точки в другие места, если вдруг пропустил момент появления ошибки.
                                            И первая точка ставится на момент (T минус сколько-то итераций). Он прикидывается исходя из логики. Если не угадали, ставим еще раньше, перезапускаем. И нет, на это уходит меньше времени, чем читать кучу логов.


                                            При чем не всегда, а в одном случае на миллион входных сообщений.

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


                                            Имея лог вы возьмете id поломанного сообщения, и сможете отследить весь процесс преобразования в обратную сторону, и найдете место, где возник этот ноль.

                                            И точно так же можно взять id поломанного сообщения, отследить логику его обработки в отладчике, и найти место, где возникает этот ноль.


                                            Как в таком виде будет выглядеть разбор бряками?

                                            Ставим бряк в процедуру приема сообщения, в процедуру возврата результата, в процедуры, которые работают с этим полем структуры данных.
                                            Запускаем, отправляем сообщение, которое обрабатывается неправильно, останавливается на приеме сообщения. Смотрим, на входе пришло 100.
                                            Запускаем выполнение дальше, останавливается на процедуре разложения в структуры. Проверяем, раскладывается правильно.
                                            Запускаем, останавливается на выходе из конвейера. Проверяем, обработано правильно.
                                            Запускаем, останавливается на выходе из преобразователя. Проверяем, вот он ноль появился.
                                            Проверяем код преобразователя. Ага, в коде написано $x -= $x; вместо $x -= $y;.
                                            Или если не нашли, расставляем бряки в преобразователе, перезапускаем, повторяем.


                                            При этом можно смотреть не только то, что залогировано, а вообще весь контекст — переменные, конфиги, родительские объекты, где-то даже методы вызывать.
                                            И это если код не менять. А если менять, то можно раскидать по коду проверки if ($obj->field == 0) { ... } и поставить бряки в тело условия. Тогда сразу можно найти, где появляется ноль. Похоже на логирование, только логгер в зависимости пробрасывать не надо, логировать все не надо, тестировать этот код не надо, и на продакшн он не влияет, потому что коммитить его не надо.

                                +5

                                Всё бы ничего, но:


                                Анализируем отдельные части (придумываем для них невалидные ситуации, граничные случаи)

                                Бывают случаи, когда ты уже не можешь представить, что могло пойти не так, у тебя кончилась вся фантазия, ты знаешь что результат не верный, но не можешь найти причину. Вариант "придумывать" уже не катит, нужно ставить дебаги, следить за потоками данных.

                                  +3
                                  Да, сняли с языка.
                                  Но все же не выкидываем Дебаг. И то и то полезно.
                                  Но в целом, именно хорошее логгирование позволит понять почему именно в проде через неделю-две что то падает. Мультипоточность, утечки памяти, и прочие вещи связанные с CAP теоремой ловятся часто только через логи. НО. Часто возникают ситуации, когда надо идти и смотреть в ключевых точках что происходит, и от этого никуда не деться.

                                  Мир не черно белый. Нет одного правильного подхода. Серединный путь, как говорил еще Будда про ИТ разработку.
                                  0
                                  Кейс с реальных продуктивных багов. У меня создается сущность с 20+ свойств.
                                  И все свойства меняются, порядка 200 изменений(связных) за пару минут в рамках одной бизнес-операции. И в редких редких случаях одно-два свойства оказываются не в том состоянии.

                                  Ещё раз, изменение свойств — связное. Т.е. при изменении свойства А может быть изменено свойство Б и иногда В. Логгировать изменения абсолютно всех свойств никто не будет, более того, некоторые значения нельзя логгировать по требованиям ИБ.

                                  И тут, кроме отладки, вариантов почти не остается. Есть ещё второй способ — обратное разворачивание всей этой операции. Ну т.е. идти от обратного. Свойство В оказалось таким-то, какие предпосылки могли быть, а как мы могли придти к ним и так далее.
                                    0
                                    Это все хорошо — предложенная роль логгирования в разработке и механизмы реализации этой роли.
                                    При этом, как и все хорошие практики, предложенный подход имеет некоторые недостатки (точнее, это не недостатки, а следствие состояния индустрии):

                                    Такие практики ведут к тому, что эффект от них проявляется в средне- и долгосрочной перспективах.
                                    Если постараться — эффект можно получить даже в ближней перспективе.
                                    Но руководству фичи нужны здесь и сейчас, даже если потом все сломается и/или будет глючить, и время и цена сопровождения фич растянутся на годы.

                                    Отсюда следуют и другие моменты.
                                    Например: «Коллегам приходится смотреть не только на сам алгоритм, но и на трассировку его выполнения».
                                    Т.е., коллегам для работы с вашей фичей нужно будет соблюдать определенную методологию.
                                    Будут ли они ее соблюдать, тем более в ситуации, когда это от вас не зависит (например, опять же, когда от них будут требовать быстрых выдачи фич на гора и закрытия тасок)?

                                    Ну и если уж заговорили о методологии, то, если соблюдать определенные методологии (т.е., если в принципе их получится соблюдать на проекте) на самом раннем этапе — этапе проектирования и написания кода — условно, тот же SOLID (до кучи можно о многом поговорить — и о понимании сложностей O(N), иммутабельности и прочем), то необходимость в отладке (дебаге) и логгировании драматически сокращается.
                                    Хотя конечно, это не отменяет отладку и логгирование как таковые.
                                      +1
                                      Во-перых, тут смешиваются тест и логи, по-хорошему есть 3 способа узнать что происходит с кодом:
                                      1. Написать тесты,
                                      2. Добавить логи,
                                      3. Включить отладку,

                                      Во-вторых, судя по всему отладку просто используют неправильно, отладка нужна для того, чтобы написал тесты, написал код к этим тестам — проверил работоспособность, не работает — отладил. Бессмысленно добавлять тонны логов, которые после того как код будет написан — не понадобятся.

                                      Отладка зло только если пытатесь отлаживать сразу все приложение, когда вы отлаживаете один unit тест — она. позволяет писать код в разы быстрее, чем поиск ошибок через логирование.

                                      В-третих, логирование увеличивает кол-ва кода в приложении и «загрязняет» бизнес код, что идет в разрез сразу многим принципам чистого кода, не пишите того что вам не нужно и т.д. Логирование должно быть только там где оно потенциально нужно и важно, иначе у вас логирования ненужного поведения будет больше чем собственно кода. По хорошему, вместо логирования стоит использовать всякие AOP и т.п. техники, чтобы не забивать собственно код приложения.
                                        +2
                                        Слишком поверхностно.
                                        1. Логгирование типовыми/хорошими библиотеками есть настраиваемое (см комменты, но не код в статье)
                                        2. Выкидывать дополнительный способ отладки — зачем? Давайте лучше отрежем руку.
                                        3. Классика DbC и подобные техники. Рекомендую почитать возможности D

                                        P.S. Асинхронное логгирование в многопоточке — то еще гадание на кофе
                                          +1
                                          Хороший совет, и даже те кто пишут про СОЛИД и тестируемый код — всегда будет какой-нить ньюхайр, который придет в многолетний код и пофиксит баг и не покроет его новыми тестами или не подумает о каком-нибудь пограничном сценарии. И потом это упадёт в продакшне у клиента и удачи вам понимать почему это произошло.

                                          В реальном продакшне производительность может страдать, поэтому флаг/опция на уровень логгирования обязателен.
                                          Еще у всяких фреймворков типа NLog есть оверлоады на лямбды применимые даже к вашему примеру:
                                          _log.Trace($«Privilege: {privilege} not added to User: {user}»);

                                          user тут объект, т.е. ожидаю что в нём перекрыт ToString который может быть еще довольно большой строкой. Также довольно удобно просто писать что-нибудь типа JsonConvert.Serialize(user), чтобы в логах почитать можно было. Поэтому лучше писать это так:
                                          _log.Trace(() => $«Privilege: {privilege} not added to User: {user}»);
                                            0
                                            У нас в системе используется DSL который вообще не имеет режима живого дебаггинга. Так что там только логгирование и помогает.
                                              0
                                              Мобильная разработка iOS/Android. Очень помогает логгирование как при обычной разработке (на машине разработчика запущен спецклиент, с выбором уровней логгирования, тегов (обычно — конкретных классов) и так далее) и в продакшене (в случае падения(или 'падения' — можно ведь отослать фейковый exception) в Crashlytics будут последние 64 Kb логов).

                                              Если совсем все плохо в продакшене и требования ИБ это допускают — подключается через специальный адаптер Amplitude с ее возможностями user path отслеживать.
                                                0
                                                Логгирование это конечно хорошо, но вот выкидывать дебуг — по-моему это перебор. К примеру, есть чудно-замечательный язык Swift (да, тот самый, который для разработки под iOS). Так вот, я так и не понял, как можно перехватить в нём фатальные ошибки через логирование, а не через вывод в лог-окно в режиме дебага?
                                                Конечно, если кто направит на путь истинный, буду благодарен
                                                  –1
                                                  Еще бы иметь развитый язык запростов для анаиза логов. Что-то типа SPARQL, а не полнотекстовый поиск с регулярными выражениями.
                                                    –1
                                                    Мысли правильные. Единственно, неплохо бы разделять logging (средство аудита) и tracing (средство диагностики).
                                                      +1
                                                      Просто залогируйте состояние нужных вам объектов при определённых условиях на определённой итерации цикла.

                                                      Ага, потом на чтение и поиск нужной строчки среди записей о success-варианте уйдет больше времени, чем весь цикл вручную с F10 пробежать.


                                                      _log.Trace($"Remote role: {roleInOtherService}")

                                                      Как логирование поможет узнать причину, почему roleInOtherService = null?




                                                      Почему-то априори предполагается, что на отладку уходит больше времени. Наоборот, не раз замечал, если с var_dump() за 1-2 раза не получилось найти причину, лучше сразу отладчик включить.


                                                      Не надо противопоставлять логи и отладчик. Они дополняют друг друга. Логи помогают установить факт наличия ошибки в логике выполнения, а пошаговая отладка помогает найти ее причину. Анализируя логи, мы тоже делаем отладку, только мысленно. Если наше представление о коде неправильное или недостаточное, то такая мысленная отладка может не дать результата.

                                                      Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                                                      Самое читаемое