Znalezienie winowajcy wysokiego wykorzystania procesora na naszym serwerze WordPress

Kilka dni temu otrzymaliśmy wiadomość e-mail od naszego dostawcy hostingu (SiteGround) z informacją, że nasza witryna ma już „90% dozwolonego miesięcznego wykorzystania procesora” i że po przekroczeniu 100% „usługa internetowa będzie ograniczona” i możemy mieć „problemy z dostępem do niego”. Dość przerażające, prawda? Zdecydowanie była to całkowicie niepożądana sytuacja, którą musieliśmy jak najszybciej naprawić. Ale… od czego zacząć?

Dzisiaj chcieliśmy podzielić się z Wami naszym doświadczeniem w obliczu dość powszechnego problemu na stronach internetowych, wyjaśniając, co zrobiliśmy, aby zidentyfikować winowajcę i jak go rozwiązaliśmy . W ten sposób, jeśli napotkasz podobny problem, będziesz miał kilka pomysłów, jak zacząć…

Powody, dla których możesz mieć wysokie zużycie procesora

WordPress to system zarządzania treścią napisany w PHP. Oznacza to, że treść, którą obsługuje, jest generowana dynamicznie przez zestaw skryptów PHP: za każdym razem, gdy odwiedzający trafia na Twoją witrynę, WordPress przetwarza żądanie (co przypomina „proszę wyślij mi swoją stronę główną”) i generuje odpowiedź (w języku angielskim). w tym przypadku wysyła stronę główną). Oczywiście, odpowiadanie na żądanie wiąże się z pewnym wykorzystaniem zasobów serwera: trzeba przyjrzeć się samemu żądaniu, określić, do czego odwiedzający chce uzyskać dostęp, pobrać je z bazy danych, wygenerować odpowiedź HTML i tak dalej.

Jeden z powodów, dla których system pamięci podręcznej przyspiesza czas ładowania witryny, powinien być teraz dość oczywisty: w zasadzie oszczędza to czas przetwarzania. Kiedy konkretne żądanie pojawia się po raz pierwszy („wyślij mi swoją stronę główną”), WordPress uruchamia się i generuje odpowiedź. Jeśli pamięć podręczna jest na miejscu, przechowuje wspomnianą odpowiedź, zanim zostanie faktycznie wysłana do odwiedzającego. W ten sposób przyszłe żądania dotyczące tego samego zasobu (w naszym przykładzie strony głównej) nie wymagają już przetwarzania czegokolwiek przez WordPress; pamięć podręczna może odesłać wcześniej zapisaną kopię, oszczędzając w ten sposób czas i zasoby.

Mając na uwadze taką wydajność, nietrudno sobie wyobrazić, jakie są powody, dla których widzimy wysokie zużycie procesora na naszym serwerze:

• Otrzymujesz zbyt wiele próśb. Jeśli w tym samym czasie do Twojej witryny wchodzi wielu użytkowników lub otrzymujesz wiele nieuzasadnionych żądań (ktoś prawdopodobnie atakuje Twój serwer), WordPress będzie musiał przetworzyć wszystkie te żądania, a tym samym zwiększy się wykorzystanie zasobów serwera.
• Żądania są rozpatrywane powoli. Jeśli masz zainstalowanych wiele wtyczek lub niektóre z nich są z jakiegoś powodu nieefektywne, wszystkie żądania, które otrzymasz, potrwają dłużej niż to konieczne, ponieważ WordPress będzie uruchamiał dużo nieefektywnego kodu.

Wygląda więc na to, że pamięć podręczna jest dobrą ochroną przed tymi problemami, prawda? I rzeczywiście tak jest. Należy jednak pamiętać, że pamięć podręczna nie „rozwiązuje” problemu; po prostu go „ukrywa”. Należy o tym pamiętać, ponieważ istnieją funkcje WordPressa, których nie można buforować i dlatego zawsze będą wymagały działania WordPressa:

• Zadania zaplanowane za pomocą WP-Cron. WP-Cron to mechanizm WordPress do planowania zadań, które będą uruchamiane w przyszłości. Na przykład WordPress używa go do publikowania zaplanowanych postów.
• API REST WordPressa. REST API to interfejs, którego można używać z aplikacji innych firm do interakcji z witryną WordPress poprzez wysyłanie i odbieranie obiektów JSON. Niektóre żądania REST API mogą być buforowane (mianowicie żądania GET), ale inne nie (POST i PUT). Dlatego jest to coś, czego generalnie nie można buforować…
• Żądania AJAX w WordPress. Zanim mieliśmy REST API w WordPressie, musieliśmy używać jego API AJAX do tworzenia dynamicznych stron internetowych. To API jest dość podobne do API REST, ponieważ możemy go również użyć do wysyłania i odbierania informacji z serwera. To inny system, ale podlega tym samym ograniczeniom, co REST API.

Analiza problemu

