PHP-script crasht op Zlib

[AW_Bos]

Mijn vraag

Ik heb net iets heel vreemd ontdekt. Ik heb een PHP-script die om een of andere reden op een bepaalde result uit mijn database lijkt te stoppen. Dit is de log, waar ik weinig wijzer van word. De code kan ik ook aanleveren als jullie willen, maar ik durf te wedden dat daar niks mis mee is, omdat het op andere results uit de database wel werkt. Zelf op de 1-op-1 testomgeving gaat het goed.

Alleen live weer niet...

code:

[Tue Mar 16 19:00:55.952887 2021] [deflate:error] [pid 31910:tid 139924382566144] [client ***:***:***:1:753f:3967:77cf:392f:13688] AH01386: Zlib error -2 deflating data ((null)), referer: https://www.*******.nl/*****/index.php?module=********&action=materieelnummers_multiedit

[Tue Mar 16 19:00:55.952903 2021] [proxy_fcgi:error] [pid 31910:tid 139924382566144] (20014)Internal error (specific information not available): [client ***:***:***:1:753f:3967:77cf:392f:13688] AH01075: Error dispatching request to : (passing brigade to output filters), referer: https://www.******.nl/******/index.php?module=********&action=materieelnummers_multiedit

Relevante software en hardware die ik gebruik

Eigen VPS met Directadmin
Cloudflare

Wat ik al gevonden of geprobeerd heb

Niet gek veel gevonden. Maar het lijkt erop dat zlib zich ergens in verslikt?
Ik heb PHP en Apache al herstart. Ook heb ik het geheugenverbruik op de VPS bekeken, en daar is ook niks mis mee. Maar het probleem blijft.

[RobIII]

En wat verwacht je dat we aan die anderhalve logregel kunnen zien?

Kun je iets vertellen over wat je probeert te doen? We weten niet eens wát je probeert te comprimeren. Ik neem aan dat je al gegoogled hebt op "php zlib error -2"? Of AH01386? Wat kwam daar uit?

Heb je een testcase gemaakt? Mogen we relevante(!) code zien?

[Voor 46% gewijzigd door RobIII op 16-03-2021 19:21]

[mjax]

Klinkt alsof er met een leeg bestand (0 bytes) wordt gewerkt.

[AW_Bos]

Ik kan mijn code hier wel plaatsen als je wilt, maar er gebeurt echt niks met zlib of comprimeren, dat kan ik je zeker wel vertellen Dus de zlib-module lijkt ergens op vast te lopen, en ik heb geen idee hoe ik dat kan debuggen.

Ook gebeurt het maar met een bepaalde resultset met data die ik uit mijn database haal met een paar queries.

Wel ben ik erachter gekomen dat de instelling; php_flag zlib.output_compression On de boel weer laat werken. maar dan is het wel vreemd dat ik een zlib-error krijg terwijl zlib eerst gewoon uitstond?

[RobIII]

AW_Bos schreef op dinsdag 16 maart 2021 @ 19:21:

Zie mijn edit en de link...

[mcDavid]

De logregels die je post lijken totaal niet op PHP errors? Hoe ben je tot de conclusie gekomen dat het probleem in de PHP-laag zit en niet gewoon in de webserver of zo?

Heb je de errorcodes al gegoogled? Zo te zien komen die rechtstreeks uit apache...

[AW_Bos]

Die link is erg fijn en leerzaam, maar ik kan dat niet rijmen met mijn code waar ik enkel een paar queries uitvoer. Ik doe niks met zlib in die functie.

Maar als iemand de code wilt zien:

PHP:

