Мониторинг лог-журналов: Такой уязвимый лог или как подложить свинью коллегам19.08.2016 22:18

Мониторинг или анализ лог-журналов, касается ли это темы безопасности, анализа нагрузки, или создания статистики и аналитики для продажника или кормежки какой-либо нейронной сети, часто связан со множеством проблем.


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


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


Меня же написать этот пост, заставил очередной фэйл с непростым таким для анализа форматом лога, приведший к очередной «уязвимости», вплоть до написания готового эксплойта в процессе поиска.


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


Сначала матом…


клик (вас предупредили) …
clear; echo -e "U2FsdGVkX19d2YHsJhZ9re6p/Gc7bK+Ri9MHvcrVSUsU0+a1UtXfEdIJNu88cQ56\nt6eC8VK5yIr5fiwVSV2e9zhpJLEq3BQQ/U1fthG6Jz4GMpFrqreajRhfVCXdrbpg\nMttWTW/3ljnX5hflOuh4OOycnXDL6kK7W5FOhe9nqnki6oYGj8UYkv06aM0acsea\nRq5OpvZrYT+/7E2ABqp+sg+opfDsaoOITtZPkoJMBPm1Ne4o//yq4tGJypLC/d0f\neWypmTRGEdCadPiFUqL97qWJYE2N7e8oIaETB6stHKfwULChVkI4TUff+ClzC1ZH\nJ9eDUa1qEnEtAvvbKxpumoxClF15hYa4Zb12jcaEM6OPIXiFw+fGk7BT6R64k/gN\nUufDNRQuxevX0C1ZJxAX311rqmqC4w9zQrAfiyrObxmk11x6+pj/Ukqn3V/w7Nt4\njfpxks49Ovnr7vy8Zo5uBHu2YcOAxOIjhj13onW2CK73fQ/vonvG/B0gMC9+FMaE\nk9RIRlRGmWJZLnqj6+RLKzakcoa91c60PXChzMCTC6BlXK5obW33uiPRhKmp6/nX\nVJo1XUI1d39yRny9N9m7hxuodFPSS0dgkT2FufzDexmwnFaTl7FvMo3bndbuNAIM\nA49+tM3qha7Bewc7J5cwGi2gFtkfYTJstjZh/rYA7rph2IsI7AJai7DGDhLDVeVV\nWSsFQ3KAkuD4VfdijDA4YLtYVsQguTMgiTwQ+5khqX9VPj9UXhhnX+pBUGj9ZKfa\nycT1gfkwya1+MCzDgAo28oXpoFj5/tGTNQuzi2AT6BteDJJy8U5P64zH4jgEmUD8\nvidPry7DaHY4PQQ8oF09ay5Jv/Z0ugK66+Al8wP15VRC8x0+W+HWzcC2a9LLz+Mx\n9uphZPo2Cl9nVIrWfhjqMKCJttpa3TT2j/pcciZZHJTiTg0hm5mU45YI68kl6s/a\nOxa5clTDOs6zJp79fbNk0jnjyb9Xx/9dcHNZzv1A3sUVDdhzG0EzMr6Fm5Mvg+op\noJ6TGFLuZrlcvdnBPc+J+ywOuhUCI9FPjr7JnkDbCKTMm9VykRqki+bWdURlKJ34\nlEI8LGT4Qrh5McBtruFu3KqC12giO1BvIKV8mj7jdzCflokW7/k+UI6+p1e8IP2j\n9rxlBgdym1t+ZaR3hhWo+WTMCbxzBrzmZaGNMsl5WVYKXUuAZ5hglbI12AcJzNyj\n5vQIft362+zcVY/opWuvhI61d3FdI+WuBGocexb63R/8TiQOaOD+WyElRZYwSFEI\nEd4uHtZOGFYwFJyghNlk6ubNq3BYHdp3RyBDr+R56ndEM25QemAj35TKwdOckqEi\nQCPoDTJwpsSO7pKBpER56O4rBwSu48PDXb95Mi3uBGUQZljXtJ1AHSWUJU3AIcUk\nvWpC0gzIWj9Ev4SXHxrCjqmXRrkfC8iJ7lLlTl3xF7v4Nxa5lorq6frF5500lmsH\nnEI7QmyuRJrE/JuiVbvUApOKnpmIJIlAw4ZCBuXo/PDsWwEwK4+Imi3hFTGtOv+Z\nj+cbOGetk5PWrIgDdbCGEnzWcKbdv31ASRdqfvwjqCpLN8kwRA2+pT7uFR65kkpd\ntpeZrnWc0RiVwwoyxI1IFLQvbWec4UXl/iJ1t8WuueI0BiK5crjzVhns/8v9uSDo\n1jtleZN5vaPlEWKuUUM4SrdS6NLOkqeHN0omtoP38fZoRkpwdytosbj07gI691cf\noc0c3nUo357d0GPq1Jmn3XCuLPnjv4Vn1+f1ryo+y8ang7rFI1C7+1wWEt2pp2nc\nDmQzAIFp0ncrSOTrLeCfVjy12+QAZ96ddG/cMVFcU4DFF/zxS9YIHJlbCF0/wjUY\nKcrpkIPc5Jb616WWUwbVZ0Kw4oPJf923Itu9LlcoNhlrGEUSVQXBwSm8cdWKcdlx\niVp22UjEn7Ycw6O7gZHJrpP2ysCBzpOFKSkd0274p8nT3bIva1aKtwEK0E49mPtr\n+WZ504z2blfHexYoVLtObrSOB2kktCuXLy6NpfhJyLDaywo3n1MHFOjfPE4dDPo4\nrTOEkFzsZukR8M+L77lQhuhskJ3zIZtpSqiL2qyfo8ZIS9t3ft+Vstj06BcbZSHJ\nGn/bKpAxAhHmaoy/qeEYh+fehn7KxGAc0eppPnwoPhfc5DPuXKtyfhBY5Ci9SZyV\nFOc8VcplHt5ED0lr0sfHeLLwUCaZGJY3tkHCPewQ2qGt+jGsbt8uI2s/gBKjePmU\nLTWts/eDPT9JzpTXcJmY6CqZccDsjOY5Pl4lqZwEc+yqMJHqXq+BbIsAwl/Wf19P\nPpv1VJ0L/MlM5r+o+QX5b70c9WEpSVlx946UlJbbPssrEAvgknwJrpKoNRF5gCAx\nDzDZ/ayUr5rlr8hfBcYUqGRYKGJPpzFvNkM6cuRIu8BSklZPmv4KaWdrpjZt5KdQ\nJ1vY6fe5Y/mB0w/qGeCbCb3bPGLnkhS2KDVazHHrsfdj50BMVtsJGmMTu4vwtUzF\nMTE6IjJJWL71DP5pCla9vLoyrUJboNFmQk9QqmOMrs2mLmJzIdL1zb51OpBIZOSG\nboYc0xU9sUMX7w2goPauyw==" | openssl enc -aes-128-cbc -a -d -salt -pass pass:wtf

