Как читать консоль сервера и находить настоящую причину

Консоль - это сервер, который в точности рассказывает, что произошло, и именно её в первую очередь просит любая служба поддержки, потому что почти всегда её достаточно. Беда в том, что консоль - это тысяча строк повествования, в середине которого зарыты четыре важные, и оформлены все они одинаково. Читать её как следует - навык, на освоение которого уходит около двадцати минут и который потом экономит час каждый раз, когда что-то ломается. Приёмов четыре: найти строку, говорящую, что сервер запустился; определить серьёзность того, на что вы смотрите; читать вверх от сбоя, а не на самом сбое; и узнавать десяток строк, которые выглядят катастрофой, а на деле ничего не значат.

Строение строки лога#

Большинство серверных логов - это одни и те же пять полей в разном порядке.

[21:14:07] [Server thread/INFO]: Done (11.402s)! For help, type "help"[21:16:44] [Server thread/WARN]: Can't keep up! Is the server overloaded?[21:19:02] [Craft Scheduler Thread #3/ERROR]: Could not pass event to ShopPlus v3.2

Время, поток, уровень, сообщение. Поток полезнее, чем кажется: в Minecraft Server thread - это главный цикл тиков, и всё, что ломается в нём, касается всех, тогда как сбой в Craft Scheduler Thread - это фоновая задача плагина, и обычно страдает одна функция. Новые сборки Paper печатают более короткую форму, где уровень вложен в скобку со временем, так что не удивляйтесь, если формат слегка отличается между версиями.

Две вещи именно о консоли, в отличие от файла лога за ней:

• Это stdout и stderr вместе. Порядок между двумя потоками около сбоя может быть слегка неверным, потому что буферизуются они отдельно. Если ошибка будто бы приходит сразу после строки, которая должна была её вызвать, причина в этом.
• Время в логе - по часам сервера, а не ваших. На хостинге это очень часто UTC. Когда игрок говорит «сломалось в девять», выясните, чьи это девять, прежде чем искать.

На панели консоль - это неотфильтрованный вывод самого сервера плюс то, что панель печатает о действиях с питанием. На RE:NODE шум, который создают веб-серверы, - каждый бот в интернете, щупающий /wp-login.php, - свёрнут под счётчик, который можно отключить, и именно это отличает читаемый лог от бегущей стены текста.

Сначала найдите строку готовности#

Каждый сервер что-то печатает, закончив запуск. Найти эту строку - самое ценное действие во всём процессе, потому что она делит лог на две половины и подсказывает, какую из них читать.

Если эта строка есть, сервер запустился, и ваша проблема - всё, что после неё. Если её нет, всё напечатанное - это запуск, а последние несколько строк перед концом - причина, по которой он остановился. Одно это различие снимает значительную долю обращений вида «мой сервер не работает» ещё до всякого другого размышления.

Как выглядит здоровый запуск#

Блок запуска проходит одни и те же стадии в одном и том же порядке, и когда вы их знаете, место, где обрывается ваш лог, и есть диагноз. Сервер Minecraft, слегка сокращённый:

[21:13:52] [ServerMain/INFO]: Starting minecraft server version 1.21.1[21:13:52] [ServerMain/INFO]: Loading properties[21:13:52] [ServerMain/INFO]: Default game type: SURVIVAL[21:13:53] [ServerMain/INFO]: Generating keypair[21:13:53] [Server thread/INFO]: Starting Minecraft server on *:25565[21:13:53] [Server thread/INFO]: Using epoll channel type[21:13:54] [Server thread/INFO]: This server is running Paper version 1.21.1[21:13:55] [Server thread/INFO]: [LuckPerms] Enabling LuckPerms v5.4[21:13:56] [Server thread/INFO]: Preparing level "world"[21:14:01] [Server thread/INFO]: Preparing start region for dimension minecraft:overworld[21:14:04] [Server thread/INFO]: Preparing spawn area: 62%[21:14:07] [Server thread/INFO]: Time elapsed: 11123 ms[21:14:07] [Server thread/INFO]: Done (11.402s)! For help, type "help"

Пять стадий: определить и прочитать конфиг, занять порт, загрузить плагины, загрузить мир, закончить. Место остановки говорит, какая из них упала.

Строка Preparing spawn area ловит людей при первом запуске с новым миром, особенно при большой дальности прорисовки или моде генерации. Она вполне законно может стоять на одном проценте минутами. Дайте ей десять, прежде чем объявлять зависание, а если процент не двигается вовсе, проверьте диск.

