Szukanie błędów

Wstęp

Skrypt działał. U Ciebie na laptopie działał. Kod wyjścia zero, kciuk w górę. A raport pusty.

Co robi początkujący? Wpatruje się w kod. Czyta go piąty raz. Dopisuje echo "tu jestem" w dwunastu miejscach. Restartuje serwer, na wszelki wypadek. Modli się.

Co robi admin? Bierze cztery narzędzia i w dwie minuty wie, gdzie jest problem. Korektor, kamera, nadgorliwy sąsiad i podsłuch. Dziś poznasz wszystkie cztery.

Skrypt do zepsucia

plik raport.sh

#!/bin/bash
# raport.sh — liczy pliki .log w folderze i ich linijki
folder=$1
licznik=0

if [ ! -d $folder ]; then
    echo "Nie ma folderu $folder"
    exit 1
fi

for plik in "$folder"/*.log; do
    licznik=$((licznik + 1))
    linie=$(wc -l < "$plik")
    echo "$plik: $linie linii"
done

echo "Plików: $licznk"

Wygląda niewinnie. Uruchamiamy na folderze Moje logi, ze spacją w nazwie, bo przecież nikt nigdy nie daje spacji w nazwach folderów. Poza wszystkimi.

$ ./raport.sh "Moje logi"
./raport.sh: line 6: [: Moje: binary operator expected
Moje logi/app.log: 2 linii
Moje logi/db.log: 1 linii
Plików: 
$ echo $?
0

Dwa błędy, jeden komunikat, kod zero. Idealna zbrodnia. Bierzemy się do śledztwa.

bash -n: korektor, który czyta, ale nie wykonuje

Wyobraź sobie korektora w urzędzie. Bierze Twój wniosek i sprawdza tylko, czy jest po polsku: czy zdania się kończą, czy nawiasy się zamykają. Nie sprawdza, czy masz prawo do zasiłku. Niczego nie podbija, niczego nie wysyła.

To jest bash -n. Bash czyta skrypt i sprawdza składnię, ale nie wykonuje ani jednej komendy. Można go puścić na skrypcie, który kasuje pół serwera, i nic się nie stanie.

bash -n literowka.sh
bash -n cudzyslow.sh

literowka.sh: line 4: syntax error: unexpected end of file
cudzyslow.sh: line 3: unexpected EOF while looking for matching `"'

Pierwszy plik ma if bez fi. Drugi ma cudzysłów otwarty i nigdy niezamknięty, czyli kopertę, do której wsadzono pół skryptu i nikt jej nie zakleił. Zwróć uwagę: Bash zgłasza błąd na końcu pliku, a nie tam, gdzie zapomniałeś. On dopiero na końcu orientuje się, że czegoś brakuje. Jak kelner, który dopiero przy rachunku zauważa, że nikt nie zamówił deseru, a w karcie było, że deser obowiązkowy.

A teraz nasz raport.sh:

bash -n raport.sh; echo "kod: $?"

kod: 0

Czysto. Bo oba błędy są gramatycznie poprawne. Literówka w nazwie zmiennej to dla Basha po prostu inna zmienna. bash -n łapie tylko błędy składni. Dlatego to pierwsze narzędzie, a nie jedyne.

bash -x: kamera nad ramieniem urzędnika

Teraz montujemy kamerę nad biurkiem urzędnika. Widzimy każdy wniosek, który bierze do ręki, i to już po wypełnieniu: wszystkie zmienne podstawione, gwiazdki rozwinięte, cudzysłowy zdjęte. Dokładnie to, co naprawdę zostanie wykonane.

bash -x ./raport.sh "Moje logi"

+ folder='Moje logi'
+ licznik=0
+ '[' '!' -d Moje logi ']'
./raport.sh: line 6: [: Moje: binary operator expected
+ for plik in "$folder"/*.log
+ licznik=1
++ wc -l
+ linie=2
+ echo 'Moje logi/app.log: 2 linii'
Moje logi/app.log: 2 linii
+ for plik in "$folder"/*.log
+ licznik=2
++ wc -l
+ linie=1
+ echo 'Moje logi/db.log: 1 linii'
Moje logi/db.log: 1 linii
+ echo 'Plików: '
Plików: 

podświetlona linijka '[' '!' -d Moje logi ']'

Popatrz na trzecią linijkę. Komenda [ dostała osobno Moje i osobno logi. To dwa argumenty zamiast jednego, czyli list rozerwany na pół, bo nie był w kopercie. Bash pokazuje to w cudzysłowach: każdy kawałek w apostrofach to jeden argument. A Moje logi jest bez apostrofów, czyli rozsypało się na dwa.

I zobacz, co się stało dalej: test się wyłożył, ale skrypt nie wyszedł, tylko pojechał dalej. Gdyby folderu w ogóle nie było, dostałbyś to samo, plus kilka błędów z pętli. Bramkarz zemdlał, a impreza trwa.

Ostatnia linijka: licznik to dwa, a echo wypisało pusto. Kamera pokazuje, że w echo nie było żadnej liczby. Czyli zmienna, którą wypisujemy, jest pusta. Patrzymy w kod: $licznk. Zjedzona literka.

Jeszcze dwa szczegóły w zapisie z kamery. Plus oznacza „to wykonuję”. Dwa plusy, ++, oznaczają „to wykonuję w środku czegoś innego”, tutaj w $( ). Im więcej plusów, tym głębiej w zagnieżdżeniu. A wszystkie linijki z plusami idą na drugi głośnik, czyli stderr. Wynik skryptu leci osobno, więc możesz go nadal przekierować do pliku.

set -x i set +x: kamera tylko na kawałek

Skrypt na trzysta linijek z bash -x to powódź. Często chcesz nagrać tylko podejrzany fragment.

#!/bin/bash
echo "To leci normalnie"
set -x
wynik=$(( 6 * 7 ))
echo "Wynik: $wynik"
set +x
echo "Znowu cisza"

To leci normalnie
+ wynik=42
+ echo 'Wynik: 42'
Wynik: 42
+ set +x
Znowu cisza

set -x włącza kamerę, set +x wyłącza. Tak, w Bashu minus włącza, a plus wyłącza. Nie pytaj. Ktoś kiedyś tak zdecydował i od tamtej pory wszyscy udajemy, że to logiczne.

Kamerę można włączyć też w zwykłym terminalu. Świetny sposób, żeby zobaczyć, co Bash robi z Twoją komendą, zanim ją wykona:

set -x
plik="Moje logi"
ls $plik
set +x

+ plik='Moje logi'
+ ls Moje logi
ls: cannot access 'Moje': No such file or directory
ls: cannot access 'logi': No such file or directory

Lekcja o spacjach w nazwach w jednym obrazku.

PS4: kamera z numerem linijki

Kamera ma jedną wadę: widzisz, co się dzieje, ale nie wiesz, w której linijce pliku. Ten plusik na początku to zawartość zmiennej PS4. Pamiętasz PS1 z lekcji o ustawianiu Basha? To jej kuzynka, tylko od śledzenia.

PS4='+ ${BASH_SOURCE}:${LINENO}: '
set -x

Wstawiamy te dwie linijki na górę raport.sh i odpalamy:

+ raport.sh:5: folder='Moje logi'
+ raport.sh:6: licznik=0
+ raport.sh:8: '[' '!' -d Moje logi ']'
raport.sh: line 8: [: Moje: binary operator expected
+ raport.sh:13: for plik in "$folder"/*.log

Teraz każda linijka mówi: z którego pliku i z której linijki. Przy skrypcie, który wczytuje inne pliki, to jak numer pokoju na nagraniu z monitoringu.

Uwaga na apostrofy. W pojedynczych cudzysłowach ${LINENO} zostaje napisem i Bash rozwija go za każdym razem od nowa, przy każdej komendzie. W podwójnych rozwinąłby się raz, przy przypisaniu, i każda linijka miałaby ten sam numer. Koperta zaklejona kontra koperta otwarta.

ShellCheck: nadgorliwy sąsiad, który ma rację

Każdy ma takiego sąsiada. Przechodzi obok, rzuca okiem na Twój płot i mówi: „Ten słupek się przewróci przy pierwszym wietrze”. Irytujące. I zwykle ma rację.

ShellCheck to program, który czyta skrypt i wypisuje wszystko, co wygląda podejrzanie: brak cudzysłowów, literówki w zmiennych, bashizmy w #!/bin/sh, setki typowych pułapek. Niczego nie uruchamia, tylko czyta, jak bash -n, ale zna nie tylko gramatykę, lecz także złe nawyki.

Instalacja:

sudo apt install shellcheck        # [Ubuntu]
sudo dnf install ShellCheck        # [RHEL] z repozytorium EPEL

[RHEL] Na Red Hacie i pochodnych ShellCheck jest w dodatkowym repozytorium EPEL i nazywa się z wielkich liter. Jak włączyć EPEL, pokażę w lekcji o menedżerach pakietów. Do tego czasu możesz go wypróbować w przeglądarce na shellcheck.net, tylko nie wklejaj tam skryptów z hasłami.

shellcheck raport.sh

In raport.sh line 6:
if [ ! -d $folder ]; then
          ^-----^ SC2086 (info): Double quote to prevent globbing and word splitting.

Did you mean:
if [ ! -d "$folder" ]; then


In raport.sh line 17:
echo "Plików: $licznk"
              ^-----^ SC2154 (warning): licznk is referenced but not assigned (did you mean 'licznik'?).

Dwie sekundy. Oba błędy. Z numerem linijki, ze strzałką, z gotową poprawką. A przy drugim jeszcze pyta: „Czy chodziło ci o licznik?”. Lepiej niż autokorekta w telefonie, bo ta by poprawiła na „licznik gazu”.

Każde ostrzeżenie ma kod, na przykład SC2086. Pod kodem jest strona z wyjaśnieniem: https://www.shellcheck.net/wiki/SC2086. Czytaj je. To najlepszy darmowy kurs pisania skryptów, jaki istnieje, napisany na podstawie błędów milionów ludzi przed Tobą.

Po poprawkach:

$ shellcheck raport.sh && echo "czysto"
czysto
$ ./raport.sh "Moje logi"
Moje logi/app.log: 2 linii
Moje logi/db.log: 1 linii
Plików: 2

Kiedy ShellCheck się myli albo robisz coś celowo, możesz mu powiedzieć „wiem, co robię” komentarzem nad linijką:

# shellcheck disable=SC2086

Tylko nad tą jedną linijką i tylko z konkretnym kodem. Wyłączanie wszystkiego na górze pliku to jak wyjęcie baterii z czujnika dymu, bo piszczy przy smażeniu.

Przydatne opcje: -S warning pokazuje tylko ostrzeżenia i błędy, bez drobnych uwag. -x pozwala mu zajrzeć do plików wczytywanych przez source, wrócimy do tego za dwa lekcje. Większość edytorów ma wtyczkę, która podkreśla błędy ShellChecka na bieżąco, w trakcie pisania. Zainstaluj ją dziś.

strace: podsłuch rozmowy z jądrem

Czasem skrypt jest czysty, kamera nic nie pokazuje, a program i tak zachowuje się dziwnie. Nie widzi pliku, choć plik tam jest. Wisi i nie wiadomo na czym.

Wtedy podsłuchujemy. Każdy program, żeby cokolwiek zrobić, otworzyć plik, coś zapisać, połączyć się z siecią, musi poprosić jądro. Te prośby nazywają się wywołaniami systemowymi, po angielsku system calls, w skrócie syscalle. To jak okienko w urzędzie, tylko jeszcze niżej: okienko między programem a jądrem. strace stoi przy tym okienku i notuje każdą prośbę i każdą odpowiedź.

sudo apt install strace     # [Ubuntu]
sudo dnf install strace     # [RHEL]

Przykład z życia. Skrypt kopii ma czytać ustawienia z pliku, a jeśli pliku nie ma, po cichu bierze domyślne:

#!/bin/bash
cel=/tmp/kopie
if [[ -r /etc/kopia.conf ]]; then
    # shellcheck source=/dev/null
    source /etc/kopia.conf
fi
echo "Kopiuję do: $cel"

Kolega przysięga, że wpisał w ustawieniach cel=/srv/kopie. A skrypt uparcie kopiuje do /tmp/kopie. Podsłuchujemy:

strace -f -e trace=%file ./kopia_conf.sh 2>&1 | grep kopia

execve("./kopia_conf.sh", ["./kopia_conf.sh"], 0x7ffd34acd788 /* 241 vars */) = 0
openat(AT_FDCWD, "./kopia_conf.sh", O_RDONLY) = 3
faccessat2(AT_FDCWD, "/etc/kopia.conf", R_OK, AT_EACCESS) = -1 ENOENT (No such file or directory)