<?php
            $PagedQuery = new PagedQuery($db, $sql, $totalRows);
            $result = $db->query($sql);
            if ($result->num_rows == 0) {
                echo '<tr><td colspan="6">Geen materieelnummers gevonden</td></tr>';
            } else {
                $nummers_r = array();
                while ($nummers = $result->fetch_assoc()) {
                $nummers_r[] = $nummers;
                echo'
                    <tr>
                        <td width="25%"><input type="hidden" name="matid[' . $nummers['id'] . '][id]" value="' . $nummers['id'] . '" ><input type="text" name="matid[' . $nummers['id'] . '][nummer]" size="6" value="' . $nummers['nummer'] . '" ></td>
                        <td width="15%"><input type="text" name="matid[' . $nummers['id'] . '][aflevering]" size="14" value="' . $nummers['aflevering'] . '" class="datepicker" /></td>
                        <td width="15%"><input type="text" name="matid[' . $nummers['id'] . '][indienststelling]" size="14" value="' . $nummers['indienststelling'] . '" class="datepicker" /></td>
                        <td width="15%"><input type="text" name="matid[' . $nummers['id'] . '][gesloopt]" size="14" value="' . $nummers['gesloopt'] . '" class="datepicker" /></td>
                        <td width="15%">
                            <select size="1" name="matid[' . $nummers['id'] . '][status]">
                                <option value="In dienst" ' . ( ( "In dienst" == $nummers['status'] ) ? ' selected="selected"' : '') . '>In dienst</option>
                                <option value="In modernisering" ' . ( ( "In modernisering" == $nummers['status'] ) ? ' selected="selected"' : '') . '>In modernisering</option>
                                <option value="Museumtreinstel" ' . ( ( "Museumtreinstel" == $nummers['status'] ) ? ' selected="selected"' : '') . '>Museumtreinstel</option>
                                <option value="Terzijde" ' . ( ( "Terzijde" == $nummers['status'] ) ? ' selected="selected"' : '') . '>Terzijde</option>
                                <option value="Gesloopt" ' . ( ( "Gesloopt" == $nummers['status'] ) ? ' selected="selected"' : '') . '>Gesloopt</option>
                                <option value="In aanbouw" ' . ( ( "In aanbouw" == $nummers['status'] ) ? ' selected="selected"' : '') . '>In aanbouw</option>
                            </select>
                        </td>
                        <td width="15%">
                        <select name="matid[' . $nummers['id'] . '][Subcategory]" style="width:150px;">';
                                echo '<option>-- Maak een keuze --</option>';
                                foreach($subcategories as $subcategory) {
                                echo '<option value="'.$subcategory['ID'].'" ' . ( ( $nummers['Subcategory']  == $subcategory['ID'] ) ? ' selected="selected"' : '') . '>'.$subcategory['Name'].'</option>';
                                }
                                
                                
                        echo '</td>
                    </tr>
                    <tr>
                    <td colspan="6"><strong>Opmerking:</strong> <input type="text" name="matid[' . $nummers['id'] . '][opmerking]" size="91" value="' . $nummers['opmerking'] . '"></td>
                    </tr>
                    <tr>
                    <td colspan="6"><hr></td>
                    </tr>
                                ';
                }
            }

Het simpelste wat er bestaat (en wat ik binnenkort ga refurbishen), waar hij bij de foreach onderuit gaat.
Geen zlib-functies. En enkel op een bepaalde result-set uit de query (die bespaar ik maar even omdat ik niet verwacht dat die vreemd is.)

Het is 'opgelost' door Zlib op On te zetten in php.ini, maar dat is niet echt een oplossing vind ik.

- Waarom treedt het op?
- Hoe debuggen we dat, omdat het enkel op een bepaalde resultset komt?
- Waarom moet ik in PHP Zlib aanzetten om het 'op te lossen' terwijl het als het uit staat alsnog door Zlib veroorzaakt wordt?

[AW_Bos]

mcDavid schreef op dinsdag 16 maart 2021 @ 19:29:
De logregels die je post lijken totaal niet op PHP errors? Hoe ben je tot de conclusie gekomen dat het probleem in de PHP-laag zit en niet gewoon in de webserver of zo?

Heb je de errorcodes al gegoogled? Zo te zien komen die rechtstreeks uit apache...

Snap ik, maar er werd om relevante code gevraagd...
Het is iets in zlib zelf, maar hoe en wat? En waarom gebeurt het niet in dezelfde code op mijn test-domein?

Enige wat ik mij kan indenken:
- Iets braks met mijn /tmp
- Creatieve bug gevonden in mod_deflate. Misschien eens kijken of ik Apache kan updaten.

[Voor 18% gewijzigd door AW_Bos op 16-03-2021 19:44]

[DJMaze]

@AW_Bos denk eerder dat je een out of memory hebt.

Zet even je error_reporting en ini_set('log_errors') aan.
En doe exact hetzelfde zonder de fastcgi proxy/php-fpm (terminal command een optie?).