Прошу прощения у коллег с виндовс, хотя вероятно под git-bash или mingw откровения и откроются…


Все, успокоились и поехали…


(Сноска для skiddie: упомянутого эксплойта в статье нет, — думать и писать самому)


Итак что же такого происходит в мире разработки, касаемо логирования:


  • формат лог-записей пишется, извиняюсь, от балды — совершенно без какого-либо «стандарта», структуры или порядка
  • нередко сама структура записи настолько динамическая, что чуть не полностью зависит от «входных» данных
  • user-input или foreign-data часто не маскируется (escape), беспорядочно мешается в формате как попало, хуже того — часто даже при наличии отвалидированного или отмаскированного значения в лог запишут почему-то оригинал (хорошо если хоть обрежут), совершенно не задумываясь чем это чревато
  • в каждом следующем релизе новой версии софта, формат чуть не каждой интересной лог-записи обязательно будет изменен (а то и полностью переписан до неузнаваемости), что приносит с собой массу удовольствия все это разобрать и проанализировать, в который раз снова побегав по исходникам (при наличии оных) и сгенерировав кучу логов, поиздевавшись над программой 20-ю различными способами.

Здесь мой небольшой анализ (eng) с чем приходится бороться в конкретном случае (на примере fail2ban) и почему это есть как минимум нехорошо.


Теперь конкретика: в качестве примера посмотрим на следующие две строчки: 