Najpierw musimy określić , dlaczego w naszej witrynie wzrosło użycie procesora. Czy wzrosła liczba zapytań do naszej strony internetowej? Czy obsługa indywidualnych żądań jest teraz wolniejsza? Aby odpowiedzieć na te pytania, na naszym serwerze mamy bardzo przydatne narzędzie: dziennik dostępu .

Dziennik dostępu to plik tekstowy, w którym serwer rejestruje każde otrzymane żądanie wraz z przydatnymi informacjami na jego temat. W szczególności dziennik dostępu informuje nas, kiedy otrzymano żądanie (data i godzina), kto je wykonał (adres IP), jakiego zasobu zażądał (adres URL), czy żądanie zakończyło się powodzeniem itp. Oto przykład z naszego serwera :

 66.249.83.82 - - [22/Apr/2020:14:04:59 +0200] "GET /es/blog/imagenes-gratuitas-para-tu-blog/ HTTP/1.0" 200 22325 "-" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19" 66.249.83.84 - - [22/Apr/2020:14:05:02 +0200] "GET /es/wp-content/uploads/sites/3/2018/07/aziz-acharki-549137-unsplash-540x350.jpg HTTP/1.0" 200 10566 "https://neliosoftware.com/es/blog/imagenes-gratuitas-para-tu-blog/" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19" 66.249.83.82 - - [22/Apr/2020:14:05:02 +0200] "GET /es/wp-content/uploads/sites/3/2018/07/Screenshot-of-Unsplah-website-768x520.png HTTP/1.0" 200 399577 "https://neliosoftware.com/es/blog/imagenes-gratuitas-para-tu-blog/" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19" ... 188.79.17.218 - - [22/Apr/2020:14:06:14 +0200] "GET /es/blog/problemas-mas-comunes-de-wordpress/ HTTP/1.0" 200 110741 "https://www.google.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15" 188.79.17.218 - - [22/Apr/2020:14:06:16 +0200] "GET /es/wp-content/plugins/nelio-ab-testing/assets/dist/js/alternative-loader.js?version=52b0ff65c68ab39896d47d6ff673fd59 HTTP/1.0" 200 2763 "https://neliosoftware.com/es/blog/problemas-mas-comunes-de-wordpress/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15" 188.79.17.218 - - [22/Apr/2020:14:06:16 +0200] "GET /es/wp-includes/css/dist/block-library/style.min.css?ver=5.4 HTTP/1.0" 200 7627 "https://neliosoftware.com/es/blog/problemas-mas-comunes-de-wordpress/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15" ...

Przyjrzyjmy się temu bliżej:

• 66.249.83.82 . To jest adres IP urządzenia, które wysłało żądanie.
• 22/Apr/2020:14:04:59 +0200 . To jest dokładna data i godzina żądania.
• GET /es/blog/imagenes-gratuitas-para-tu-blog/ HTTP/1.0 . Następnie widzimy, że odwiedzający poprosił ( GET ) o post z naszego bloga (w języku hiszpańskim).
• Mozilla/5.0 (Linux; Android ... To jest agent użytkownika przeglądarki i podaje nam pewne informacje o urządzeniu i systemie operacyjnym, które wysłały żądanie.

Zwróć uwagę, jak nasz serwer otrzymał wiele żądań z tego samego adresu IP ( 66.249.83.82 ) po pierwszym. Może to wyglądać na atak, ale w rzeczywistości tak nie jest: strony internetowe zwykle zawierają kilka zasobów (obrazów, skryptów, stylów) i jest całkowicie normalne, że użytkownik uzyskujący dostęp do określonej strony internetowej w Twojej witrynie będzie wykonywał wiele żądań, aby je wszystkie pobrać .

Cóż, w naszym przypadku udało nam się zweryfikować, że rzeczywiście mieliśmy wyjątkowo dużą liczbę próśb. Właściwie ekstremalnie wysoki. Wiedzieliśmy o tym, ponieważ plik dziennika był znacznie większy niż zwykle.

Możliwym wyjaśnieniem byłoby to, że z jakiegoś powodu nastąpił szczyt odwiedzin… ale według Google Analytics tak nie było. A więc działo się coś innego.

Bardziej szczegółowa analiza dziennika dostępu pozwoliła nam zidentyfikować następujący fakt: ponad 15% wszystkich otrzymanych żądań pochodziło z tego samego adresu IP. I (bębenek) ten adres IP był naszym własnym serwerem sieciowym!

Identyfikacja sprawcy

W tym momencie w końcu wiedzieliśmy, że to nasz własny serwer wysyła tak wiele żądań, że wygenerował szczytowe użycie procesora. Ale dlaczego? Dlaczego tak się stało? Kto generował te prośby? To są trudniejsze pytania.

Najpierw ponownie przyjrzeliśmy się naszym dziennikom, filtrując według adresu IP i próbując zidentyfikować wzorzec, który mógłby rzucić nieco światła na omawiany problem:

 35.214.244.124 - - [22/Apr/2020:14:06:08 +0200] "GET /es HTTP/1.0" 301 - "https://neliosoftware.com/es" "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:06:08 +0200] "GET /es?..." "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:06:18 +0200] "GET /es?..." "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:07:21 +0200] "GET /es?..." "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:07:24 +0200] "GET /es?..." "php-requests/1.7-3470169" ...

