PHP Erschwertes Debugging

[joschilein]

Ich habe ein kurioses Problem:
In meinem Backend funktioniert alles wunderbar. Nur an einer Stelle gibt es eine nicht enden wollende Seitenladezeit und auch das PHP-Timeout wird völlig ausgehebelt. Dementsprechend bekomme ich weder über Wincachegrind noch über Apache-Logs raus an welcher Stelle vielleicht eine Endlosschleife o.ä. sein könnte.

Eine mögliche Problemstelle sieht quasi so aus:

$section = $_GET['section'];
if ($section == 'Test'){
  KlasseABC::machmal();
} elseif ($section == 'Wasganzanderes') {
  KlasseABC::machmalwasanderes();
} elseif (...) {
  // ...
} else {
  echo 'So geht es aber nicht.';
}

Wenn ich das 'Test' in 'Test2' ändere und die Url entsprechend anpasse funktioniert alles problemlos. Bis es am nächsten Tag wieder nicht geht und eine Änderung auf 'Test' (oder jeden anderen Wert) dann wieder problemlos funktioniert. Ich spreche also definitiv den richtigen if-Block an, aber ich bekomme in diesem aufgehängten Status keine Debugausgabe raus (weder im Block noch vor dem Block, die() funktioniert auch nicht) und kann sogar die kompletten Anweisungen im Block auskommentieren und es passiert dennoch nichts. Das Problem kann also eigentlich auch nicht in den Aktionen liegen, die im if-Block gemacht werden. Wenn ich eine Url verwende, die in keinem Block gefangen wird, funktioniert der Rest drumherum auch problemlos - im Sinne von Seite wird geladen mit Fehlermeldung "Keine passende Eingabe" etc.

Als ob PHP wegen diesem Block (für diese Anfrage) komplett eingefroren wird. Warum gehen nicht mal die()'s vor dem Block? Warum kommt kein Timeout?

 

[DasGuru]

was sagt denn die error.log vom Apache ?

 

[leller]

Ohne exakte Begründung- also nur aus dem Bauch raus - klingt mir das nach einem Problem mit einem evtl. vorhandenem CompilerCache, da kleine unwichtige Änderung am Quelltext zunächst zur problemlosen Ausführung des Codes führen, und anschließend das gleiche Ergebnis (Problem) wieder auftaucht.
Schon mal in die Richtung geforscht?

Viele Grüße aus Berlin

leller

 

[joschilein]

Noch eine kleine Idee von mir: Vielleicht hat es irgendwas mit Cookies zu tun. Das sieht bei mir so aus: Ist man eingeloggt, wird bei jedem Aufruf ein neuer Token generiert und in Cookies und DB gespeichert, auch wenn man eingeloggt im Frontend unterwegs ist. Das funktioniert auch schon seit mehreren Wochen reibungslos und wurde seitdem nicht mehr umprogrammiert.

Wenn ich also das FE aufrufe (ausgeloggt), dann nach dem Login im BE die entsprechende Stelle aufrufe (sie funktioniert!), anschließend wieder was im FE mache (funktioniert!), erst dann friert diese Stelle im BE ein - während jede andere Aktion im BE und FE funktioniert.

Ich bekomme den Zustand durch künstliche Cookiemanipulation/-löschen aber nicht reproduziert. Vermutlich ist das also doch nicht das Problem. Zumal dieser "Trick" mit der Variablenendung ja nun auch keine Cookies beeinflussen dürfte.

was sagt denn die error.log vom Apache ?

Nix

CompilerCache[..]Schon mal in die Richtung geforscht?

Ähm nö. Ich wüsste jetzt nicht mal, dass ich einen installiert hätte. Aber müsste in dem Fall nicht auch ein zusätzliches die() vor dem if-Block zu einer neuen Cashingversion führen?

 

[ice-breaker]

PHP mal auf die neueste Version aktualisiert? Wäre das erste was ich machen würde.

 

[theHacker]

Irgendne magische Methode, die im "aufgehängten Block" ausgeführt wird?

 

[leller]

Ähm nö. Ich wüsste jetzt nicht mal, dass ich einen installiert hätte. Aber müsste in dem Fall nicht auch ein zusätzliches die() vor dem if-Block zu einer neuen Cashingversion führen?

Ja, da hast du recht.

Gruß aus Berlin

leller

 

[thrown-out]

mit dem pseudocode ists nicht ganz einfach...