En zet zlib output compression uit in je php.ini.

[AW_Bos]

Errors worden verder gewoon op de achergrond gelogd, zoals je in de TS kan zien.

Out of memory zou kunnen, maar dan op PHP-niveau. Hoewel ik niet het idee heb dat met deze matige resultset dit op zou treden. Grotere resultsets werken wel, plus dat het per pagina gewoon netjes van een offset wordt voorzien.

Zlib output compression stond al uit, maar die heb ik aan gezet. Werkt nu wel goed.
Maar ik snap nog steeds niet waarom die error optreedt als het uit staat...

Mooi moment om binnenkort Apache even te herinstalleren. Ik kan ook eens kijken of ik het in mijn setup kan uitvoeren via fastcgi. Maar ik draai al jaren php-fpm met succes.

[Voor 7% gewijzigd door AW_Bos op 16-03-2021 20:28]

[DJMaze]

@AW_Bos als het geen out of memory is, dan is er iets anders met het geheugen aan de hand.
Ergens denkt het systeem "oh content-type:gzip, let's deflate" en dan blijkt er geen output buffer ((null)) te zijn.

Vandaar dat ik vroeg of je het commando los op de terminal kan uitvoeren zonder Apache.

Zo duurde het oplossen van deze geheugen bug 4 jaar.

[AW_Bos]

Goed idee, ik zal het eens proberen.

[MueR]

DJMaze schreef op dinsdag 16 maart 2021 @ 20:16:
@AW_Bos denk eerder dat je een out of memory hebt.

Zet even je error_reporting en ini_set('log_errors') aan.
En doe exact hetzelfde zonder de fastcgi proxy/php-fpm (terminal command een optie?).

En zet zlib output compression uit in je php.ini.

Zucht. Echt waar..

Een php out of memory exception zegt letterlijk PHP Fatal error: Out of memory. Welk deel van de error geeft jou aanleiding om wederom eens irrelevante onzin te roeptoeteren?

[DataGhost]

Wat is je setup precies? Browser -> proxy? -> webserver -> .....? -> php-fpm?

Uit welk logbestand komen deze errors? Als het goed is heb je namelijk met php-fpm een volledig apart logbestand van php (gedefinieerd in php.ini) en een volledig apart logbestand van je webserver, alsmede van alle tussenliggende stappen een aparte. Daarmee kan je al uitsluiten waar het probleem in ieder geval niet direct zit. Het forcen van zlib in php-fpm zorgt er namelijk als het goed is voor dat je webserver dit zelf niet meer doet. Dus wie weet zit er een bug in apache die slechts getriggerd wordt door de output van jouw script in dat specifieke geval.

Welke request headers komen er aan bij je php-fpm, en welke response headers komen daar weer uit?
Gebeurt het ook als je je (uiteindelijke) request met "Accept-Encoding: identity" doet?
Gebeurt het ook op een (zo goed als lege) pagina, al dan niet via php-fpm geserveerd, met exact dezelfde request headers en POST-data (indien van toepassing)?
Wat zie je als je error reporting maximaal zet op alle plekken (naar een logfile, dus niet per se naar de browser)?
Werkt het op de cli wel met dezelfde dataset?
En kan je je probleem proberen te verkleinen tot minder code waarmee het ook fout gaat, bijvoorbeeld door de hele while-body (dus niet de loop zelf) na regel 8 uit te commenten, om te zien of het überhaupt wel optreedt in het gedeelte waar jij denkt dat het zit, aangenomen dat het in je code zit?
Welke precieze versies heb je draaien? Zijn die exact hetzelfde op je testomgeving?

Edit: als ik naar de huidige source van apache kijk zie ik de error daar staan. Die wijst in principe op een bug in apache (ook al zie ik de bug zelf niet) of misschien in zlib, niet in php (die is dan immers al klaar) maar misschien wel getriggerd door jouw output, en zou zelfs kunnen duiden op een buffer overflow in apache:

quote: https://zlib.net/manual.html#Basic

Z_STREAM_ERROR if the stream state was inconsistent (for example if next_in or next_out was Z_NULL or the state was inadvertently written over by the application)