i znaleźliśmy jeden: agentem użytkownika wszystkich tych nietypowych żądań był php-requests/1.7-3470169 . Ciekawe!

WordPress ma kilka funkcji, za pomocą których można wyzwalać żądania: wp_remote_request . Jeśli spojrzysz na kod źródłowy tych funkcji, zobaczysz, że zasadniczo zawierają one kilka metod z klasy o nazwie WP_Http . Ta klasa jest ciekawa, ponieważ domyślnie wszystkie żądania, które ona wysyła, ustawiają User-Agent na „WordPress/wersja”, więc możliwe, że ma to coś wspólnego z naszym problemem. Ale tak się nie stało… jeszcze.

Jeśli będziemy nadal sprawdzać kod źródłowy WordPressa, zobaczymy, że WP_Http używa wewnętrznie innej klasy WordPressa, aby faktycznie wysyłać żądania: Requests . I chłopcze, ta klasa jest interesująca: na samym początku jej definicji widzimy, że definiuje ona stałą o nazwie VERSION , której wartość to 1.7-3470169 . Nieco później używa tej stałej do zbudowania agenta użytkownika , który znaleźliśmy w naszych logach: php-requests/1.7-3470169 .

Znakomity! Potwierdziliśmy, że wszystkie te dziwne prośby, które otrzymujemy, pochodzą z naszej witryny WordPress. To prawdopodobnie oznacza, że ​​winowajcą jest wtyczka… ale która?

Pomysł, który musieliśmy rozgryźć, był dość prosty: jeśli zmodyfikujemy User-Agent tak, aby zawierał nazwę wtyczki korzystającej z klasy Requests , zobaczymy nazwę wtyczki w dzienniku dostępu naszego serwera. A to jest całkiem łatwe do osiągnięcia. Jedyne, co zrobiliśmy, to edytowanie funkcji Requests ' get_default_options za pomocą następującego fragmentu:

 $trace = debug_backtrace(); $files = []; foreach ( $trace as $log ) { if ( false !== strpos( $log['file'], '/wp-content/plugins/' ) ) { $files[] = $log['file']; } } if ( empty( $files ) ) { $debug = 'no-plugin'; } else { $plugins = array_map( function( $x ) { return preg_replace( '/.*\/wp-content\/plugins\/([^\/]+)\/.*/', '$1', $x ); }, $files ); $plugins = array_unique( $plugins ); $debug = implode( ' ', $plugins ); } $defaults['useragent'] .= " (NelioDebug {$debug})";

Zobaczmy, co robi krok po kroku:

• Najpierw otrzymujemy stos wykonania z debug_backtrace . Jest to funkcja PHP, która generuje ślad wsteczny, ujawniając wszystkie funkcje, które zostały wywołane, aby osiągnąć bieżącą.
• Dla każdego elementu w stosie wykonania mamy takie informacje, jak wywołana funkcja, plik i wiersz, w którym jest zdefiniowana, argumenty, z którymi została wywołana itp. To, na czym chcemy się skupić, to plik, w którym zdefiniowano funkcję: jeśli jest w wp-content/plugins , wiemy na pewno, że jest to funkcja zdefiniowana we wtyczce.
• Po przetworzeniu wszystkich elementów na stosie musimy po prostu pobrać nazwy (jeśli istnieją) wszystkich znalezionych wtyczek i uwzględnić je w zmiennej useragent .

Po rozszerzeniu WordPressa zgodnie z opisem, szybko zaczęliśmy sprawdzać, kto był winowajcą :

 35.214.244.124 - - [23/Apr/2020:10:59:08 +0200] "GET /es HTTP/1.0" 301 - "https://neliosoftware.com/es" "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:10:59:20 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:10:59:36 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:11:00:01 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:11:05:21 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culprit)" ...

Rozwiązywanie problemu

Gdy znaliśmy nazwę wtyczki, która narusza prawa, po prostu skontaktowaliśmy się z jej twórcą i poprosiliśmy o pomoc. Odpowiedzieli i powiedzieli nam, jak rozwiązać problem, podczas gdy pracowali nad właściwym rozwiązaniem. Na szczęście dla nas sytuacja szybko się poprawiła:

Jak widać, jedną z największych zalet wolnego oprogramowania jest to, że możemy badać kod źródłowy aplikacji, których używamy i dostosowywać go do naszych potrzeb. W tym przypadku byliśmy w stanie zmodyfikować sam WordPress, aby mógł ujawnić niektóre potrzebne nam informacje.

Mam nadzieję, że spodobała Ci się sztuczka polegająca na użyciu debug_backtrace , aby dowiedzieć się, kto uruchomił określoną funkcję. Jasne, nie jest to ortodoksyjna metoda, ale jest szybka do wdrożenia i, jak dotąd, zawsze okazała się niezwykle pomocna.

Polecane zdjęcie Michała Mancewicza na Unsplash.