wenn du magst, kannst du mir gern mal das script oder nen ftp schicken, dann sehe ichs mir mal an

mfg
simon

 

[MrToiz]

Du kannst dir ja auch ein eigenes Logfile schreiben lassen...

function l($text) {
  $fh = fopen('error.log', 'a');
  fwrite($fh, $text."\n");
  fclose($fh);
}
l('1');
$section = $_GET['section'];
l('2');
if ($section == 'Test'){
  l('3');
  KlasseABC::machmal();
  l('4');
} elseif ($section == 'Wasganzanderes') {
  l('5');
  KlasseABC::machmalwasanderes();
  l('6');
} elseif (...) {
  l('7');
  // ...
  l('8');
} else {
  l('9');
  echo 'So geht es aber nicht.';
  l('10');
}
l('11');

Natürlich nicht sonderlich performant, aber das müsste dir einen Hinweis geben, bis wohin das Skript ausgeführt wird.

 

[joschilein]

PHP mal auf die neueste Version aktualisiert? Wäre das erste was ich machen würde.

Hmm 5.3.5 ist drauf, 5.3.8 ist aktuell

Irgendne magische Methode, die im "aufgehängten Block" ausgeführt wird?

In dem Block wird ggf. gar nichts ausgeführt (wenn ich alles auskommentiere). Das wurmt mich ja gerade so.

wenn du magst, kannst du mir gern mal das script oder nen ftp schicken, dann sehe ichs mir mal an

Ähm ja, das sind mittlerweile rund 20.000 Zeilen über verschiedenste Dateien verteilt. Dazu auch nur rudimentär dokumentiert. Glaub mir, das wäre kein Spaß

Du kannst dir ja auch ein eigenes Logfile schreiben lassen... [..]
Natürlich nicht sonderlich performant, aber das müsste dir einen Hinweis geben, bis wohin das Skript ausgeführt wird.

Hmm, es passiert genau gar nichts. Aber das könnte natürlich auch was aussagen, denn..

Ich habe die Funktionsdefinition ganz an den Anfang der ersten Datei geschrieben und auch direkt dahinter einen ersten 'Init'-Aufruf. Bei jeder anderen BE-Seite (es wird immer die selbe php-Datei zuerst aufgerufen) wird ordnungsgemäß geloggt. Bei meiner heutigen Problemurl passiert nichts, nichtmal diese Init-Zeile. Auch ein die('test'); in der allerersten Zeile (natürlich nach dem <?php ) wird komplett ignoriert.

Könnte es nun also eher ein Apache-Problem sein?

Ich habe nun auch rausgefunden, dass schon ein zweites laden der selben Url dazu führt, auch ohne zwischenzeitliche FE-Aktion. Nachdem ich die Variable wieder umbenannt habe, funktioniert es - auf der neuen Url. Auf der alten ist es noch genauso eingefroren.

Als ob der erste Aufruf (wurde komplett geladen) dazu führt, das diese Url für den Tag eingefroren wird. Wenn es aber am Script liegt, müsste doch auf der neuen Url auch ab dem zweiten Aufruf alles tot sein?!

Und was passiert in dem ersten Aufruf: Ein paar MySQL-Abfragen und die Darstellung der Ergebnisse als Tabelle. Keine Klasse wird nur dort verwendet wird, nichts außergewöhnliches.

Und der Apache-Log? An irgendeiner zentralen Stelle wird regelmäßig ein E_USER_WARNING geworfen (suche ich gleich mal), ein paar Startschwierigkeiten wegen der Logfunktion und ansonsten scheinbar unspektakuläre Einträge zum Serverstart:

