Schreibmaschine mit memory_limit

Normalerweise sitze ich nicht um 1:20 Uhr noch am Rechner, um PHP-Probleme zu debuggen. Insbesondere nicht, wenn’s keine bezahlte Auftragsarbeit ist, sondern nacktes „Ich! Will! Das! Verstehen!“. Aber genau sowas hatte ich heute. Nachdem ich vor einigen Tagen schon mal ergebnislos an dem folgenden Problem herumgedoktert hatte, habe ich mich heute nochmal darin verbissen.

Ein User betreibt einen Magento-Shop auf unserer Hosting-Plattform Uberspace.de. Dazu gehören auch einige Hintergrundjobs, und zwar unter anderem dieser hier, der ganz offenkundig am memory_limit scheitert:

[demosite@krypton ~]$ php -c ~/cli /home/demosite/html/www.demosite.tld/shell/indexer.php status 
PHP Fatal error:  Allowed memory size of 262144 bytes exhausted (tried to allocate 232 bytes) in /var/www/virtual/demosite/www.demosite.tld/app/code/core/Mage/Index/Model/Mysql4/Process.php on line 110

Moment mal – ein memory_limit von gerade mal 256K? Das kann ja eigentlich nicht sein. In der php.ini steht nämlich 512M, und das wertet PHP an sich auch korrekt aus:

[demosite@krypton ~]$ php -c ~/cli -i | grep memory_limit
memory_limit => 512M => 512M

Nun gibt’s aber ja auch die Möglichkeit, in PHP-Scripts zur Laufzeit mit ini_set() einzelne Einstellungen dynamisch zu ändern, also auch das memory_limit. Schauen wir also mal, wo das möglicherweise noch so passiert:

[demosite@krypton ~]$ grep -r memory_limit /var/www/virtual/demosite/www.demosite.tld | grep -v cache
/var/www/virtual/demosite/www.demosite.tld/lib/Varien/.svn/text-base/Pear.php.svn-base:        @ini_set('memory_limit', '256M');
/var/www/virtual/demosite/www.demosite.tld/lib/Varien/Pear.php:        @ini_set('memory_limit', '256M');
/var/www/virtual/demosite/www.demosite.tld/lib/Zend/Memory/.svn/text-base/Manager.php.svn-base:     * Default value is 2/3 of memory_limit php.ini variable
/var/www/virtual/demosite/www.demosite.tld/lib/Zend/Memory/.svn/text-base/Manager.php.svn-base:        $memoryLimitStr = trim(ini_get('memory_limit'));
/var/www/virtual/demosite/www.demosite.tld/lib/Zend/Memory/Manager.php:     * Default value is 2/3 of memory_limit php.ini variable
/var/www/virtual/demosite/www.demosite.tld/lib/Zend/Memory/Manager.php:        $memoryLimitStr = trim(ini_get('memory_limit'));
/var/www/virtual/demosite/www.demosite.tld/magiczoomplus/module/magictoolbox/core/.svn/text-base/magictoolbox.params.class.php.svn-base:@ini_set('memory_limit', '512M');
/var/www/virtual/demosite/www.demosite.tld/magiczoomplus/module/magictoolbox/core/magictoolbox.params.class.php:@ini_set('memory_limit', '512M');
/var/www/virtual/demosite/www.demosite.tld/.svn/text-base/payment_check.php.svn-base:ini_set('memory_limit', '1024M');
/var/www/virtual/demosite/www.demosite.tld/.svn/text-base/.htaccess.svn-base:  php_value memory_limit 128M
/var/www/virtual/demosite/www.demosite.tld/.htaccess:  php_value memory_limit 128M

Okay, kommt einige Male vor, durchaus auch mit wechselnden Werten, aber nirgendwo etwas mit 256K. Was also ist hier los?

XDebug muss her. Flugs kompiliert und die xdebug.so via zend_extension in die php.ini eingebunden und xdebug.auto_trace=1 gesetzt. Dann nochmal ausgeführt und geschaut, und siehe da – dreimal wird ini_set() aufgerufen:

[demosite@krypton ~]$ grep ini_set traces/trace.3557638816.xt 
    0.1443    8707248         -> ini_set() /var/www/virtual/demosite/www.demosite.tld/shell/abstract.php:117
    0.1443    8707384         -> ini_set() /var/www/virtual/demosite/www.demosite.tld/shell/abstract.php:117
    0.1444    8706736         -> ini_set() /var/www/virtual/demosite/www.demosite.tld/shell/abstract.php:123