Серьёзность, по порядку#

Важная оговорка: уровень выбирает тот, кто написал строку, а не какая-то инстанция. Авторы плагинов с удручающей регулярностью пишут обычную болтовню запуска с уровнем ERROR, а настоящие катастрофы - с уровнем INFO. Считайте уровень подсказкой, куда смотреть в первую очередь, а не приговором. То же относится и к потоку: множество вполне добропорядочных программ пишут баннеры, уведомления о версии и логи сборки мусора в stderr, так что появление строки там само по себе ничего не доказывает.

Другое полезное правило: первая ERROR за сессию ценнее сотой. Ошибки каскадируют. Один плагин, не загрузившийся, порождает сорок последующих сбоев у всего, что от него зависело, и эти сорок - шум. Прокрутите до самой ранней.

Читайте вверх от сбоя#

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

Вставляйте пятьдесят строк перед сбоем, а не последнюю. Последняя строка - наименее информативная часть любого краша.

Когда вы ещё не знаете, что ищете, ищите вот это, в таком порядке:

$ grep -n -iE "fatal|exception|caused by|error" logs/latest.log | head -40$ sed -n '/Done (/,$p' logs/latest.log | head -100     # everything after startup$ tail -n 200 logs/latest.log

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

Как читать Java stack trace#

Большинство игровых серверов написаны на Java, а у трейса Java есть структура, которую стоит знать.

[21:19:02] [Server thread/ERROR]: Could not pass event PlayerInteractEvent to ShopPlus v3.2org.bukkit.event.EventException: null    at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:306)    at org.bukkit.plugin.EventExecutor.execute(EventExecutor.java:70)    at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:70)    ... 24 moreCaused by: java.lang.NullPointerException: Cannot read field "price" because "shop" is null    at net.example.shopplus.ShopListener.onInteract(ShopListener.java:128)    ... 27 more

Пять правил читают это секунд за десять:

1. Первая строка - это резюме, и она обычно уже называет виновника. В ней есть ShopPlus v3.2. Половина всех трейсов решается здесь.
2. Кадры идут от самого свежего. Верхняя строка at - это то место, где находилось выполнение в момент сбоя.
3. Пропускайте кадры из пакетов самой игры. org.bukkit, net.minecraft, java.util - это посыльный. Ищите первый пакет, который принадлежит чьему-то плагину или моду.
4. Идите по `Caused by:` до самого низа. Цепочка тянется от симптома к корню, так что последний Caused by и есть настоящая причина. Люди читают первый и чинят не то.
5. `... 27 more` значит, что одинаковые кадры опущены. Это не обрезка, которую нужно восстанавливать.

Один лишь тип исключения нередко и есть весь диагноз:

UnsupportedClassVersionError называет оба числа, и они расшифровываются просто: версия class-файла 52 - это Java 8, 61 - Java 17, а 65 - Java 21. Сообщение, что jar имеет версию 65, а среда исполнения понимает до 61, значит, что вам нужна Java 21. Соответствие для каждого релиза Minecraft есть в статье JVM-флаги Minecraft и версии Java.

Другие среды исполнения, другие формы#

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

Node.js ставит ошибку первой, а кадры - ниже, от самого свежего, и цепочки Caused by нет, если её не построила библиотека. Полезна верхняя строка.

Error: listen EADDRINUSE: address already in use :::3000    at Server.setupListenHandle [as _listen2] (node:net:1872:16)    at listenInCluster (node:net:1920:12)

Четыре, которые вы действительно встретите: EADDRINUSE (порт занят, часто предыдущим экземпляром), MODULE_NOT_FOUND с Cannot find module (зависимости не установлены, либо путь, различающий регистр, работает на вашем Mac, но не на Linux), ECONNREFUSED (то, от чего вы зависите, не запущено) и необработанный promise rejection, который в актуальных версиях Node по умолчанию завершает процесс. Ошибки, связанные с памятью, разобраны в статье лимиты памяти Node.js.

Python - наоборот по сравнению с Java: кадры traceback идут от самого старого, а исключение - последняя строка. В Python последняя строка действительно и есть ответ.

