Логирование с метками

А с 2>&1 как выглядит?

2>&1

Текст

#!/bin/bash
rm /tmp/log
id=`date +%G%m%d_%H%M%S`
{
   echo_ 1
   echo 2
   echo_ 3
   echo 4
   echo_ 5
    echo 6
#} 2> >(sed 's/^/[ERROR] /' >> /tmp/log) >> /tmp/log
} 2>&1 >> /tmp/log

Запуск

$ /tmp/1.sh
/tmp/1.sh: строка 5: echo_: команда не найдена
/tmp/1.sh: строка 7: echo_: команда не найдена
/tmp/1.sh: строка 9: echo_: команда не найден

Лог

$ cat /tmp/log
2
4
6

Интересная задача. Никогда не сталкивался. Почему так происходит, понятно — sed не сразу выводит строку в stdout, а копит их. Наверное, это можно как-то побороть при помощи stdbuf, но что-то я не смог его домучать…

Костыль, который работает:

#!/bin/bash
{
  (
    echo_ 1
    echo 2
    echo_ 3
    echo 4
    echo_ 5
    echo 6
  ) 2>&1 >&3 | while read -r line; do echo "[ERR] $line"; done
} 3>&1

Но может кто-то предложит более элегантное решение, без относительно медленного while.

upd: а не, это ж тоже поломается, если надо не в терминал, а в файл в итоге. Хм…

#!/bin/bash

{

(

echo_ 1

echo 2

echo_ 3

echo 4

echo_ 5

echo 6

) 2>&1 >&3 | while read -r line; do echo "[ERR] $line"; done

} 3>&1

#!/bin/bash
{
  (
    echo_ 1
    echo 2
    echo_ 3
    echo 4
    echo_ 5
    echo 6
  ) 2>&1 >&3 | while read -r line; do echo "[ERR] $line"; done
} 3>&1 >> /tmp/log2

stdoutd не попадает в журнал

~$ cat /tmp/log2
[ERR] /tmp/2.sh: строка 4: echo_: команда не найдена
[ERR] /tmp/2.sh: строка 6: echo_: команда не найдена
[ERR] /tmp/2.sh: строка 8: echo_: команда не найдена

Городить костыли так городить…

#!/bin/bash
rm /tmp/log
{
  FIFO=$(mktemp -u)
  mkfifo "$FIFO"
  while IFS= read -r line; do
      echo "[ERR] $line"
  done < "$FIFO" &
  BG_PID=$!
  exec 3> "$FIFO"
  (
    echo_ 1
    echo 2
    echo_ 3
    echo 4
    echo_ 5
    echo 6
  ) 2>&3
  exec 3>&-
  wait $BG_PID 2>/dev/null
  rm -f "$FIFO"
} >> /tmp/log

Я так понимаю, у него задача не дописывать это к каждой строчке (может там вместо шести echo огромный скрипт внутри).

Да, это разный подход.

В его случае можно сделать два раздельных лога.

Внутри 6 команд dd, tar, cp, mv

Это развлекательно-теоретическая задача?

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

Что до проблемы, если это разные потоки, то они по определению асинхронны, разве не?

Вот это работает корректно в 90% случаев.

#!/bin/bash
rm log.log
#id=`date +%G%m%d_%H%M%S`
{
   echo_ 1
   echo 2
   echo_ 3
   echo 4
   echo_ 5
    echo 6
} 2> >(awk '{print "[ERROR] "  $0 >> "log.log"; fflush()}') \
    >> log.log

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

Кстати, а systemd, кушая выхлоп демонов, различает stdout и stderr?

я правильно понимаю что awk будет ждать завершения всех комманд в блоке и stdout,stderr будут сидеть в памяти.
Т.е. если запустить какой-то tar -v на условный *лиард файлов оно может «выесть» гигабайты RAM ?

Кстати аналогичный вопрос к любому перечисленному выше методу перенаправления вывода в комманду ведь проблемы бы не было если бы sed/awk параллельно вывод блока комманд обрабатывали

Кстати, а systemd, кушая выхлоп демонов, различает stdout и stderr?

$ grep Standard system/rescue.service 
StandardInput=tty-force
StandardOutput=inherit
StandardError=inherit

А если ты через какой нить systemd-cat всё вывалишь? Он же вроде сам умеет разделать.

Нет, awk держит в памяти одну строку.

Можно обрабатывать вывод каждой отдельной команды, а не вывод всего блока целиком. Например запускать команды функцией оберткой. Для простых скриптов это будет работать. Но если команда напишет одновременно и в stdout и в stderr, то будет такая же проблема

Занятная штука. Но даже в нём возникает гонка.

systemd-cat -t TESTTEST --stderr-priority err ./1.sh