Ostatnia linijka: skrypt pyta jądro „czy mogę czytać /etc/kopia.conf?”, a jądro odpowiada ENOENT, czyli „nie ma takiego pliku”. A kolega? Wrzucił plik do /etc/kopia/kopia.conf, do folderu. Zagadka rozwiązana bez czytania ani jednej linijki kodu.

Jak to czytać: po lewej nazwa wywołania, w nawiasie argumenty, po znaku równości odpowiedź jądra. Liczba zero albo większa zwykle znaczy sukces. Minus jeden z nazwą błędu znaczy porażkę, a nazwy są czytelne: ENOENT brak pliku, EACCES brak uprawnień.

Kilka przydatnych wariantów:

strace -f -Z -e trace=%file ./kopia_conf.sh   # tylko nieudane prośby o pliki
strace -o slad.txt -f ./kopia_conf.sh          # cały zapis do pliku
strace -c ls /etc                              # statystyka: ile czego wywołał
sudo strace -p 1234                            # podepnij się do działającego procesu

-f śledzi też dzieci, czyli każdą komendę, którą skrypt odpali. Przy skryptach to obowiązkowe, bo skrypt to głównie odpalanie innych programów. -p podpina się do procesu, który już działa, na przykład wiszącego od godziny. Zobaczysz, na czym czeka. Do cudzych procesów potrzebujesz sudo.