Also mal geschaut, was an dieser Stelle so für Code steht – und das hat mich wirklich überrascht:

    /**
     * Parse .htaccess file and apply php settings to shell script
     *
     */
    protected function _applyPhpVariables()
    {
        $htaccess = $this->_getRootPath() . '.htaccess';
        if (file_exists($htaccess)) {
            // parse htaccess file
            $data = file_get_contents($htaccess);
            $matches = array();
            preg_match_all('#^\s+?php_value\s+([a-z_]+)\s+(.+)$#siUm', $data, $matches, PREG_SET_ORDER);
            if ($matches) {
                foreach ($matches as $match) {
                    @ini_set($match[1], $match[2]);
               	}
            }
            preg_match_all('#^\s+?php_flag\s+([a-z_]+)\s+(.+)$#siUm', $data, $matches, PREG_SET_ORDER);
            if ($matches) {
                foreach ($matches as $match) {
                    @ini_set($match[1], $match[2]);
                }
            }
        }
    }

Es kommt hier also Code zum Tragen, der bei der Ausführung eines PHP-Scripts auf der Kommandozeile eine .htaccess-Datei auswertet, die in diesem Kontext nun eigentlich überhaupt keine Rolle spielt – handelt es sich dabei doch um eine webserver-spezifische Konfigurationsdatei. Also flugs dort nochmal reingeschaut:

[demosite@krypton ~]$ grep memory_limit /var/www/virtual/demosite/www.demosite.tld/.htaccess
  php_value memory_limit 128M

Hm. Da steht aber auch nichts von 256K. Wo zum Kuckuck kommt das her? Also auf die Schnelle – es ist spät – schnell ein wenig Debugging-Code an die entsprechende Stelle gesetzt, um einfach mal auszugeben, was genau dort geschrieben wird (jaja, das ist nicht elegant, aber man muss auch mal pragmatisch sein dürfen):

               	foreach ($matches as $match) {
                    echo "setting '" . $match[1] . "' to '" . $match[2] . "'\n";
                    @ini_set($match[1], $match[2]);
                }

Die Ausgabe hat dann doch reichlich überrascht:

[demosite@krypton ~]$ php -c ~/cli /home/demosite/html/www.demosite.tld/shell/indexer.php status 
'etting 'memory_limit' to '128M
'etting 'max_execution_time' to '18000
PHP Fatal error:  Allowed memory size of 262144 bytes exhausted (tried to allocate 92 bytes) in /var/www/virtual/demosite/www.demosite.tld/app/code/core/Mage/Index/Model/Mysql4/Process.php on line 110

Auch dem ungeübten Betrachter wird auffallen, dass die Ausgabe nicht mit setting, sondern mit 'etting beginnt, und dafür nicht mit '128M' endet, sondern mit '128M. Was zum..? Es wird doch nicht..?

Ein kleiner Exkurs: Unix-Systeme benutzen andere Zeilenumbrüche als Windows-Systeme. Während unter Unix Zeilenumbrüche mit einem einzelnen line feed ("\n") separiert werden, werden unter Windows Zeilenumbrüche mit einem carriage return, line feed ("\r\n") separiert: Carriage return, der gute alte Wagenrücklauf wie bei der Schreibmaschine – am Hebel ziehen, um den Druckkopf wieder am Zeilenanfang zu positionieren; Druckwalze eine Zeile vorrücken lassen.

Und genau so sah das hier aus: Das zweite ' von '128M' ist nach vorne gerutscht; ein carriage return hat stattgefunden. Und das wiederum heißt, dass … Moment, kurz nachgucken …

[demosite@krypton ~]$ file /var/www/virtual/demosite/www.demosite.tld/.htaccess
/var/www/virtual/demosite/www.demosite.tld/.htaccess: ASCII English text, with CRLF line terminators

… richtig: Die Inhalte der .htaccess-Datei sind mit Windows-Zeilenumbrüchen gespeichert. Werden jene nun auf einem Unix-System eingelesen, was die Zeilen am „\n“ auftrennt, dann hat memory_limit hier faktisch nicht den Wert „128M„, sondern den Wert „128M\r“ – Wagenrücklauf inklusive. Und genau das ist es, was PHP nun so gar nicht schmeckt. Verdammte Axt!

Also los:

[demosite@krypton ~]$ dos2unix /var/www/virtual/demosite/www.demosite.tld/.htaccess
dos2unix: converting file /var/www/virtual/demosite/www.demosite.tld/.htaccess to UNIX format ...

Getestet:

[demosite@krypton ~]$ php -c ~/cli /home/demosite/html/www.demosite.tld/shell/indexer.php status 
setting 'memory_limit' to '128M'
setting 'max_execution_time' to '18000'
Product Attributes:            Pending
Product Prices:                Pending
Catalog Url Rewrites:          Pending
Product Flat Data:             Pending
Category Flat Data:            Pending
Category Products:             Pending
Catalog Search Index:          Running
Stock status:                  Pending

Problem gelöst. Script läuft. Nur noch die Debug-Zeile wieder rausnehmen. So, erledigt.

Und jetzt ist wirklich Zeit für’s Bett.