Samstag, 11. Februar 2023
Mit monit überwache ich die Grösse der Datei /var/log/php.log auf meinen Web-Servern und alarmiere mich, wenn die Datei die Grösse von 1 MB überschreitet. Das geht natürlich nur, wenn man mit logrotate sicherstellt, dass die Datei täglich rotiert wird. Und wenn man so (defensiv) in PHP programmiert, dass das Log nicht infos, notices, warnings und errors vollgepflastert wird. Um es noch schwieriger zu machen: Ich habe in php.ini error_reporting = E_ALL aktiviert, denn das motiviert Web-Entwickler (mich), ihren Code sauber zu halten.
Vor einigen Tagen machte ich mich daran, ein immer wiederkehrendes Problem zu lösen, welches das Log füllte: Ich greife die Werte meiner ZigBee Temperatur-Sensoren ab und speichere sie auf einem Server in eine Datenbank. Gleichzeitig cache ich den aktuellsten Wert eines Sensors als JSON auch unter dem Web-Root eines Virtualhosts, damit ich den aktuellen Wert rasch und umkompliziert per HTTP abfragen kann.
Immer wieder kam dabei vor, dass beim Dekodieren solcher JSON-Dateien ein Fehler auftrat. Schlussendlich programmierte ich eine Routine, die solche JSONs mit falscher Syntax entdeckte und kurzerhand löschte. Dementsprechend führten Anfragen für die Cache-Dateien bestimmter Sensoren anschliessend zu dutzenden Einträgen in php.log, weil die Cache-Datei nicht mehr gefunden werden konnte:
[08-Feb-2023 19:06:34 Europe/Zurich] E - json_decode() returned null for path "/var/www/app/cache/BathroomWindow.json" but payload is 128 bytes. JSON error: "Syntax error". Unlinking file assuming it is malformed. in /var/www/app/class.php:258 for URI (Referer: unknown) from IP 10.1.2.3 with User Agent "Mozilla/4.0 (compatible; cron/SERVER/USER/cron.sh)"
...
[08-Feb-2023 19:07:19 Europe/Zurich] E - Path "/var/www/app/cache/BathroomWindow.json" not found in /var/www/app/class.php:247 for URI (Referer: unknown) from IP 10.1.2.3 with User Agent "Mozilla/4.0 (compatible; cron/SERVER/USER/cron.sh)"
Erst wenn der Sensor wieder ein Lebenszeichen sendete, konnte das Cache-File neu erstellt werden, und die Fehlermeldungen hörten auf.
Doch wieso war die JSON-Syntax zerschossen? Um dem auf den Grund zu gehen, baute ich in die Subroutine, welche die Syntaxprüfung durchführt, noch eine zusätzliche Zeile hinzu, welches den Inhalt der kaputten JSON-Datei in das Log schrieb. Hier ein Beispielresultat:
[09-Feb-2023 20:06:29 Europe/Zurich] E - JSON payload: "{"utime":1675969548,"sid":"158d000XXXXXXX","deviceName":"Office Mario Door","open":true,"deviceType":"magnet","battery":100}":100}" in /var/www/app/class.php:259 for URI (Referer: unknown) from IP 10.1.2.3 with User Agent "Mozilla/4.0 (compatible; cron/SERVER/USER/cron.sh)"
Das letzte ":100} sollte wirklich nicht dort stehen und machte keinen Sinn. Es sah so aus, als ob die Datei zwei Mal geschrieben wurde: Zuerst mit einem längeren String, und gleich darauf mit einem kürzeren String. In der Tat ist es so, dass die ZigBee-Sensore manchmal innert Sekunden zwei oder mehrere Male Werte absenden. Könnte ich also einer Race Condition beim Schreiben von Dateie aufgesessen sein?
Wie man das löst? Wenn Prozess A die Cache-Datei schreibt, muss sie für andere Prozesse gesperrt werden. Tatsächlich kennt PHP das Flag LOCK_EX für file_put_contents(), und seit ich dieses mitgebe, hat sich das Problem (zumindest in den letzten 48 Stunden) nicht mehr wiederholt:
...
$res = file_put_contents($filename, $jsonOut, LOCK_EX);
...