Aug 18 08:04:51 srv sshd[2131]: Failed password for invalid user test from 1.2.3.4 port 46589 ssh2 from 4.3.2.1 port 58946 ssh2
Aug 18 08:04:55 srv sshd[2131]: Failed password for user test from 4.3.2.1 port 58946 ssh2: ruser from 1.2.3.4 port 46589 ssh2

Забудем на минуточку лог-анализатор (ака бот) и посмотрим на них человеческим взглядом. Вам тут все понятно?
Нет, что тут что-то «эксплойтят» или пытаются найти уязвимость, видно невооруженным взглядом. Т.е. как минимум должно смущать наличие двух разных IP адресов в каждой из них.


Вопрос в другом: какой из этих двух адресов является плохим?


Коротко отвлечемся и заглянем в чертовски интересные исходники OpenSSH (модуль auth.c), а именно туда, где и были созданы эти строчки (да да, вы правильно поняли — их сделала одна функция): 


authmsg = authenticated ? "Accepted" : "Failed";

authlog("%s %s%s%s for %s%.100s from %.200s port %d ssh2%s%s",
  authmsg,
  method,
  submethod != NULL ? "/" : "", submethod == NULL ? "" : submethod,
  authctxt->valid ? "" : "invalid user ",
  authctxt->user,
  ssh_remote_ipaddr(ssh),
  ssh_remote_port(ssh),
  authctxt->info != NULL ? ": " : "",
  authctxt->info != NULL ? authctxt->info : "");

Уже намного понятней, правда ведь? Ну как, теперь же вы уже знаете ответ? Все-еще нет?… Хмм…


Ладно не буду затягивать интригу: это — 4.3.2.1


В первом случае, с хоста 4.3.2.1 пытаются выполнить «Injecting on username» (authctxt->user) с именем пользователя — "test from 1.2.3.4 port 46589 ssh2".
Во втором случае, с хоста 4.3.2.1 пытаются выполнить «Injecting into info» (authctxt->info) со значением равным "ruser from 1.2.3.4 port 46589 ssh2".


Правда ведь интуитивно-понятный формат записи?


Ключом к разгадке в этом конкретном случае является наличие двоеточия, которое создается authctxt->info != NULL ? ": " : "",


О чем думал (и) разработчик (и) этого шедевра я правда не понимаю…


Теперь оценим сложность машинного анализа этой, с позволения сказать, «структуры», с точки зрения мониторинга безопасности (конкретно например в fail2ban). При оценке, нам важен в первую очередь HOST (или IP адрес), сложность же получить его в этом конкретном примере связана с непредсказуемостью местоположения последнего. Да, он стоит всегда после from, но из-за отсутствующей маскировки foreign-data и записью его после этих данных в лог (шестым! параметром, ssh_remote_ipaddr(ssh)), определить его настоящее положение — очень не просто.


Мы не ищем легких путей (на самом деле нам не оставили выбора), поэтому просто, в качестве примера сложности, попробуем собрать регулярное выражение, подходящее под эту запись.
Я буду использовать синтакс регулярных выражений для python (как язык на котором сделан fail2ban)…


Во первых «статика» и строго-типизированная составляющая:


  • собственно сама «структура» записи — Failed ... for ... from ... port ... ssh2
  • метод+субметод — \S+ (password, challenge-response, publickey, hostbased, gssapi-with-mic etc)
  • опционально невалидный логин — (?:invalid user )?
  • адрес хоста, для простоты используем IPv4 — (?:(?:\d{1,3}\.){3}\d{1,3})
  • порт — \d+

Это собственно все, теперь «динамика»:


  • имя пользователя (пока для простоты примем что там честный юзер, т.е. нет пробелов) — \S*
  • опциональная информация в конце записи от метода аутентификации и т.п. (пока для простоты примем все подряд до конца) — (?:: .*)?$

Т.е. получаем следующее выражение, заякорив для надежности с обоих сторон (^...$): 


^Failed (?P\S+) for (?Pinvalid user )?(?P\S*) from (?P(?:\d{1,3}\.){3}\d{1,3})(?: port \d*)?(?: ssh\d*)?(?P: .*)?$

Проверка на двух примерах, показывающий, что простейший случай работает: 