Uwaga: strace mocno spowalnia śledzony program, bo zatrzymuje go przy każdej prośbie do jądra. Na produkcji podpinaj się krótko i z głową. I pamiętaj, że w zapisie widać wszystko, co program czyta i pisze, łącznie z hasłami. Plik slad.txt traktuj jak poufny.

Jak to działa pod spodem

Cztery narzędzia, cztery różne poziomy.

bash -n uruchamia tylko pierwszą połowę pracy urzędnika: czytanie i rozbiór na części. Bash i tak zawsze najpierw rozbiera całą komendę złożoną, na przykład cały if aż do fi, a dopiero potem wykonuje. Z opcją -n zatrzymuje się po rozbiorze.

set -x działa w drugiej połowie. Bash po rozwinięciu zmiennych, gwiazdek i cudzysłowów, tuż przed uruchomieniem komendy, wypisuje ją na stderr z prefiksem z PS4. Dlatego widzisz wartości, a nie nazwy zmiennych.

ShellCheck w ogóle nie jest Bashem. To osobny program, który buduje sobie drzewo skryptu i przykłada do niego setki reguł. Skryptu nie uruchamia nigdy. Dlatego jest bezpieczny, ale też dlatego nie wie, co jest naprawdę w Twoim /etc.

strace korzysta z mechanizmu jądra o nazwie ptrace, tego samego, którego używają debugery. Jądro zatrzymuje śledzony proces przy wejściu do każdego wywołania systemowego i przy wyjściu z niego, a strace w tym czasie odczytuje argumenty i wynik. Dwa przystanki na każdą prośbę, stąd spowolnienie.

Ściąga flag