[PHP/MySQL] Premature end of script headers

[egonolieux]

Ik heb een API endpoint waar ik in bulk JSON naar PUT. Daarbij krijg ik de volgende error (PHP-FPM 7.4, Apache 2.4.46, Ubuntu 20.04):

code:

[Sat Apr 24 09:13:27.944932 2021] [proxy_fcgi:error] [pid 112610:tid 140078236018432] [client ::1:39960] Premature end of script headers: index.php
[Sat Apr 24 09:13:27.944994 2021] [proxy_fcgi:error] [pid 112610:tid 140078236018432] [client ::1:39960] AH01070: Error parsing script headers
[Sat Apr 24 09:13:27.945003 2021] [proxy_fcgi:error] [pid 112610:tid 140078236018432] (22)Invalid argument: [client ::1:39960] AH01075: Error dispatching request to :

Mijn eerste vermoeden was een te kleine post_max_size, max_execution_time of memory_limit. Ik ben vervolgens in de PHP-FPM logs gaan kijken, maar daar was raar genoeg niets te zien. Voor de zekerheid heb ik de logs op debug gezet en catch_workers_output op yes. Ik heb vervolgens ook post_max_size op 100M, max_execution_time op 30s en memory_limit op 1024M gezet. Maar helaas... zelfde resultaat en niets in de logs.

De inhoud van de request body is een JSON array als volgt:

code:

[
  {
    "vendorId": 1,
    "currencyId": 1,
    "cardId": 8990,
    "cardVariantTypeId": 2,
    "cardLanguageId": 1,
    "cardConditionId": 4,
    "price": 228,
    "priceDate": "2021-04-24T03:24:12.1510714Z",
    "vendorProductUrl": "https://store.tcgplayer.com/pokemon/xy-evolutions/ninetales"
  }
]

Ik ben de grootte van de request body beginnen verlagen, in de hoop ergens een grens te bereiken waar het wel werkt. Die grens ligt blijkbaar op een 1140 items in de array. Vanaf 1141 items weer dezelfde fout. Dit deed me toch vermoeden dat er ergens een limiet bereikt werd, maar bij 1140 items wordt er 15MB geheugen gebruikt, < 1 MB request body, en een execution time van < 1s...

Om er 100% zeker van te zijn of dit probleem (niet) aan Apache/FCGI ligt, heb ik nogmaals geprobeerd met alle 80000 items in de JSON, maar dan met alle database calls naar MySQL uitgecomment. Succes, dit blijkt te werken.

Mijn focus ligt nu dus op MySQL (8). Mijn vermoeden is dat de database driver ergens op vast loopt zonder exception/error te tonen/loggen. Meer specifiek gebruik ik native queries met Doctrine DBAL, met de PDO driver. Ik verdeel de inserts in batches van 10000 en maak gebruik van MySQL batch inserts (meerdere rows per insert statement).

Na wat experimenteren met de batch size, lijkt het er op dat het niet uitmaakt of de batch size 100 of 10000 is, het loopt altijd vast vanaf 1141 rows, ook al wordt elke batch in een andere transaction gedaan. Voor zij die de betreffende code willen inkijken: https://gist.github.com/e...f052caff3d7e0a634a43cc390 (vanaf regel 105 gebeurt de batch).

Heeft iemand enig idee wat hier exact foutloopt? Zijn er bepaalde MySQL instellingen die hier van toepassing zijn?

[ValHallASW]