[Tue Nov 01 12:39:51 2011] [warn] pid file R:/xampp/apache/logs/httpd.pid overwritten -- Unclean shutdown of previous Apache run?
[Tue Nov 01 12:39:51 2011] [notice] Digest: generating secret for digest authentication ...
[Tue Nov 01 12:39:51 2011] [notice] Digest: done
[Tue Nov 01 12:40:06 2011] [notice] Apache/2.2.17 (Win32) mod_ssl/2.2.17 OpenSSL/0.9.8o PHP/5.3.4 mod_perl/2.0.4 Perl/v5.10.1 configured -- resuming normal operations
[Tue Nov 01 12:40:06 2011] [notice] Server built: Oct 18 2010 01:58:12
[Tue Nov 01 12:40:06 2011] [notice] Parent: Created child process 5292
[Tue Nov 01 12:40:09 2011] [notice] Digest: generating secret for digest authentication ...
[Tue Nov 01 12:40:09 2011] [notice] Digest: done
[Tue Nov 01 12:40:12 2011] [notice] Child 5292: Child process is running
[Tue Nov 01 12:40:12 2011] [notice] Child 5292: Acquired the start mutex.
[Tue Nov 01 12:40:12 2011] [notice] Child 5292: Starting 150 worker threads.
[Tue Nov 01 12:40:12 2011] [notice] Child 5292: Starting thread to listen on port 443.
[Tue Nov 01 12:40:12 2011] [notice] Child 5292: Starting thread to listen on port 80.
[Tue Nov 01 12:40:12 2011] [error] [client 127.0.0.1] client denied by server configuration: R:/xampp/htdocs/.htaccess
[Tue Nov 01 12:40:39 2011] [error] [client 127.0.0.1] client denied by server configuration: R:/xampp/htdocs/.htaccess
[Tue Nov 01 12:42:21 2011] [error] [client 127.0.0.1] E_USER_WARNING: Query.setVar(): Variable ..blabla..

zu Zeile 1: Nein, ich habe ganz sauber beendet.
zu Zeile 4: phpinfo sagt was von 5.3.5
zu Zeile 14+15: Keine Ahnung warum das kommt, in dieser .htaccess kommen nur die Befehle AddIcon, IndexOptions und 2x RewriteRule (die nichts mit diesem Projekt zu tun haben) vor. Diese Zeilen wiederholen sich danach auch nicht mehr
zu Zeile 16: Der ist von mir und kommt ständig wieder. Ab hier hat also letztlich der Browser was in dem Projekt gewollt.

 

[joschilein]

Das Problem besteht weiterhin.

Weiteres Detail das ich rausgefunden habe: Wenn man einen weiteren GET-Parameter anhängt, funktioniert auch die eingefrorene Url - es ist natürlich nicht 100%ig die selbe Url, aber der eingefrorene Teil kommt komplett darin vor. Im aktuellen Fall ist dieser Paramater gedacht um die Auswahl der dargestellten Seite zu verfeinern/zu filtern. Es liegt also definitiv ein Apache-Problem o.ä. vor, da beide Anfragen durch den selben if-Block aus dem ersten Post laufen.

Tja soll ich mir nun für die entsprechenden Menülinks einen zufälligen GET-Parameter anhängen? Ich möchte aber gerade hier eigentlich nicht die Adresszeile vollspamen, weil dort eh schon mit hashs gearbeitet wird und die Länge ja begrenzt ist..

 

[tobomator]

Bevor Du diesen IF Block, oder das ganze was jetzt nicht funzt, eingebaut hast, hat doch alles funktioniert oder ?
Wenn ja, dann würde ich nicht unbedingt davon ausgehen, es sei ein Apache Problem.

Ich habe Fehler in meinen Scripten vergeblich gesucht. Wenn Du mit Short Cuts arbeitest, dann könnte folgender Fehler vorliegen:
ein Steuerzeichen, welches zu Fehlinterpretationen führt.
Ich habe schon mal über eine Stunde nen Fehler gesucht. Die gleiche Datei gelöscht und neugeschrieben und es funzte.

Wenn es ein Prog gibt, das Steuerzeichen in einem Textdokument sichtbar macht, dann probier es mal auf diesem Weg.

Ist ne Vermutung, aber möglich wär es.
Wenn nicht, ich wüßt - ehrlich gesagt- nicht wo ich sonst noch was suchen könnte.

 

[joschilein]

Ja klar natürlich ging es erstmal. An irgendeinem Tag hat es nicht mehr getan, dieser seltsame Einfriereffekt ist aufgetreten und ich habe erstmal eine halbe Ewigkeit gebraucht um das Problem halbwegs einzugrenzen.

In Datei A ist diese if-Block-Geschichte, die steuert was überhaupt gemacht werden soll. Dort wurde im Prinzip schon länger nichts mehr verändert. Ich hatte Datei B gerade erweitert, die dann (und nur dann) angesprochen wird, wenn eben gewisse GET-Parameter zusammentreffen. Funktionierte super toll und funktioniert ja auch jetzt an jedem Tag für einen einzigen Aufruf - also kein parse error oder sonstewas. Aber ab jedem zweiten Aufruf der selben Url geht nichts mehr, nicht wenn ich Datei B komplett auskommentiere und nicht mal das die() in der ersten Zeile springt an - von einem timeout ist auch nichts zu merken.

