Seit gestern beschäftigte mich und Tom ein Problem mit einem gekauften WordPress-Theme (Paula von Themeforest) auf meinem Server:
Bei einem normalen Reload der Seite wurden oft mehrere Thumbnails nicht angezeigt. Bei mehreren Reloads hintereinander wurde auch die CSS-Datei nicht geladen, kurz danach wurde der zugreifende Client per 403er vom Server ausgesperrt.
Bei mir trat dieses Problem übrigens nicht auf, wenn ich die Seite komplett neu laden ließ (Strg + F5), Tom konnte das nicht ganz bestätigen.

Das ist natürlich nicht so sehr schön, also sah ich mal in die Logs. Dort tauchten dann diverse Fehlermeldungen auf, die sich meistens auf die timthumb.php des oben genannten Themes bezogen:

[Sun Sep 09 13:21:34 2012] [error] [client xx.xx.xx.xx] client denied by server configuration: /web/wordpress/wp-content/themes/paula/scripts/timthumb.php, referer: http://example.com/wordpress

Ich vermutete also entweder ein Rechteproblem in der Vhost-Konfiguration (dem war allerdings nicht so) oder zu offene Rechte für den Cache von Timthumb (suPHP mag 777 bekanntlich nicht). Auch das war allerdings nicht zutreffend.

Was mich stutzig machte war, dass im error.log fast ausschließlich Meldungen für timthumb.php vorlagen, dennoch ab und an auch Bilder nicht angezeigt wurden, die nicht über die Datei geladen wurden. Auch die CSS-Dateien haben ja mit Timthumb nichts zu tun, CPU-Load und Arbeitsspeicherauslastung waren voll im Rahmen, daran lag es also auch nicht. Und für gewöhnlich sperrt mich mein Server bei Problemen mit einem Script auch nicht aus.

Mein Verdacht fiel dann auf mod-evasive, der zur Abwehr kleiner DDoS-Angriffe eingesetzt wird. Ich habe die Restriktionen ein wenig gelockert (Pagecount auf 5 und Sitecount auf 100), was das Problem dennoch nicht behob. Die eingeschaltete Debugfunktion von Timthumb brachte wider erwarten zum Vorschein: Alles in Ordnung! Alle Bilder werden normal geladen oder aus dem Cache ausgeliefert:

[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.000158 : 0.000000]: Starting new request from xx.xx.xx.xx to /wordpress/wp-content/themes/paula/scripts/timthumb.php?src=http://example.com/wordpress/wp-content/uploads/2012/09/20120903_072704-Custom.jpg&w=594&h=350&zc=1, referer: http://example.com/wordpress
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.000280 : 0.000094]: Doc root is: /web, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.000605 : 0.000315]: Salt is: 1347189733-17614574, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.000954 : 0.000346]: cleanCache() called, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.001378 : 0.000420]: Cache was cleaned less than 86400 seconds ago so no cleaning needed., referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.001630 : 0.000250]: Is a request for an internal file: /wordpress/wp-content/uploads/2012/09/20120903_072704-Custom.jpg, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.001982 : 0.000349]: Found file as /web/wordpress/wp-content/uploads/2012/09/20120903_072704-Custom.jpg, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.002210 : 0.000224]: Local image path is /web/wordpress/wp-content/uploads/2012/09/20120903_072704-Custom.jpg, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.002594 : 0.000380]: Cache file is: ./cache/timthumb_int_c6eab4a5ece41e479b428c3bf43d117c.timthumb.txt, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.002764 : 0.000168]: Trying server cache, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.003009 : 0.000242]: Got request for internal image. Starting serveInternalImage(), referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.003137 : 0.000124]: Local image path is /web/wordpress/wp-content/uploads/2012/09/20120903_072704-Custom.jpg, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.003405 : 0.000266]: Calling processImageAndWriteToCache() for local image., referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.003747 : 0.000340]: Mime type of image is image/jpeg, referer: http://example.com/wordpress/
[Sun Sep 09 13:22:19 2012] [error] [client xx.xx.xx.xx] TimThumb Debug line 1127 [0.003977 : 0.000227]: Not adjusting memory size because the current setting is 128M and our size of 30M is smaller., referer: http://example.com/wordpress/

Da funktionierte also alles. Nachdem Tom mich bat, mod-evasive doch mal testweise auszuschalten war der Fehler allerdings weg. Im Nachhinein ist das auch sehr logisch: Für jedes selbst eingefügte Bild wird bei Paula die Datei timthumb.php bemüht. Wird das gleiche Bild zwei mal angezeigt, wird auch zwei mal die timthumb.php aufgerufen. Es kann also durchaus vorkommen, dass man für eine einzelne Seite ziemlich oft die timthumb.php aufruft.
Tut man das bei einem normalen Reload, möchte der Browser den eigenen Cache benutzen, ruft die timthumb.php aber dennoch auf. Da die Bilder nicht mehr heruntergeladen werden müssen, passiert das wohl in wenigen Millisekunden, was wiederum mod-evasive auf den Plan ruft (welcher DDoS vermutet).
Da meine Internetanbindung nicht besonders schnell ist, dauert das Laden der Bilder bei einem kompletten Neuladen etwas länger (der Browser läd ja ein Bild nach dem anderen), mod-evasive springt nicht an. Toms Anbindung wiederum ist schneller, so dass er auch dann ab und zu in den DDoS-Schutz rannte.

Fazit: Themes, die timthumb.php inflationär benutzen, machen im Zusammenpiel mit mod-evasive Probleme. Ich habe das Modul nun deaktiviert, da ich noch mehrere andere Programme zur DDoS-Abwehr einsetze wie beispielsweise hooheads “hoodog“.