AndiLeni
duplicate entries (INSERT INTO rex_pagestats_hash)
Hi, ich habe mehrfach täglich in meinen error_log "Duplicate entry"-Einträge wie diesen:
[27-Apr-2022 04:50:22 Europe/Berlin] Error while executing statement "INSERT INTO `rex_pagestats_hash` SET `hash` = :hash, `datetime` = :datetime" using params {"hash":"fb8322a94990ecb56cbeecf6de21749dd4b4652c","datetime":"2022-04-27 04:50:19"}! SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry 'fb8322a94990ecb56cbeecf6de21749dd4b4652c' for key 'PRIMARY'
Vielleicht hilft es bei der Aufklärung... Immer in Kombination mit drei (oder manchmal auch vier oder fünf) "headers already sent"-Einträgen wie diese:
[27-Apr-2022 04:50:22 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /htdocs/redaxo/src/core/lib/response.php:316)
[27-Apr-2022 04:50:22 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[27-Apr-2022 04:50:22 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
Eine Idee woran es liegen könnte?
Existiert der Hash eventuell mehrfach in der Tabelle rex_pagestats_hash?
Eigentlich sollte der entsprechende Eintrag für den Hash aktualisiert werden, wenn er bereits existiert.
Wenn du Zeit und Lust hast, kannst du schauen, welchen Wert getRows() bei dir hat.
Das ist diese Zeile: https://github.com/AndiLeni/statistics/blob/7f294edef3999ea1b1b80d1443a80ac1c64e9476/lib/stats_visit.php#L239
Dafür einfach eine Zeile davor eine Log-Message erzeugen.
Der Hash existiert und zwar genau mit dem Zeitstempel des error_logs. Nachdem der Fehler nicht bei jedem Seitenaufruf auftritt, sondern sporadisch... kann es sein, dass es mit der Geschwindigkeit der Seitenaufrufe zu tun hat? (Bots)
Schade, dass in der DB nicht im Detail geloggt wird, welcher Hash zu welchem genauen Seitenbesuch von welchem Besucher gehört. Das würde die Fehlersuche erleichtern.
Hab die Log-Message eingfügt. Schauen wir mal.
PS: Wo ich es gerade sehe... ein "LIMIT 1" wäre bei diesem Query an der von dir genannten Stelle sicher kein Fehler, da mit (getRows == 1) eh nur ein Eintrag abgefragt wird.
Den Fehler habe ich jetzt auch:
Error while executing statement "INSERT INTO rex_pagestats_hash SET hash = :hash, datetime = :datetime" using params {"hash":"a083070787a49cf4fbbabee9a5232e84c95be6ed","datetime":"2022-05-17 23:59:58"}! SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry 'a083070787a49cf4fbbabee9a5232e84c95be6ed' for key 'PRIMARY' |
|---|
Der Hash ist imho nicht eindeutig: https://github.com/AndiLeni/statistics/blob/7f294edef3999ea1b1b80d1443a80ac1c64e9476/lib/stats_visit.php#L231
Du könntest in rex_sql mit insertOrUpdate(); arbeiten.
Hätte das fast vergessen. Hatte ja wie vorgeschlagen den Code eingebaut. Es war eine Zeit lang Ruhe (vielleicht, weil ich den Cache gelöscht hatte) und dann ging es wieder los.
Hier das Ergebnis anhand eines log-Eintrages von Gestern:
[17-May-2022 01:17:06 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 0
[17-May-2022 01:17:06 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 0
[17-May-2022 01:17:06 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 0
[17-May-2022 01:17:07 Europe/Berlin] Error while executing statement "INSERT INTO `rex_pagestats_hash` SET `hash` = :hash, `datetime` = :datetime" using params {"hash":"308212d17fa5b1f942aa789f964ed82926025c10","datetime":"2022-05-17 00:00:00"}! SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '308212d17fa5b1f942aa789f964ed82926025c10' for key 'PRIMARY'
[17-May-2022 01:17:07 Europe/Berlin] Error while executing statement "INSERT INTO `rex_pagestats_hash` SET `hash` = :hash, `datetime` = :datetime" using params {"hash":"308212d17fa5b1f942aa789f964ed82926025c10","datetime":"2022-05-17 00:00:00"}! SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '308212d17fa5b1f942aa789f964ed82926025c10' for key 'PRIMARY'
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 01:17:07 Europe/Berlin] Cannot modify header information - headers already sent by (output started at /home/htdocs/redaxo/src/core/lib/response.php:316)
[17-May-2022 02:26:10 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 0
[17-May-2022 02:54:05 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 1
[17-May-2022 04:26:37 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 1
[17-May-2022 04:26:37 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 1
[17-May-2022 05:17:03 Europe/Berlin] [262] Statistics Fehlersuche. WERT $sql->getRows() == 0
@oioix handelt es sich um eine Live-Seite?
Dann sollte ganz unabhängig davon dringlichst das öffentliche error-reporting serverseitig ausgeschalten sein. Damit erledigen sich auch die Fehler Cannot modify header information im Log (und im Frontend bei den Besuchern!). Warnings und Notices sollten keine Fehlermeldungen im Frontend erzeugen dürfen.
Danke für den Hinweis. Serverseitig ist es eigentlich komplett ausgeschaltet. Kann passieren, wenn das Template mit einer ini-Anweisung von der Entwicklungsumgebung übertragen wird. Das log ist aber dennoch nicht zugänglich. Ein ooops kann natürlich erscheinen. Hab dank deinem Hinweis das Template um eine Serverabfrage erweitert.
Danke für das Feedback. Leider habe ich noch keinen offensichtlichen Fehler gefunden, wieso das Verhalten so ist :-(
@alxndr-w
Der Hash ist imho nicht eindeutig:
Das kann und soll er auch nicht sein.
Du könntest in rex_sql mit insertOrUpdate(); arbeiten.
Schaue ich mir gerne an. Auf der redaxo.org Seite zu rex_sql wird diese Funktion nicht erwähnt.
@oioix
Was nicht korrekt ist ider der Fall, dass WERT $sql->getRows() == 0 geloggt wird, aber daraufhin beim einfügen ein duplicate auftritt. Das sollte nicht passieren können, denn wenn der Hash bereits existiert müsste getRows() gleich 1 sein.
Leider enthalten die api docs die Methode nicht, aber bei richtiger Nutzung von Primärschlüssel und SQL kannst du dir das zählen sparen und das DBMS entscheidet für dich, ob der Eintrag erstellt oder geupdatet werden muss.
Im Hintergrund läuft dann https://werner-zenk.de/mysql/einfuegen_oder_aktualisieren_mit_on_duplicate_key_update.php
Da es offenbar mehrere hashes in einer einzigen Sekunde gibt (siehe error log) würde in "$hash_string = " ein microtime() oder eine Zufallszahl einfügen, damit der hash wirklich unique ist. Sekundengenau reicht hier offenbar nicht.
Übrigens ich sehe gerade... "datetime":"2022-05-17 00:00:00" in der error-Meldung deutet auch darauf hin, dass keine Zeit, sondern nur das Datum übergeben wird.
@oioix
Da es offenbar mehrere hashes in einer einzigen Sekunde gibt (siehe error log) würde in "$hash_string = " ein microtime() oder eine Zufallszahl einfügen, damit der hash wirklich unique ist. Sekundengenau reicht hier offenbar nicht.
Da habt ihr gerade einen Denkfehler 😅 Der Hash darf nicht unique sein, sonst könnte ich wiederkehrende Besuche nicht erkennen. Baue ich in den Hash ein microtime() ein, ist jeder Hash und somit auch jeder Aufruf neu und wird geloggt. Aber genau das möchte ich durch den Hash verhindern, nämlich häufige Aufrufe/DDOS/Bots/Spammer von der Erkennung auszuschließen.
Übrigens ich sehe gerade... "datetime":"2022-05-17 00:00:00" in der error-Meldung deutet auch darauf hin, dass keine Zeit, sondern nur das Datum übergeben wird.
Das ist korrekt. Für die Statistik "Besucher pro Tag" wird ein Hash ohne Stundenangabe gespeichert, für "Aufrufe pro Tag" mit Stundenangabe.
Ich werde auf "ON DUPLICATE" umstellen in der Hoffnung, dass das DBSM dann das Problem löst.
Dann wäre on duplicate aber tatsächlich verkehrt, außer du bildest einen unique-Schlüssel über hash+Datum.
Es sollte schon gehen. Geupdated werden muss, wenn der Hash existiert und die min_duration zwischen Aufrufen überschritten wurde. Eingefügt werden muss, wenn der Hash nicht existiert.
@alxndr-w das sollte das Problem beheben, wenn ich mich nicht täusche 😅 (Solange ich nicht aus Versehen was an der Logik kaputt gemacht habe)
https://github.com/AndiLeni/statistics/commit/8dda12251f27a35c32d8e1a98ce759b59acddd3e?diff=split
@oioix , @alxndr-w gibt es diesen Fehler weiterhin oder ist das Problem durch die Änderungen behoben worden?
Ich hatte kurz über den Code geschaut, das ist etwas redundant, nach dem Hash zu schauen, wenn er eh unique ist und per insertOrUpdate() angesteuert wird. Da kannst du dir das Nachsehen im Vorfeld sparen. Wir können uns gerne mal deinen Code gemeinsam anschauen, wenn du Zeit hast.
Das hatte ich auf deinen Vorschlag hin umgestellt :-)
Ich schließe das Issue mal, wenn noch was bei dir auftaucht, gerne nochmal rühren :-)
insertOrUpdate() ist ja auch richtig - die Vorprüfung kann dann weg. Das macht die Datenbank für dich.
Ja, passt. Kann geschlossen werden. Es gab schon seit langer Zeit keine Einträge mehr. Danke!