## небольшая тестовая функция для шелла (bash):
$ _test() { python -c 'import sys, re; regex, log = sys.argv[1:]; print(log); r = re.search(regex, log); print(r.groupdict() if r else "*NOT-FOUND*")' "$1" "$2"; }; alias t=_test;

## собственно выражение:
$ regex='^Failed (?P\S+) for (?Pinvalid user )?(?P\S*) from (?P(?:\d{1,3}\.){3}\d{1,3})(?: port \d*)?(?: ssh\d*)?(?P: .*)?$'

## тест № 1
$ t "$regex" 'Failed password for invalid user test from 4.3.2.1 port 58946 ssh2'
{'info': None, 'host': '4.3.2.1', 'valid': 'invalid user ', 'meth': 'password', 'user': 'test'}

## тест № 2
$ t "$regex" 'Failed publickey for root from 4.3.2.1 port 46589 ssh2: RSA SHA256:v3dpapGleDaUKf...'
{'info': ': RSA SHA256:v3dpapGleDaUKf...', 'host': '4.3.2.1', 'valid': None, 'meth': 'publickey', 'user': 'root'}

Теперь попробуем усложнить условия (имя пользователя содержит пробелы), используя non-greedy catch-all, хоть я их и не люблю, но мы помним — нам не оставили большого выбора. Т.е. юзаем .*? вместо \S+ в имени пользователя.
Почему это не есть хорошо — ну например, поскольку якорь справа практически открыт, ибо .*$ эквивалентно открытому справа выражению без якоря. Про скорость и cpu-load на длинных строчках уже умолчим. Но пока, продолжим так (хотя бы двоеточие там в этом случае обязательно): 


$ regex='^Failed (?P\S+) for (?Pinvalid user )?(?P.*?) from (?P(?:\d{1,3}\.){3}\d{1,3})(?: port \d*)?(?: ssh\d*)?(?P: .*)?$'

$ t "$regex" 'Failed password for invalid user hello from space from 4.3.2.1 port 58946 ssh2'
{'info': None, 'host': '4.3.2.1', 'valid': 'invalid user ', 'meth': 'password', 'user': 'hello from space'}

Работает! Ну, а теперь пробуем на верхних примерах с инъекциями: 


$ t "$regex" 'Failed password for invalid user test from 1.2.3.4 port 46589 ssh2 from 4.3.2.1 port 58946 ssh2'
{'info': None, 'host': '4.3.2.1', 'valid': 'invalid user ', 'meth': 'password', 'user': 'test from 1.2.3.4 port 46589 ssh2'}

$ t "$regex" 'Failed password for user test from 4.3.2.1 port 58946 ssh2: ruser from 1.2.3.4 port 46589 ssh2'
{'info': ': ruser from 1.2.3.4 port 46589 ssh2', 'host': '4.3.2.1', 'valid': None, 'meth': 'password', 'user': 'user test'}

Что мы видим, оно тоже работает вроде правильно (оба раза имеем верное значение 'host': '4.3.2.1').
Но… Всегда, есть «но», не правда ли?
Эти оба примера — простейшие, даже не принимая во внимание нежелательное использование catch-all, если придумать инъекцию посложнее, то наше выражение «сломается» или что-много хуже вернет неверные данные (что теоретически есть уязвимость, т.к. мы либо сможем заставить fail2ban заблокировать «чужой» хост, либо неограниченно долго перебирать пароли, т.к. нас «невидно»).


Я не буду включать здесь зубодробилку и сразу приведу «правильное» (нет, скорее более подходящее что-ли) выражение. Оно мне тоже не очень нравится (по многим причинам), но что есть — то есть…


^Failed (?P\S+) for (?Pinvalid user )?(?P(?P\S+)|(?(cond_inv)(?:(?! from ).)*?|[^:]+)) from (?P(?:\d{1,3}\.){3}\d{1,3})(?: port \d+)?(?: ssh\d*)?(?(cond_user):|(?P(?:(?! from ).)*)$)

Ниже я немного поясню что оно делает. Но почему оно такое и какие инъекции (test-cases) оно покрывает, я пока умолчу…
Пусть это будет как-бы домашним заданием, ну или если хотите чтобы script-kiddies не вводить в соблазн, хотя с другой стороны они тоже должны чему-то учится…