De "(null)" zou een foutmelding van zlib moeten zijn maar die is dus leeg, dat lijkt me ook niet helemaal de bedoeling dat lijkt normaal te zijn voor een Z_STREAM_ERROR. Maar zonder debugger is dit allemaal lastig uit te zoeken.
Een waarschijnlijke is dat de outputbuffer inderdaad null is, dat zal gebeuren als de memory pool voor dat request vol zit. Daar wordt verder niet direct op gecontroleerd voordat de boel bij zlib aankomt. Of en hoe je dit kan tunen, geen idee. Dit is via MaxMemFree te tunen (default is 2 MB als ik het zo zie, per pool, die bij bijv. event-mpm "shared" is binnen dezelfde thread). Daarmee is niet gezegd dat, als het dan wel werkt, het probleem daarmee opgelost is, dit is slechts symptoombestrijding. Zonder al te diep in de code te zitten is mijn gok dat dit aan de hand is, en ze een check vergeten zijn, maar de failure mode van die check zal hoe dan ook zijn dat je request niet fatsoenlijk geserveerd wordt. Maar het kan best zijn dat je config gewoon gaar is en je verschillende variabelen getuned hebt op een manier die niet lekker samenwerkt. Ik krijg het alleen zelf bij mij niet voor elkaar om het te triggeren met config-waarden die onmogelijk zouden moeten kunnen samenwerken, het blijft allemaal zonder errors goed gaan dus dat is ook niet helemaal de verwachting.
Anyway, lekker chaotisch weer, ik ga slapen.

[Voor 46% gewijzigd door DataGhost op 17-03-2021 04:27]

[Intrepidity]

MueR schreef op woensdag 17 maart 2021 @ 02:00:
[...]

Zucht. Echt waar..

Een php out of memory exception zegt letterlijk PHP Fatal error: Out of memory. Welk deel van de error geeft jou aanleiding om wederom eens irrelevante onzin te roeptoeteren?

We zien hier geen PHP errors maar waarschijnlijk webserver-errors. Beste kans dat de compressie in de webserver gewoon klapt op 0 bytes als het PHP proces het opgeeft.

[AW_Bos]

Dankjewel voor de tips @DataGhost . Ik ga eens proberen uit te zoeken om dit verder te debuggen. Klinkt zeker interessant. Hoewel ik wel zie dat er in mijn code een is_array() mist wat een hoop errors op de foreach geeft. Gelukkig geen 'showstopper'.

Misschien dat zlib vanwege een opzichzelfstaande bug zich verslikt in die fout? Maar de echte oorzaak is even een uitdaging. Ik ga het uitzoeken.

[Voor 15% gewijzigd door AW_Bos op 17-03-2021 14:33]

[DataGhost]

AW_Bos schreef op woensdag 17 maart 2021 @ 14:31:
Dankjewel voor de tips @DataGhost . Ik ga eens proberen uit te zoeken om dit verder te debuggen. Klinkt zeker interessant. Hoewel ik wel zie dat er in mijn code een is_array() mist wat een hoop errors op de foreach geeft. Gelukkig geen 'showstopper'.

Misschien dat zlib vanwege een opzichzelfstaande bug zich verslikt in die fout? Maar de echte oorzaak is even een uitdaging. Ik ga het uitzoeken.

Probeer het vooral te reproduceren met een kleinere testcase, en kijk ook of de exacte output van je php-script hetzelfde restultaat geeft als het als statische pagina los of via PHP geserveerd wordt, en ook de andere mogelijkheden die ik heb genoemd in mijn vorige post.

Daarnaast hoor je in testomgevingen (alsmede productie) volledige logging aan te hebben, naar een logfile (dus niet naar de eindgebruiker). Mijn persoonlijke mening is dat je zelfs geen enkele notice mag krijgen, geen undefined variable/index of wat dan ook. Zaken die toevallig een failure mode hebben waardoor het in de meeste gevallen "goed gaat" zullen vast eerder of later een groter probleem veroorzaken als de situatie subtiel anders is, of er iets aan de code gewijzigd wordt. Ook ben je minder geneigd om warnings e.d. op te lossen als je notices al negeert, terwijl die wel aangeven dat er iets aan je code niet helemaal netjes is. Op het moment dat er dan wel dingen in je log verschijnen weet je ook direct dat er iets niet klopt, in plaats van dat je denkt dat het allemaal maar normaal is.

[AW_Bos]

