Analiza zrzutów pamięci na przykładzie nginx

Zrzut pamięci (ang. core dump, memory dump) to zrzut zawartości pamięci procesu wykonywany w momencie jego wyjątkowego zakończenia (np. naruszenia ochrony pamięci – ang. segmentation fault, segfault).

Analiza zrzutów pamięci to technika przydatna gdy proces niespodziewanie kończy swoje działanie, a w logach, czy systemach monitoringu nie mamy wystarczających informacji aby tę sytuację wyjaśnić. W złożonych systemach zdarza się także, że trudno jest problem reprodukować, co z kolei znacznie utrudnia debugowanie, a w konsekwencji przygotowanie poprawki.

W niniejszym artykule posłużę się przykładem serwera nginx obsługującego setki tysięcy zapytań na minutę, z których kilka na dobę powodowało segfaulty widoczne w /var/log/messages. Logi nginx nie zawierały nic nt. tych zapytań, a przy tak dużym ruchu trudno było określić w inny sposób które żądania sprawiają problem. Analiza zrzutu pamięci pozwoliła znaleźć ten błąd bez konieczności reprodukowania go – wystarczyło przygotować środowisko i poczekać, aż wystąpi on po raz kolejny.

Przygotowanie środowiska

Na przygotowanie środowiska składają się dwa elementy:

• binaria skompilowane z włączonymi symbolami debugowania,
• konfiguracja zawierająca dyrektywę włączająca robienie zrzutów pamięci.

Niektóre dystrybucje Linuksa dostarczają binaria skompilowane z włączonymi symbolami debugowania. W systemach CentOS takie paczki dostępne są w repozytorium debuginfo. Jeśli nasza dystrybucja nie dostarcza takich paczek, lub używamy paczki, którą sami budujemy, pozostaje nam własnoręczna kompilacja kodu z włączonymi symbolami. Przełącznik do takiej kompilacji zależy od kompilatora. Dla GCC (ang. GNU Compiler Collection) jest to -g . Warto także wyłączyć optymalizacje, co w przypadku GCC możemy zrobić korzystając z -O0.

Opcje konfiguracji ustalające rozmiar i miejsce zapisu zrzutu pamięci oczywiście także zależą od programu, który debugujemy. Dla nginx są to:

worker_rlimit_core 500M;
working_directory /var/cores/;

Mając binaria skompilowane z włączonymi symbolami debugowania oraz konfigurację włączającą wykonywanie zrzutów pamięci, jedyne co nam pozostaje to czekać na wyjątkowe zakończenie programu, lub jeśli potrafimy, to je wywołać.

Analiza zrzutu pamięci

Po wystąpieniu błędu, w naszym przypadku segfaulta, zrzut pamięci znajdziemy w katalogu podanym w konfiguracji, czyli /var/cores:

# file /var/cores/core
/cores/core: ELF 64-bit LSB core file x86-64, version 1 (SYSV), SVR4-style, from 'nginx: worker process'
# ls -lh /var/cores/core
-rw-------. 1 root root 40M Jun 15 07:20 /var/cores/core

Analizę takiego pliku możemy przeprowadzić z użyciem GDB (ang. GNU Debugger), podając plik wykonywalny programu i plik zrzutu pamięci jako argumenty uruchomienia:

# gdb /opt/nginx/sbin/nginx /var/cores/core

GNU gdb (GDB) Red Hat Enterprise Linux (7.2-90.el6)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /root/nginx...done.