Het makkelijkste is denk ik om met een debugger (i.e., https://xdebug.org/) daadwerkelijk door een request-afhandeling heen te lopen. Dat kost wat moeite om op te zetten maar maakt het een stuk makkelijker om dit soort issues te tracen.

Een alternatieve optie is om extra logging statements toe te voegen & je logger zodanig te configureren dat 'ie de logs naar een file wegschrijft. Dan werken ze nog steeds als je geen response in je browser krijgt


Op basis van je beschrijving heb ik twee hunches:

• Is er iets geks met je 1141e entry? Een missend/leeg veld, unicode, ...? Wat gebeurt er als je die entry weghaalt? Wat gebeurt er als je dezelfde entry 1200x herhaalt?
• zou het kunnen dat er iets in je output tegen een limiet aanloopt?

[ACM]

Een snelle google search impliceert dat deze meldingen niet met de request maar met de response te maken hebben. Er zijn diverse varianten, teveel of te grote headers, een te kleine response (die klinkt wel erg onwaarschijnlijk).

Ik zou es kijken hoeveel header-data je terugstuurt naar apache. Heb je toevallig een logger/output geconfigureerd die e.e.a. als headers meestuurt?

[egonolieux]

Het makkelijkste is denk ik om met een debugger (i.e., https://xdebug.org/) daadwerkelijk door een request-afhandeling heen te lopen. Dat kost wat moeite om op te zetten maar maakt het een stuk makkelijker om dit soort issues te tracen.

Een alternatieve optie is om extra logging statements toe te voegen & je logger zodanig te configureren dat 'ie de logs naar een file wegschrijft. Dan werken ze nog steeds als je geen response in je browser krijgt

Dat heb ik inderdaad gedaan, zo ben ik op MySQL uitgekomen, maar er wordt helaas niets van errors getoond/gelogd.

Op basis van je beschrijving heb ik twee hunches:

• Is er iets geks met je 1141e entry? Een missend/leeg veld, unicode, ...? Wat gebeurt er als je die entry weghaalt? Wat gebeurt er als je dezelfde entry 1200x herhaalt?
• zou het kunnen dat er iets in je output tegen een limiet aanloopt?

Heb ik beiden ook getest , het maakt niet uit wat de inhoud van de entry is, het is altijd de 1141ste. Verder kan ik ook 80000 entries posten zonder problemen, zolang er geen database calls gebeuren.

Een snelle google search impliceert dat deze meldingen niet met de request maar met de response te maken hebben. Er zijn diverse varianten, teveel of te grote headers, een te kleine response (die klinkt wel erg onwaarschijnlijk).

Ik zou es kijken hoeveel header-data je terugstuurt naar apache. Heb je toevallig een logger/output geconfigureerd die e.e.a. als headers meestuurt?

Klopt, het is de response, maar ik denk eerder dat dit een generische error is dat fcgi geen response krijgt. De headers zijn hetzelfde bij 1140 of 1141 entries: enkel een Date en Cache-Control.

Maar goed, ik heb ondertussen wat verder gezocht en heb ontdekt dat MySQL een harde limiet op prepared statement parameters heeft, namelijk 65535. Bij een batch van 10000 items zit ik daar over, want er zijn 8 kolommen per insert. PDO/Doctrine lijkt deze error gewoonweg niet te tonen/loggen en er mee te stoppen. Ik heb dit kunnen confirmeren door even snel een aparte query uit te voeren onder en boven deze limiet.

Na de batch te verlagen, heb ik nog steeds hetzelfde probleem (zoals eerder vermeld), dus er moeten waarschijnlijk nog andere factoren meespelen. Ik experimenteer hier vandaag verder mee.

[eLScha]

Na hoeveel tijd krijg je deze melding in beeld? Ik vermoed namelijk dat je tegen de proxy time-out van Apache aanloopt.

[ValHallASW]

egonolieux schreef op zondag 25 april 2021 @ 08:28:
Dat heb ik inderdaad gedaan, zo ben ik op MySQL uitgekomen, maar er wordt helaas niets van errors getoond/gelogd.

Om het even concreet te maken: als je je batch size op 100 zet, en 1600 entries invoert, dan zie je 14x "100 card price entries have been replaced." in je log verschijnen en verder niets? (als je meer dan 14x dat bericht ziet dan is het niet puur een mysql-probleem).

Wat zie je als je logging toevoegt aan je catch (Exception $exception) blok? (als je maar 14x je log entry ziet én het exception-blok niet geraakt wordt dan suggereert dat die() ergens aangeroepen wordt... of dat er je proces door je OS onderuit wordt gehaald door bv een segfault).

Wat gebeurt er als je een command line script maakt waarmee je dezelfde inserts doet? (daarmee haal je php-fpm uit de vergelijking)

[Matis]

egonolieux schreef op zondag 25 april 2021 @ 08:28:
Klopt, het is de response, maar ik denk eerder dat dit een generische error is dat fcgi geen response krijgt. De headers zijn hetzelfde bij 1140 of 1141 entries: enkel een Date en Cache-Control.

Maar goed, ik heb ondertussen wat verder gezocht en heb ontdekt dat MySQL een harde limiet op prepared statement parameters heeft, namelijk 65535. Bij een batch van 10000 items zit ik daar over, want er zijn 8 kolommen per insert. PDO/Doctrine lijkt deze error gewoonweg niet te tonen/loggen en er mee te stoppen. Ik heb dit kunnen confirmeren door even snel een aparte query uit te voeren onder en boven deze limiet.

Na de batch te verlagen, heb ik nog steeds hetzelfde probleem (zoals eerder vermeld), dus er moeten waarschijnlijk nog andere factoren meespelen. Ik experimenteer hier vandaag verder mee.

Of het een goed idee is om 10.000 items in 1 keer te updaten kan ik niet beoordelen, maar het klinkt wat veel. Als je de JSON (of modellen) nu eens opknipt met https://www.php.net/manual/en/function.array-chunk.php en dan per 1000 tegelijkertijd een insert/update maakt in je prepared statement?

Werkt het dan wel?

[ValHallASW]

Matis schreef op maandag 26 april 2021 @ 18:29:
Of het een goed idee is om 10.000 items in 1 keer te updaten kan ik niet beoordelen, maar het klinkt wat veel. Als je de JSON (of modellen) nu eens opknipt met https://www.php.net/manual/en/function.array-chunk.php en dan per 1000 tegelijkertijd een insert/update maakt in je prepared statement?

Heeft de OP al geprobeerd:

egonolieux schreef op zaterdag 24 april 2021 @ 11:49:
Na wat experimenteren met de batch size, lijkt het er op dat het niet uitmaakt of de batch size 100 of 10000 is, het loopt altijd vast vanaf 1141 rows, ook al wordt elke batch in een andere transaction gedaan.

Dat is ook juist wat het zo vreemd maakt: je zou inderdaad verwachten dat een mysql-issue met slimmer batchen op te lossen is.

...ik bedenk me nu wel: dat gaat er wel vanuit dat het batchen correct werkt en niet bv. per ongeluk eerst een batch van 100, dan 200, etc doet... de moeite waard om te checken, want dat zou wel verklaren waarom de cutoff niet afhangt van de batch size.

[Matis]

ValHallASW schreef op maandag 26 april 2021 @ 20:32:
Heeft de OP al geprobeerd:

Je hebt gelijk. Ik had er over heen gelezen / anders geïnterpreteerd. Ik dacht dat hij het in batches aanbood aan de API. Niet dat het intern werd opgeknipt.

Dat is ook juist wat het zo vreemd maakt: je zou inderdaad verwachten dat een mysql-issue met slimmer batchen op te lossen is.

...ik bedenk me nu wel: dat gaat er wel vanuit dat het batchen correct werkt en niet bv. per ongeluk eerst een batch van 100, dan 200, etc doet... de moeite waard om te checken, want dat zou wel verklaren waarom de cutoff niet afhangt van de batch size.

Ik heb in de broncode gekeken, maar zie zo snel niets vreemds.

Het enige devies is inderdaad een debugger installeren en het script debuggen.

[Matis]

@egonolieux waarom doe je eerst een delete en daarna een insert? Waarom niet één van de drie smaakjes upsert?

[Voutloos]

De errorcode slaat op het aantal headers, dus ik zie niet direct waarom er van alles over sql gegokt wordt? Voegt die logger info call niet een response header voor elke row toe ofzo?

egonolieux schreef op zondag 25 april 2021 @ 08:28:
Klopt, het is de response, maar ik denk eerder dat dit een generische error is dat fcgi geen response krijgt. De headers zijn hetzelfde bij 1140 of 1141 entries: enkel een Date en Cache-Control.

Heb je de aanwezig headers écht bekeken?

[egonolieux]

eLScha schreef op zondag 25 april 2021 @ 09:26:
Na hoeveel tijd krijg je deze melding in beeld? Ik vermoed namelijk dat je tegen de proxy time-out van Apache aanloopt.

7 seconden, als ik alle database calls er uit laat en als ik `sleep()` voor 30s, geen errors.

Matis schreef op maandag 26 april 2021 @ 20:44:
Je hebt gelijk. Ik had er over heen gelezen / anders geïnterpreteerd. Ik dacht dat hij het in batches aanbood aan de API. Niet dat het intern werd opgeknipt.

Inderdaad, wordt intern in batches opgedeeld

Matis schreef op maandag 26 april 2021 @ 20:44:
Ik heb in de broncode gekeken, maar zie zo snel niets vreemds.

Het enige devies is inderdaad een debugger installeren en het script debuggen.

Dat doe ik ook, het probleem is dat alles gewoonweg stopt bij de database call: blijft hangen, geen exceptions, geen logs, niets.

Voutloos schreef op maandag 26 april 2021 @ 22:19:
De errorcode slaat op het aantal headers, dus ik zie niet direct waarom er van alles over sql gegokt wordt? Voegt die logger info call niet een response header voor elke row toe ofzo?


[...]
Heb je de aanwezig headers écht bekeken?

Yep, manueel naar de response gekeken, enkel de 2 eerder vermelde headers aanwezig.

---

Maar goed, het goede nieuws is dat ik ondertussen het probleem opgelost heb! Hoe?

Wel, het eerste probleem zat hem bij de limiet op parameters bij prepared statements, deze is 65535. 8 kolommen en 10000 per batch + de deletes = 90000 parameters, te veel dus. Maar waarom loopt het dan vast op 1140 items? 1140 * 8 + 1140 (deletes) = 10260 parameters.

Wel, ik ben de data zelf beginnen debuggen, en wat nu blijkt, is dat er een aantal duplicates in zitten die er niet zouden mogen zijn... op 1141 was de eerste. Ik had reeds andere data omgewisseld op plaats 1141, maar toevallig was dit ook een duplicate entry die tussen de eerste 1140 zat, pech dus.

Waarom werd hier nooit een error voor getoond? Goede vraag. Ik weet niet wat intern binnen PDO/Doctrine gebeurt, maar ik vermoed dat vanaf een groot aantal parameters, de error gewoonweg niet gelogd wordt. Een bug of by design bij te veel data? Geen idee, het heeft me alleszins veel tijd gekost om dit uit te zoeken. Hetzelfde bij het te veel aan parameters: PHP stopt er gewoon mee, geen exceptions, geen logs, niets.

Uiteindelijk is het allemaal nog goed gekomen dus, bedankt voor de input

Matis schreef op maandag 26 april 2021 @ 20:44:
@egonolieux waarom doe je eerst een delete en daarna een insert? Waarom niet één van de drie smaakjes upsert?

Ahh, dat wist ik niet! Heb het juist uitgeprobeerd, scheelt heel wat in performance, bedankt!

[Voutloos]

Dat soort errors verdwijnt nooit zomaar, dus ik ben bang dat je ergens een te ruime catch{} hebt zonder logging, of het loggen van de error is ook een issue etc..

[egonolieux]

Voutloos schreef op dinsdag 27 april 2021 @ 13:55:
Dat soort errors verdwijnt nooit zomaar, dus ik ben bang dat je ergens een te ruime catch{} hebt zonder logging, of het loggen van de error is ook een issue etc..

Toch niet, als ik test met bvb 50 entries waarin dubbels zitten, krijg ik een exception zoals verwacht. Trek dat aantal op naar een hoog aantal zoals 5000, en dat is niet langer het geval...

[Voutloos]

Zie je in het geval van de error na 50 rows wel extra response headers?

[Janoz]

egonolieux schreef op dinsdag 27 april 2021 @ 06:12:
Yep, manueel naar de response gekeken, enkel de 2 eerder vermelde headers aanwezig.

Maar dat was waarschijnlijk het response welke Apache naar de browser gestuurd heeft. Je zult moeten kijken welke headers PHP naar Apache gestuurd heeft. Apache geeft immers aan dat het daar mis gaat en stuurt vervolgens een nieuwe fout pagina terug.