Oh wauw.....
Wil ik het debuggen, krijg ik het niet meer gereproduceerd....
Statisch verwerkt hij de HTML-code gewoon, maar ook dynamisch is er niks meer aan het handje.

Geen idee wat er mis was...

- Zou het te maken kunnen hebben met Cloudflare en een eventuele overdracht (handshake) tussen client-server-client wat niet lekker soepel verloopt? Ik weet niet of zlib hierin invloed kan hebben, het is een zomaar iets wat bij me in mij opkwam..
- Of misschien wat rotzooi in de /tmp waar die over struikelt wat inmiddels gepurged is?

Volgende keer maar direct de trukendoos openen als het gebeurt...

[DataGhost]

Zoals het er in Apache uit ziet, met mijn beperkte kennis over de rest van de codebase en zonder met een debugger gekeken te hebben, is het volgens mij gewoon een bug. Als er een nullpointer uit de alloc terugkomt wordt daar niet op gecontroleerd en zal het misgaan. Zlib checkt er zelf op, dus de boel crasht niet, maar er komt wel een error. In een van de bugreports (over iets anders) die ik gevonden heb lees ik dat het schering en inslag is dat de pointers uit de apache-allocator niet gecontroleerd worden door moduls alvorens ze te gebruiken, dus ik denk dat mijn theorie verder klopt. Het kan best dat het restarten van Apache ervoor gezorgd heeft dat de trigger-condities tijdelijk weg zijn, maar wil niet zeggen dat ze niet terug kunnen komen. Eventueel veroorzaakt of getriggerd door je config. Gelijktijdige andere requests kunnen het ook triggeren. Het zal in ieder geval niet aan je code liggen.

Je kan mod_deflate uitschakelen als je die verder niet gebruikt. Dat hangt een beetje van je config af of dat zo is. Dan wordt de buggy code in die module in ieder geval nooit uitgevoerd. Alternatief is compressie in php toepassen maar daarmee is ook niet gezegd dat heel zlib in apache dan geskipt wordt (als je mod_deflate dan wel aan laat) dus dat zal, net als alle andere wijzigingen, waarschijnlijk slechts een tijdelijke "oplossing" zijn. Anders proberen met een minimale en liefst statische testcase het probleem consistent te reproduceren zodat iemand er een debugger aan kan hangen en er een bugreport geschreven kan worden. Dat kan overigens ook zonder al die moeite al maar dan moet je dus eerst de code gaan lezen om zeker te weten dat je geen report doet van iets wat niet waar is.

[Matis]

Zou het kunnen dat er mogelijk gebruik wordt gemaakt van stdout /stdin /stderr bij het streamen van de zipfile?

En dat de logging interfereert (of interfereerde) met de data stream?

[AW_Bos]

Matis schreef op donderdag 18 maart 2021 @ 18:58:
Zou het kunnen dat er mogelijk gebruik wordt gemaakt van stdout /stdin /stderr bij het streamen van de zipfile?

En dat de logging interfereert (of interfereerde) met de data stream?

Hoe bedoel je? En welke zip-file? Want ik doe niks met zip-bestanden.
Enkel gzip-compressie, wat blijkbaar standaard was in Cloudflare terwijl het in mijn PHP uitstond.

[Matis]

Ik bedoelde zip stream, geen idee waarom ik file schreef.

[AW_Bos]

Matis schreef op vrijdag 19 maart 2021 @ 21:22:
Ik bedoelde zip stream, geen idee waarom ik file schreef.

Ik doe niets met stdout stdin of stderr. Ik houd het op een glitch.
Ik ga binnenkort apache en PHP eens updaten omdat het weer nodig is. Hopelijk was het de eerste en de laatste keer.

[Cartman!]

@AW_Bos Ongerelateerd aan je probleem maar het stuk code wat je laat zien is zeer waarschijnlijk nogal vatbaar voor XSS.

[Voor 4% gewijzigd door Cartman! op 26-03-2021 17:31]

[AW_Bos]

Cartman! schreef op vrijdag 26 maart 2021 @ 16:27:
@AW_Bos Ongerelateerd aan je probleem maar het stuk code wat je laat zien is zeer waarschijnlijk nogal vatbaar voor XSS.