окт 02 11:41:54 battlehummer TESTTEST[200624]: rm: невозможно удалить 'log.log': Нет такого файла или каталога
окт 02 11:41:54 battlehummer TESTTEST[200625]: ./1.sh: строка 5: echo_: команда не найдена
окт 02 11:41:54 battlehummer TESTTEST[200623]: 2
окт 02 11:41:54 battlehummer TESTTEST[200626]: ./1.sh: строка 7: echo_: команда не найдена
окт 02 11:41:54 battlehummer TESTTEST[200627]: ./1.sh: строка 9: echo_: команда не найдена
окт 02 11:41:54 battlehummer TESTTEST[200623]: 4
окт 02 11:41:54 battlehummer TESTTEST[200623]: 6
о

(все сообщения об ошибках красные, не знаю как это на лоре показать без скриншота)

Ну и оно прибито гвоздями к journald, читать приходится через sudo journalctl -n 50 --no-pager причём, скрипт выполнен от юзера, но в «юзерском» журнале journalctl --user не пишется, очень удобно, Леннарт, большое спасибо.

Ну, не знаю, у нас в бабашке такой проблемы нету. Чините свой баш, значит:

(doseq [cmd ["echo_ 1" "echo 2" "echo_ 3" "echo 4" "echo_ 5" "echo 5"]]
        (spit "/tmp/log"
              (-> (try (-> (shell {:out :string :err :string :continue true}  cmd)
                      (select-keys [:exit :out :err]))
                  (catch java.lang.Exception e {:exit -1 :err (ex-message e)}))
             ((fn [{:keys [exit err out]}]
                (if (= 0 exit) out (str "ERROR: " err "\n")))))
              :append true))
nil

user> (-> "/tmp/log" slurp println)
ERROR: Cannot run program "echo_": Exec failed, error: 2 (Нет такого файла или каталога) 
2
ERROR: Cannot run program "echo_": Exec failed, error: 2 (Нет такого файла или каталога) 
4
ERROR: Cannot run program "echo_": Exec failed, error: 2 (Нет такого файла или каталога) 
5

Чего это ему ломаться при выводе в файл? Всё там норм будет.

Ну, за тем исключением что некоторые команды (не echo) внутренне проблемные при выводе в файл, но это другая тема (они портятся и от простого ./programname >> filename 2>&1 ).

Потому что >> /tmp/log2 у тебя не действует на 3>&1 (3>&1 склеивает третий поток с первым, но с тем первым который был до >>-редиректа). Надо >> делать до 3>&1.

Чего это ему ломаться при выводе в файл? Всё там норм будет.

stdout пойдёт в терминал, а не в файл, если там просто добавить перенаправление в конец.

Добавить timestamp и сортировать при просмотре.

А если там в конец добавить патч Бармина то он вообще начнёт делать плохие вещи. Но зачем добавлять всякую ерунду? Судя по каскадной конструкции, которую ты соорудил, логику работы редиректов ты всё-таки понимаешь, но «редирект в конец» всё равно почему-то предложил, странно.

Ну да, всё правильно, вот так всё работает:

#!/bin/bash
rm /tmp/log
{
  (
    echo_ 1
    echo 2
    echo_ 3
    echo 4
    echo_ 5
    echo 6
  ) 2>&1 >&3 | while read -r line; do echo "[ERR] $line"; done
} >> /tmp/log 3>&1

Из-за while всё равно как-то колхозно это всё выглядит. Наверняка же можно как-то более элегантно… Но я не придумал, как.

Да, лучше программу на Си сделать, конечно. А выше вот пример с awk вместо while предлагали.

А выше вот пример с awk вместо while предлагали.

Да, но там говорят, что работает корректно в 90% случаев, а не в 100… Хотя я сам не проверял это утверждение.

Не знаю, как там 90% насчитали. Там же гонка, будет LA огромным и начнётся мешанина. Вот правильный путь https://github.com/joshtriplett/highlight-stderr . Там процес (скрип) запускается из под бинарника, чтобы его stdout и stdin были перенаправлены в unix сокеты, которые в datagram-режиме, так что записываемая сокет куча байт останется отдельной кучей и будет прочитана отдельной кучей. И, возможно, к сокетам ещё нужно прикрутить SO_TIMESTAMPNS, чтобы точно отличать, какое сообщение было раньше.

Вроде работает, чистый баш + coreutils, оконная сортировка вывода по времени, тормоза обеспечены.

#!/bin/bash

work() {
    echo_ 1
    echo 2
    echo_ 3
    echo 4
    echo_ 5
    echo 6
}

tag(){
        while read -r line; do
                echo $EPOCHREALTIME $1 "$line"
        done
}