[New Thread 15105]
Missing separate debuginfo for /usr/lib64/libluajit-5.1.so.2
Try: yum --enablerepo='*-debug*' install /usr/lib/debug/.build-id/aa/ebf83fc74bba6f54c6de2185e238f6584634c6
Missing separate debuginfo for
Try: yum --enablerepo='*-debug*' install /usr/lib/debug/.build-id/12/7d04348e3782d988a26e1433edec8d70375208
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypt.so.1
...
Loaded symbols for /lib64/libnss_files.so.2
Reading symbols from /lib64/libnss_sss.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss_sss.so.2
Core was generated by `nginx: worker process                                       '.
Program terminated with signal 11, Segmentation fault.
#0  0x000000000041a80c in ngx_list_push (l=0x275dcd8) at src/core/ngx_list.c:38
38          if (last->nelts == l->nalloc) {
Missing separate debuginfos, use: debuginfo-install glibc-
...
(gdb)

W powyższym przykładzie widzimy ostrzeżenia o braku symboli (no debugging symbols found), ale dotyczą one bibliotek, które w naszym dochodzeniu nie będą potrzebne. Oczywiście jeśli potrzebowalibyśmy symboli także dla tych bibliotek, musielibyśmy je także przekompilować z opcją -g.

Pierwszym krokiem do określenia jak doszło do unicestwienia procesu jest wyświetlenie backtrace:

(gdb) backtrace
#0  0x000000000041a80c in ngx_list_push (l=0x275dcd8) at src/core/ngx_list.c:38
#1  0x0000000000525243 in ngx_http_set_header_helper (r=0x275dc70, hv=0x21c51d8, value=0x7fffc75d72a0, output_header=0x0)
    at /rhome/rpmbuild/BUILD/headers-more-nginx-module-0.261/src/ngx_http_headers_more_headers_in.c:251
#2  0x0000000000524fa6 in ngx_http_set_header (r=0x275dc70, hv=0x21c51d8, value=0x7fffc75d72a0)
    at /rhome/rpmbuild/BUILD/headers-more-nginx-module-0.261/src/ngx_http_headers_more_headers_in.c:168
#3  0x0000000000524f40 in ngx_http_headers_more_exec_input_cmd (r=0x275dc70, cmd=0x2b59180)
    at /rhome/rpmbuild/BUILD/headers-more-nginx-module-0.261/src/ngx_http_headers_more_headers_in.c:155
#4  0x0000000000523ad3 in ngx_http_headers_more_handler (r=0x275dc70)
    at /rhome/rpmbuild/BUILD/headers-more-nginx-module-0.261/src/ngx_http_headers_more_filter_module.c:319
#5  0x000000000045db6f in ngx_http_core_rewrite_phase (r=0x275dc70, ph=0x2b7e7b8) at src/http/ngx_http_core_module.c:894
#6  0x000000000045d9d1 in ngx_http_core_run_phases (r=0x275dc70) at src/http/ngx_http_core_module.c:840
#7  0x000000000045d948 in ngx_http_handler (r=0x275dc70) at src/http/ngx_http_core_module.c:823
#8  0x00000000004618d9 in ngx_http_internal_redirect (r=0x275dc70, uri=0x7fffc75d7460, args=0x7fffc75d7450) at src/http/ngx_http_core_module.c:2603
#9  0x00000000004683a6 in ngx_http_send_error_page (r=0x275dc70, err_page=0x21d7390) at src/http/ngx_http_special_response.c:570
#10 0x0000000000467f9b in ngx_http_special_response_handler (r=0x275dc70, error=400) at src/http/ngx_http_special_response.c:416
#11 0x000000000046dcf3 in ngx_http_finalize_request (r=0x275dc70, rc=400) at src/http/ngx_http_request.c:2320
#12 0x000000000046ad5d in ngx_http_process_request_line (rev=0x7fa1d28eb1f0) at src/http/ngx_http_request.c:1023
#13 0x0000000000469936 in ngx_http_wait_request_handler (rev=0x7fa1d28eb1f0) at src/http/ngx_http_request.c:499
#14 0x0000000000441241 in ngx_event_process_posted (cycle=0x2077e20, posted=0x77c750) at src/event/ngx_event_posted.c:33
#15 0x000000000043ed1b in ngx_process_events_and_timers (cycle=0x2077e20) at src/event/ngx_event.c:259
#16 0x000000000044bcfd in ngx_worker_process_cycle (cycle=0x2077e20, data=0x1) at src/os/unix/ngx_process_cycle.c:753
#17 0x00000000004485f2 in ngx_spawn_process (cycle=0x2077e20, proc=0x44bc05 <ngx_worker_process_cycle>, data=0x1, name=0x532403 "worker process", respawn=1)
    at src/os/unix/ngx_process.c:198
#18 0x000000000044b7d2 in ngx_reap_children (cycle=0x2077e20) at src/os/unix/ngx_process_cycle.c:621
#19 0x000000000044a462 in ngx_master_process_cycle (cycle=0x2077e20) at src/os/unix/ngx_process_cycle.c:174
#20 0x000000000041636c in main (argc=5, argv=0x7fffc75d7c78) at src/core/nginx.c:415

Powyższy backtrace pokazuje nam kolejno wywoływane funkcje. Ostatnią z nich jest ngx_list_push, a problem dotyczy linii 38 w pliku src/core/ngx_list.c. Polecenie frame pokaże nam ten kawałek kodu źródłowego:

(gdb) frame 0
#0 0x000000000041a80c in ngx_list_push (l=0x275dcd8) at src/core/ngx_list.c:38
38 if (last->nelts == l->nalloc) {

Widać tutaj odwołania do pamięci last->nelts i l->nalloc. Wartości zmiennych w GDB możemy podglądać przy użyciu polecenia print:

(gdb) print l
$1 = (ngx_list_t *) 0x275dcd8
(gdb) print last
$2 = (ngx_list_part_t *) 0x0

Okazuje się, że last wskazuje na adres 0x0. Próba odczytu danych spod tego adresu przez proces nginx oczywiście kończy się naruszeniem ochrony pamięci i unicestwieniem procesu. Mamy więc już bezpośredni powód segfaulta, ale dalej nie wiemy skąd w funkcji ngx_list_push wziął się wskaźnik równy 0x0 i jakie żądanie HTTP spowodowało ten błąd. Przy pomocy polecenia list możemy wyświetlić szerszy kontekst kodu źródłowego:

(gdb) list
33 void *elt;
34 ngx_list_part_t *last;
35
36 last = l->last;
37
38 if (last->nelts == l->nalloc) {
39
40 /* the last part is full, allocate a new list part */
41
42 last = ngx_palloc(l->pool, sizeof(ngx_list_part_t));

Widzimy teraz, że last = l-> last (linia 36). Z kolei wyświetlając jeszcze wcześniejsze linie kodu dowiadujemy się, że zmienna l jest parametrem funkcji ngx_list_push:

(gdb) list -
23 return NULL;
24 }
25
26 return list;
27 }
28
29
30 void *
31 ngx_list_push(ngx_list_t *l)
32 {

Aby prześledzić, skąd wziął się parametr l->last równy 0x0, musimy zmienić ramkę na wcześniejszą, tj. fukcji która wywołała ngx_list_push. W GDB możemy to zrobić używając frame i podając nr ramki widoczny na zrobionym wcześniej backtrace. W naszym przykładzie będzie to frame 1:

(gdb) frame 1
#1 0x0000000000525243 in ngx_http_set_header_helper (r=0x275dc70, hv=0x21c51d8, value=0x7fffc75d72a0, output_header=0x0)
at src/headers-more-nginx-module-0.261/src/ngx_http_headers_more_headers_in.c:251

h = ngx_list_push(&r->headers_in.headers);

Udało się nam więc ustalić, że problematycznym parametrem jest &r->headers_in.headers. Podobnie jak poprzednio dla funkcji ngx_list_push, tym razem w kodzie źródłowym funkcji ngx_http_headers_more_headers_in odszukujemy sprawiającą kłopoty zmienną r. Okazuje się, że jest to zmienna zawierająca dane żądania. Jej zawartość podobnie jak poprzednio możemy wyświetlić przy użyciu polecenia print:

(gdb) print *r
$3 = {signature = 1347703880, connection = 0x7fa1d2a6c448, ctx = 0x275e558, main_conf = 0x20793d0, srv_conf = 0x21c3350,
loc_conf = 0x21cf388, read_event_handler = 0x46eb7e <ngx_http_block_reading>,
write_event_handler = 0x45d94a <ngx_http_core_run_phases>, cache = 0x0, upstream = 0x0, upstream_states = 0x0,
pool = 0x275dc20, header_in = 0x2b81d78, headers_in = {headers = {last = 0x0, part = {elts = 0x0, nelts = 0, next = 0x0},
size = 0, nalloc = 0, pool = 0x0}, host = 0x0, connection = 0x0, if_modified_since = 0x0, if_unmodified_since = 0x0,
if_match = 0x0, if_none_match = 0x0, user_agent = 0x0, referer = 0x0, content_length = 0x0, content_type = 0x0,
...
request_start = 0x275f560 "GeT / HTTP/1.1\r\nUser-Agent: openvas\r\nHost: nginx-segfault\r\nAccept: */*\r\n\r\n",
request_end = 0x0, method_end = 0x0, schema_start = 0x0, schema_end = 0x0, host_start = 0x0, host_end = 0x0,
port_start = 0x0, port_end = 0x0, http_minor = 0, http_major = 0}

Ostatecznie ustalamy, iż błąd naruszenia ochrony pamięci wystąpił dla żądania z niepoprawną metodą HTTP (GeT / HTTP/1.1), wykonanego przez skaner podatności openvas.

Opisany błąd występuje w nginx co najmniej w wersji najnowszej na dzień 1 czerwca 2016, a ujawnia się w przypadku określonej konfiguracji z użyciem modułu headers-more-nginx-module. Poprawka dla nginx nie została przyjęta przez autorów, natomiast poprawkę dla modułu autor przygotował i opublikował w ciągu kilku godzin.

Marcin Teodorczyk
Gigaset Communications Polska