Kan goed kloppen met deze legacy code.
Het is enkel in de admin verder, maar wat htmlspecialchars() over de output zou zeker niet mogen ontbreken.

Of het gerelateerd is aan het probleem weet ik niet, maar ik heb ook een is_array() toegepast op de $subcategories. Hier kwamen ook een hoop notices uit.

Jammer dat ik het niet kon debuggen omdat de behaviour opeens als sneeuw voor de zon verdween, maar als het weer speelt grijp ik direct in. Hoewel ik een vermoeden heb dat het met CloudFlare te maken heeft. Die heeft standaard gzip aan staan, terwijl Gzip op mijn server uitstond. Bij het aanzetten op mijn server ging het wel weer goed. En dat vind ik een beetje tegenstrijdig: Een gzip error terwijl het op de server uitstaat.

[Voor 17% gewijzigd door AW_Bos op 26-03-2021 18:46]

[kwaakvaak_v2]

AW_Bos schreef op vrijdag 26 maart 2021 @ 18:40:
[...]


Jammer dat ik het niet kon debuggen omdat de behaviour opeens als sneeuw voor de zon verdween, maar als het weer speelt grijp ik direct in. Hoewel ik een vermoeden heb dat het met CloudFlare te maken heeft. Die heeft standaard gzip aan staan, terwijl Gzip op mijn server uitstond. Bij het aanzetten op mijn server ging het wel weer goed. En dat vind ik een beetje tegenstrijdig: Een gzip error terwijl het op de server uitstaat.

Wel knap dat een externe dienst als cloudflare een error kan veroorzaken in een script wat server side runt.

[AW_Bos]

kwaakvaak_v2 schreef op vrijdag 26 maart 2021 @ 19:50:
[...]


Wel knap dat een externe dienst als cloudflare een error kan veroorzaken in een script wat server side runt.

Als je dit topic las dan weet je dat dit niet door het script veroorzaakt zal zijn, maar door gzip op de achtergrond zelf. Ik heb geen idee hoe de handshakes en de flow over en weer gaat bij gzip en een server of client. Maar ik kijk er niet gek van op als er ergens in dat proces wat spaak zou lopen.

[DataGhost]

AW_Bos schreef op vrijdag 26 maart 2021 @ 20:04:
[...]

Als je dit topic las dan weet je dat dit niet door het script veroorzaakt zal zijn, maar door gzip op de achtergrond zelf. Ik heb geen idee hoe de handshakes en de flow over en weer gaat bij gzip en een server of client. Maar ik kijk er niet gek van op als er ergens in dat proces wat spaak zou lopen.

Het enige wat de client kan doen is "Accept-Encoding: gzip" sturen, of niet. Meer invloed heeft die verder niet. Het is vervolgens aan je webserver om daar iets mee te doen, en/of aan PHP. Er is verder geen flow. Als de client om kan gaan met gzip is dat een teken voor de webserver om ervoor te zorgen dat de output ook gzip is (afhankelijk van hoe de configuratie precies staat). Dat proces is verder niks meer of minder dan plaintext -> gzip -> client en is volledig eenrichting. De foutmelding die je krijgt wijst op een probleem in Apache wat optreedt tijdens het gzippen van de datastream. Als PHP er al gzip overheen heeft gegooid zal die een header Content-Encoding: gzip sturen, die door je webserver herkend wordt als teken dat die niks meer hoeft te doen. Als je dus in de PHP-config gzip default aan zet skip je de bugged compressie in Apache, en doordat de webserver dus niks meer doet verdwijnt de fout, en ben je geneigd te denken dat het probleem in PHP zit terwijl dat eigenlijk niet zo is. Zonder verdere kennis over de precieze output van jouw PHP-script in de situaties dat het misging, is voor mij de enige logische aanname dat dit probleem net zo hard nog steeds kan optreden bij gewone statische data die niet gecomprimeerd is en niet door PHP geserveerd wordt.

En zoals ik eerder zei ziet het eruit als een allocatie-bug die willekeurig op kan treden, en dat ongetwijfeld herhaaldelijk zal doen in een bepaalde state (totdat de webserver herstart wordt). Het volledig uitschakelen van mod_deflate zou ervoor moeten zorgen dat dit niet meer kan gebeuren, maar dan heb je dus niet zomaar server-side compressie als je dat niet op een andere manier regelt.