P

roblem: aplikacja uruchomiona na serwerze tomcat7 z nieznanych powodów w dość powolny, ale wykładniczy sposób zaczyna otwierać i przetrzymywać deskryptory plików. Z czasem skutkuje to osiągnięciem limitu otwartych plików i błędem: java.net.SocketException: Too many open files.

Na pierwszy rzut oka może wydawać się, że liczba połączeń (socket = otwarty plik) do aplikacji jest tak duża, że ich ilość osiąga standardowy limit systemu Linux (1024). Może wystarczy, więc zwiększyć globalny limit (sysctl – fs.file-max = 500000) otwartych plików i rozszerzyć ten dla użytkownika tomcat7?:

darkstar:~# cat /etc/security/limits.conf
tomcat7 hard nofile 65535
tomcat7 hard nproc 65535
tomcat7 soft nofile 65535
tomcat7 soft nproc 65535

Niestety to tylko odsuwa w czasie wystąpienie w/w problemu – ponieważ liczba deskryptorów nadal rośnie wraz z działaniem serwera – tylko teraz mają więcej czasu na osiągnięcie limitu. Polecenie: netstat -tapn | grep tomcat7 nie wskazuje ponad przeciętnej liczby połączeń – tym bardziej, że nie ma żadnych utrzymujących się ciągle w stanie CLOSE_WAIT itp. Czas przyjrzeć się, co dokładnie powoduje takie zachowanie. Pierwszym krokiem jest znalezienie głównego id procesu tomcat7 (pidof java) i sprawdzenie wszystkich jego: otwartych plików, bibliotek i gniazd sieciowych (lsof -a -p $PID). Pierwszym wpisem, który nie pasuje do reszty jest stan: can’t identify protocol. Okazuje się, że są to cieknące sockety, które zostały niepoprawnie zamknięte przez aplikację. Problem z głowy… Nie do końca – szczególnie, gdy aplikacja, którą obsługuje tomcat7 przyjmuje i jednocześnie nawiązuje połączenia do innych aplikacji (baza danych, inne API itd.). Wówczas nie do końca wiadomo, z której strony następuje błąd i gdzie go szukać w kodzie. Jak jednoznacznie stwierdzić, które połączenia powodują stopniową lawinę błędów?

W przypadku tego typu wycieku jest to o tyle trudne, że system po pozornym zamknięciu połączenia usuwa wszystkie informacje z /proc/net/*, dlatego polecenie lsof nie jest w stanie wyświetlić szczegółów. Ten stan rzeczy wymusza na nas potrzebę zarejestrowania tych połączeń, kiedy były jeszcze w tablicy systemu, a później dotrzeć do nich na podstawie numeru inode. W tym celu w osobnym terminalu należy zacząć zbierać stany tablicy połączeń na przykład z ostatniej godziny:

#!/bin/bash

x=1
while [ $x -le 3600 ]
do
  cat /proc/net/tcp > /tmp/tcp/$x.tcp
  sleep 1
  x=$(( $x + 1 ))
done

W drugim terminalu musimy teraz złapać niepoprawnie zamknięte połączenie:

lsof -a -p 27514 | grep protocol; lsof -a -p 27514 | grep -c protocol

Za każdym razem, jak wydamy polecenie, a liczba podsumowująca będzie większa niż poprzedniego polecenia (na przykład pierwsze zwróci 502, a później 503) wówczas należy skopiować listingi tych połączeń do dwóch różnych plików i porównać w celu odnalezienia połączenia, które przybyło, a jest niepoprawne:

darkstar~:# diff 1.txt 2.txt
479a481
> java    27514 tomcat7  659u  sock   0,7  0t0 6360969 can't identify protocol

Mając numer gniazda (659) możemy powiązać go z numerem inode i spróbować odnaleźć go w zrzucanych tablicach połączeń:

darkstar~:# cd /proc/27514/fd
darkstar:/proc/27514/fd# ls -al | grep 659
lrwx------ 1 tomcat7 tomcat7 64 May 14 15:31 659 -> socket:[6373860]
darkstar:/proc/27514/fd# grep 6373860 /tmp/tcp/*.tcp
/root/877.tcp: 124: 3FC2200A:803C 1C10400A:0050 01 00000000:00000000 00:00000000 00000000 \
402        0 6373860 1 ffff8801f21b8000 20 4 24 10 -1
/root/878.tcp: 125: 3FC2200A:803C 1C10400A:0050 01 00000000:00000000 00:00000000 00000000 \
402        0 6373860 1 ffff8801f21b8000 20 4 24 10 -1

Dość enigmatyczna informacja, ale bardzo prosto ją odszyfrować. Po zamianie wartości HEX na DEC i odwróceniu wpisów widać, że połączenie, które zostało niepoprawnie zamknięte nastąpiło pomiędzy adresami:

3FC2200A -> 63.194.32.10 -> 10.32.194.63 (port 803C -> 32828)
1C10400A -> 28.16.64.10 -> 10.64.16.28 (port 0050 -> 80)

Daje to już wyraźny kierunek poszukiwań błędu. W tym przypadku był to błąd klienta HttpClient, który niepoprawnie zamykał połączenia wysyłając dane do innej usługi API.

Więcej informacji: Using HttpClient properly to avoid CLOSE_WAIT TCP connections, HttpClient ConnectionManager CLOSE_WAIT