window_sort() {
        n=$1
        declare -a arr
        while read -r line; do
                arr+=("$line")
                if [ ${#arr[@]} -ge $n ]; then
                        IFS=$'\n' sorted=($(sort <<<"${arr[*]}"))
                        echo "${sorted[0]}"
                        arr=("${sorted[@]:1}")
                fi
        done
        if [ ${#arr[@]} -gt 0 ]; then
                IFS=$'\n' sorted=($(sort <<<"${arr[*]}"))
                printf "%s\n" "${sorted[@]}"
        fi
}

{ work 1>&3; } 3> >(tag) 2> >(tag "[ERR]") | window_sort 10 | cut -d' ' -f2-

sed не сразу выводит строку в stdout, а копит их. Наверное, это можно как-то побороть при помощи stdbuf, но что-то я не смог его домучать…

RTFM уже не судьба?

#!/usr/bin/bash

: > /tmp/log.txt

exec 2> >(sed -u 's/^/[ERROR] /' >> /tmp/log.txt )
exec 1>> /tmp/log.txt

/usr/bin/echo 1
/usr/bin/echo Err1 >&2
/usr/bin/echo 2
/usr/bin/echo Err2 >&2
/usr/bin/echo 3
/usr/bin/echo Err3 >&2
/usr/bin/echo 4
/usr/bin/echo Err4 >&2

То же самое же.

cat /tmp/1 ; /tmp/1 ; echo .....; cat /tmp/log.txt 
#!/bin/bash

: > /tmp/log.txt

exec 2> >(sed -u 's/^/[ERROR] /' >> /tmp/log.txt )
exec 1>> /tmp/log.txt

echo_ 1
echo 2
echo_ 3
echo 4
echo_ 5
echo 6
.....
2
[ERROR] /tmp/1: line 8: echo_: command not found
[ERROR] /tmp/1: line 10: echo_: command not found
4
[ERROR] /tmp/1: line 12: echo_: command not found
6

То же самое же.

Я скрипт запостил.

Прекрати тестировать поведение внешних программ на bash’евских built-in’ах.

Но гонка сохраняется. В примере вывод в stderr происходит после достаточно большого числа тактов, ведь идёт поиск файла echo_. Аналогично, если в скрипте вызываемый процесс напишет что-то в stdout или в stderr, то до вывода следующих строк будет много времени, пока там процесс завершится, пока следующий запустится. Вот если один процесс пишет и в stderr, и в stdout, то получается мешанина.

Во всяком случае у меня так, я написал простой тестовый код на Си, который делает поочерёдно write(1,) и write(2,). Если убрать из примера cut и посмотреть $EPOCHREALTIME, то когда между строками мс, то работает, а если мкс, то перемешивает. А, если будет большая нагрузка (высокий LA), то, наверное, и тестовый пример может перемешать.

Чего? Вы просто внесли задержки между выводимыми строками за счёт того, что каждая команда идёт через exec(). Замели гонку под ковёр и типа ОК. Буферизация в sed — это одно, а мешанину даёт, то, что stdout и stderr идут в конечный файл разными путями.

Вы просто внесли задержки между выводимыми строками

1. Не просто задержки, а переключение контекста с передачей fd.
2. Именно так работает реальный скрипт у ОП.

мешанину даёт, то, что stdout и stderr идут в конечный файл разными путями.

Да. Если скормить sed’у несколько гигов за один вывод, мешанина снова появится. Но для ОПа это решение подойдёт.

Зануда. Точность соответствует используемым инструментам.

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

ОП не написал, в каких условиях он это запускает. Может у него однопроцессорная одноядерная машина (виртуалка, одноплатник, маршрутизатор). Там достаточно легко sed от процессора отодвинут, несколько гигов за одни вывод не нужно. Запускать тогда sed с приоритетом реального времени (chrt)?

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

Как и в любой другой реализации пространства пользователя - гонка на select. Если пока обрабатывается предыдущая строка - входящие сообщения пришли и на err и на out их порядок утерян.

при большой нагрзуке

В ТЗ не было задачи создать большую нагрузку.

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

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

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

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

По сути, если приложение по очереди вызвало кучу записей в 2 файловых дескриптора, то порядок записей могло сохранить только ядро. Ибо, если это 2 разных пайпа, то получающая сторона пайпа не знает в каком порядке что писалось. А если это один пайп - то не знает через какой дескриптор писалось. Если там не pipe, а pty - то вроде такие же проблемы. А вот message socket - похоже позволяет.

На практике (с осознованием что иногда перепутывается) я такое сохранял через вывод в терминал а потом «сохранить вывод в файл» средствами терминала. Перепутывалось довольно мало при большой нагрузке.

А в теории - это прекрасный пример задачи на которой видна недееспособность клнцепции «всё есть текстовый стрим». Всякие системы логгирования решают её тем что в начале строки при записи в стрим пишут метаданные типа времени, типа сообщения и проч, например как в ядре (по ссылке очень сложный формат): https://www.kernel.org/doc/Documentation/ABI/testing/dev-kmsg

Может у него однопроцессорная одноядерная машина

Тогда тем более всё хорошо.

с передачей fd.

Гарантирует, что stdout будет записан до fork / exec.

а переключение контекста

Почти гарантирует, что sed получит свой квант времени не позднее fork / exec. На одном ядре эта гарантия почти 100%.

Вот это кажется единственным рабочим подходом,

Это не рабочий подход, потому что нет никаких гарантий записи стандартного вывода. На большом выхлопе от одной программы данные в сокет будут улетать буферами, разделёнными в произвольном месте. Фактически будет тоже самое, что иллюстрирует ОП.

Боюсь вы не вполне поняли что здесь происходит. Тут нету единого stderr и stdout на все процессы. Производство строк, их обработка и запись в файл разделены на разные стадии и гонки нет.

нет никаких гарантий записи стандартного вывода. На большом выхлопе от одной программы данные в сокет будут улетать буферами,

Это уже от программы зависит. Если она имеет опции писать stdout/stderr не во внутренние буферы, а делая syscall для каждой строки - то этой проблемы не будет. Это много где поддерживается, PYTHONUNBUFFERED для python, иногда работающий stdbuf, --line-buffered для grep. То есть это не архитектурная проблема, а проблема конкретного софта, во многих случаях имеющая гарантированное решение

И как оно определит порядок, если одна из выполненных shell-команд выдаст 2 строки в out и 2 в err, причем в определённом порядке и с минимальными задкржками?

Если каждая из shell-команд пишет строки только в stdout или stderr - да, работать будет корректно

одна из выполненных shell-команд выдаст 2 строки в out и 2 err,

То функция shell вернёт словарь вида {:exit N :err "str1\nstr2\n" :out "str1\nstr2\n"}. После этого этапа мы можем вообще забыть, что когда-то взаимодействовали с системой, вызывали команды, там потоки какие-то были и всё такое. У нас есть словарь с которым мы можем поступать как пожелаем. Поскольку у нас тут аппликативный порядок вычисления, мы можем быть уверены, что shell (и дальнейшая постобработка, если нужна) завершится до того, как будет вызвана spit, которая просто получает строчку и записывает её в файл.

нет никаких гарантий записи стандартного вывода. На большом выхлопе от одной программы данные в сокет будут улетать буферами,

Это уже от программы зависит.

Я и говорю - в общем случае это работать не будет. Это не говоря уж том, что надо будет править весь скрипт расставляя эти опции.

функция shell вернёт словарь вида {:exit N :err "str1\nstr2\n" :out "str1\nstr2\n"}

и мы потеряли порядок вывода, мы не занем вывела ли команда строки err до строк out, после или поочереди.

С таким же успехом можно сделать на баше массив команд cmds=("echo 1", "echo_ 2", ...) и пройтись по этому массиву, собирая по отдельности вывод каждой команды, естественно с проблемами строк stdout и stderr внутри одной команды.

Фишка-то в том, шелл команды не отдельным массивом, а как код (исходный текст) программы.

Напиши лисп программу/функцию которая логирует вывод другой лисп программы/функции в порядке их появления в тексте программы, ну, или (ленивого?) вычисления.

Давайте к началу. Ваш исходный пост:

Прекрати тестировать поведение внешних программ на bash’евских built-in’ах.

Но не только bash с built-командами может генерить stdout и stderr сообщения без fork(). Запись (write()) в pipe не переключает контекст. Процесс пишет в stderr, потом пишет в stdout, когда здесь успеет поработать sed, особенно если нет другого ядра, что он работает параллельно?

Да, tar умеет писать туда и туда, например tar -v -c -f /tmp-ram/A.tar ~/.bash_history . Имя файла будет в stdout, а «Removing leading `/' from member names» будет в stderr. На моём компе, что ваш скрипт, что скрип анона с $EPOCHREALTIME ломается на таком (при выполнении не от root):

tar -v -c -f /tmp-ram/A.tar ~/.bash_history  /root/.bash_history ~/.bashrc

И тут нет никакого большого выхлопа, чтобы буфер на части. Если смотреть strace, то write(2, "/root/.bash_history: Cannot stat" происходит до write(1, "~/.bashrc\n"), а после sed перепутано, sed не успевает.

Когда я писал про перенаправление в unix сокеты, то именно из-за SO_TIMESTAMPNS. Если этот флаг там корректно работает, то наносекунд ещё надолго хватит, чтобы различать, что было раньше — запись в stderr или stdout. Про то, что в программе может быть буферизация вывода речи не идёт.