У серверов Source engine уровней логов нет вовсе - каждая строка это просто печать. Запуск - в основном шум про Steam и breakpad, а краш обычно заканчивается сигналом и предложением добавить -debug к команде запуска, чтобы получить debug.log. Полезное лежит в этом логе; консоль лишь сообщит, что сервер умер.

Серверы на Unreal (Satisfactory, Squad, The Isle) начинают строки с названия подсистемы, например LogNet: Warning:, а когда умирают, пишут отдельную папку краша с собственным логом. Читайте папку краша, а не консоль.

Строки, которые выглядят фатально, но таковыми не являются#

Этот список экономит больше времени, чем что-либо ещё в статье. Каждая из этих строк - обычное дело:

• Can't keep up! Is the server overloaded? Running 2500ms or 50 ticks behind - сообщение о том, что сервер на мгновение притормозил, а не о краше. Появляется после каждого перезапуска, каждого большого сохранения и каждого всплеска генерации чанков. Важна она только когда появляется постоянно, и тогда применима статья почему падает TPS и что делать.
• --- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH --- - раннее предупреждение watchdog в Paper, которое печатается, потому что тик выполняется долго. Оно сообщает о лаге, а баннер существует именно потому, что выглядит как отчёт о краше.
• WARNING: An illegal reflective access operation has occurred - предупреждение JDK о том, что библиотека пользуется старым механизмом. Безвредно в тех версиях Java, что его печатают.
• Picked up JAVA_TOOL_OPTIONS: - JVM подтверждает переменную окружения. Информационное сообщение.
• Setting breakpad minidump AppID - сервер Source engine при запуске настраивает собственный обработчик крашей. Это не значит, что что-то упало.
• Уведомления о недостающей необязательной зависимости от плагинов, например об API прав или экономики, без которого плагин может работать.
• Одиночные ошибки соединения в логе веб-приложения: чей-то браузер закрыл соединение посреди запроса, либо бот пощупал несуществующий путь. Одна - ничто. Тысяча в минуту - это лимиты запросов и злоупотребления.

И обратное - строки, которые выглядят безобидно, но таковыми не являются: одиночный WARN о том, что значение в конфиге сброшено на умолчание (что-то в вашем файле недопустимо и молча игнорируется), WARN о запущенном обновлении мира или исправлении данных (ваше сохранение конвертируется, и пути назад нет) и всё, где упоминается пропущенный бэкап.

Консоль как ввод и где лежат логи#

Консоль - устройство двустороннее. На RE:NODE у неё есть командная строка с историей и автодополнением по Tab, и всё, что вы введёте, попадает в стандартный ввод сервера в точности так, как если бы вы набрали это за самой машиной. stop в Minecraft, quit на сервере Source и собственные админские команды игры - всё работает. Это же правильный способ остановить игровой сервер: чистая остановка сохраняет мир, Kill - нет.

Две предосторожности. Во-первых, всё, что вы вводите, попадает в лог, поэтому не вставляйте туда пароли, токены и данные RCON - для переменных используйте вкладку Startup, а также см. переменные окружения и секреты и безопасную работу с RCON. Во-вторых, прокрутка консоли конечна и очищается при перезапуске. Файл на диске - нет.

$ zgrep -i "outofmemory\|fatal" logs/*.log.gz$ ls -lht logs/ | head

Скачивайте лог до перезапуска, а не после. Чаще всего диагноз теряют, нажав Restart, чтобы «посмотреть, повторится ли», - оно повторяется, но улики первого раза уже стёрты. Привычка их сохранять описана в статье логи, которые стоит хранить.

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

FAQ#

Консоль пуста. Что это значит?

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

Чем ERROR отличается от FATAL?

ERROR - это одна операция, которая не удалась, пока сервер продолжал работать; FATAL - это остановка сервера. В логе могут быть сотни ошибок, а сервер при этом здоровый, поэтому «я вижу ошибки» само по себе не диагноз. Смотрите, пришла ли строка готовности после них.

Как далеко читать назад перед крашем?

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

Сервер печатает предупреждения каждые несколько секунд, но работает нормально. Игнорировать?

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

Почему консоль перестаёт прокручиваться, когда я не смотрю?

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

Можно ли получать вывод консоли в Discord?

Да, но не из самой панели - это делается плагином или модом на стороне сервера, который публикует в webhook, отфильтрованные до нужных вам строк. Отправляйте входы, выходы, смерти и ошибки; если отправлять всё, вы воссоздадите ту самую стену текста, от которой уходили.