Ich glaube mit den 20.000 Zeilen habe ich weit untertrieben. Alleine diese beiden Dateien haben zusammen ca. 5.000. Da ist nicht viel mit neu schreiben oder Zeichen finden. Außerdem wird wohl bald mal noch eine kleine Auswertungsfunktion anstehen, die die Zeilen automatisch zählt (wenn das doch das einzige Problem wäre )

PS: Aktuell habe ich es wirklich mal mit der angehängten Zufallszahl überbrückt. Ist zwar unschön aber schont die Nerven.

 

[tobomator]

schon mal probiert, wenn du eine neue Datei anlegst, und zeilenweise den alten code reincopierst, wie lange es läuft, oder ob es von anfang an nicht geht.

Erklär mir mal, auch gern per pn, wie das genau aufgebaut ist.
Vll ist in dem ganzen eine Schleife drin, die nicht verlassen wird, oder eine Abbruchbedingung wird nicht erfüllt.
Klingt nach einem "Schleifenproblem" - das nicht verlassen wird, aber in das immer wieder reingesprungen wird !

 

[joschilein]

Erklär mir mal wie es ein Schleifenproblem sein könnte, wenn..

• es beim ersten Aufruf funktioniert
• vor irgendeinem anderen Befehl (und damit auch vor jeder Schleife) testweise ein die() eingebaut ist und das nicht anspringt
• es zu keinem Timeout kommt (60 sec; kommt auch nach 10 min noch nicht).

 

[tobomator]

der IF Block wird nicht das Problem sein.
DIe FUnktionsaufrufe die darin passieren,musst du mal prüfen.
Darin befindet sich vll das Problem

 

[joschilein]

Dann zitiere ich mich mal selbst..

In dem Block wird ggf. gar nichts ausgeführt (wenn ich alles auskommentiere). Das wurmt mich ja gerade so.

 

[Helo]

Hallo joschilein,

da du schreibst, dass es jeden Tag einmal funktioniert versuch einmal folgendes:
- Ruf die Seite im Firefox auf, ruf die Seite erneut auf (-> sollte jetzt nicht mehr gehen)
- Ruf die Seite anschließend z.B. im Internet Explorer auf, ruf die Seite erneut auf und erneut und ...

-> Ab wann funktioniert die Seite im IE nicht?

Ich hatte mal dasselbe Problem, im FF funktionierte die Seite nach einem Neustart des Browsers genau einmal, im IE funktionierte sie immer. Fehler lag nicht beim Apache sondern wahrscheinlich an einem Steuerzeichen innerhalb des Codes, welches vom IE scheinbar ignoriert wurde, vom FF aber nicht. (<- Vermutung, da es nach einem Rewrite klappte)

 

[joschilein]

Hmm das scheint wirklich einen Einfluss zu haben, im IE geht es durchgehend, abgesehen davon dass mein IE das CSS komplett zerschießt. Wenn ich immer mal wieder das die() einbaue, reagiert der IE drauf (ggf. nur nach Hardreload) und der Firefox läuft immer ins Unendliche.

Tja und nach was soll ich jetzt suchen?
Ich habe mir mal das HTML-Ergebnis des IE und Firefox jeweils zeichenweise eingelesen und nach Ascii-Code sortiert (im Fall des gleichen angehängten Parameters, da der das eingebundene Menü beeinflusst).
Neben den üblichen Buchstaben, Zahlen und Sonderzeichen tauchen die Asciis 9 (je 10x), 10 (Firefox 822x, IE 677x) und 13 (Firefox 822x, IE 677x) auf. Alle anderen Zeichen sind gleich oft vertreten. Beide Ergebnisdateien sind 279KB groß.

Ich habe jetzt aber sicherheitshalber noch mal ohne den Parameter getestet. Dabei ist mir aufgefallen, dass der Firefox vor dem Aufhänger überhaupt keinen Quelltext anzeigen möchte. Der IE zeigt hingegen keine Änderung in der Zeichenverteilung (bis auf den erwarteten Unterschied wegen dem Menü).

 

[Darklord]

Hast du schonmal probiert ein Testserver mit xdebug aufzusetzen und damit den Fehler einzugrenzen?
Oder per Kommandozeile das Skript auszuführen, sofern das möglich ist.

Aufjedenfall ein sehr interessantes Phenomen.