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

А с 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-