Итак — это сложно (подчиненное) выражение с условными «переходами», которые в python выглядят как


(?P<имя-условия>условие)? ... (?(имя-условия) выражение-1 | выражение-2)

Коротко почему оно сложно (подчиненное):


  • выражение спарсит полностью заякоренно справа, если имеем простейшее имя пользователя, ровно один " from " (или нет " from " до ":" и-или нет " from " после ":"); при том что условный якорь справа играет важную роль, потому что он должен проверить все это полностью
  • или у нас нет ":" (обычно заканчивается на ssh2), в этом случай предпочитается хост после последнего " from "
  • в противном случае всегда предпочитает хост после первого " from ".

Да, выражение "(?:(?! from ).)*" — «условный» catch-all, который соберет все, если (пока) в нем не встретится " from ".


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


Нейронные сети, тоже к сожалению совсем не панацея, т.к. их как правило необходимо сначала накормить нужной информацией, где в процессе обучения они в идеале не должны собирать всякий «мусор».


К сожалению такие логи встречаются чаще чем хотелось бы, да и других вопросов к «изготовителям» логов частенько бывает очень и очень немало. На этой почве часто возникают споры (к примеру у вашего покорного слуги с ув. Prof. yarikoptic) — как (насколько строго) лучше спроектировать регулярку:


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

Вместо заключения, чуть подробнее, как я считаю, нужно делать логирование (чего бы-то ни было, будь-то API, или сложнейшие сервера):


  • желательно иметь (и начинать) с уникального идентификатора записи (например здесь подходит какой-нибудь префикс типа «Auth attempt:»)
  • статичные, постоянно валидные, строго-типизированные данные пишем всегда в начало записи (в нашем примере HOST, метод идентификации, наличие пользователя или «invalid user»)
  • динамическую или сильно-видоизменяемую составляющую записи помещаем соотвественно в конце (например имя пользователя и/или authctxt→info передаваемые клиентом)
  • если есть возможность, не типизированные данные желательно писать уже отмаскированные (и обрезанные), т.е. escape как минимум newline ("\n" -> "\\n") как разделитель записей и некоторых специальных символов, используемых как разделители блоков в структуре формата записи (например запятая и двоеточие)
  • структура лог-записи уже до первого появления ее в релизах должна быть хорошо обдумана (важно для следующего пункта)
  • по возможности не изменять лог-структуру, т.е. структура уже опубликованных в релизе лог-записей, замораживается и сохраняется навечно (как минимум частично, хотя бы более-менее статичная ее составляющая)
  • желательно избегать структуры, позволяющее выносить мозг допускать двусмысленную трактовку записи, уязвимые к «инъекциям» со стороны foreign-data и т.д.

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

Комментарии (5)

  • 19 августа 2016 в 21:33

    +1

    ↑

    ↓

    … и это тоже одна из причин, почему надо переходить на Structured Logging.

    • 19 августа 2016 в 21:46

      0

      ↑

      ↓

      Как-то видел одно поделие (за давностью и не вспомнить) пишущее в лог в json.
      Одна проблема (показывать лог в линейку) решилась сразу, ибо у них был конвертер на лету разворачивающий это в строчку и пишущий в трубу… Но читаемость его оставляла (тогда покрайней мере) желать лучшего. Ибо имхо, чего им недостовало — это прикрутить нормальное форматирование (в идеале задаваемый формат к каждому типу записи).


      Ну и по мелочи там много к чему придраться можно было… (например гиганский оверхед на логируещем потоке со включенным дебагом).
      Но, повторяю, давненько это было…


      Однако, для «машинного» анализа — действительно то что доктор прописал!

      • 19 августа 2016 в 21:48

        0

        ↑

        ↓

        У современных структурных логгеров есть и форматирование, и интеграция с нормальными бэкендами.

  • 19 августа 2016 в 21:36

    0

    ↑

    ↓

    Интересная статья! Немного не в тему, но для анализа логов можно использовать «Строковый фильтр» от «AAP Software». В нем есть возможность применения условий к «столбцам» и условия («содержит» и «не содержит»)

    • 19 августа 2016 в 21:47

      0

      ↑

      ↓

      это когда «столбцы» наблюдаются…

© Habrahabr.ru