time() unterschlägt eine Ziffer?

[Patrick Andrieu]

Hallo alle!

Für die Neuauflage meines Page-Views-Counters (bis jetzt noch in der alten Form online: http://old.atomic-eggs.com/cgi-bin/html_log.cgi <- dies ist allerdings die Auswertung, der Code vom tatsächlichen Counter folgt weiter unten, allerdings schon der neue Code) lasse ich, anstatt wie bisher das komplette Datum (braucht Speicherplatz), lediglich den Unix-Timestamp in die Flatfile eintragen. Eine Dateizeile sieht dann so aus:

1234567890•zähldateiname•remotehost•ip•user-agent•referrer•auflösung•farbtiefe

(Jaja, mir ist klar, dass Auflösung und Farbtiefe (eigentlich auch der UA) vollkommen nichtssagend sind, aber die Interessenten sehen sowas gerne ;) )

Nun ja, und eben entdecke ich einen Bug in der Auswertung, schau in der Flatfile nach, und siehe da: In irgendeiner Zeile war der Timestamp statt 10-stellig nur 9-stellig, die 4. Ziffer von rechts aus gezählt fehlte. Das ergab dann der 7.12.1973 ;)

Wie kommt sowas? Durch das Speichern des Rückgabewerts von time() in $time?

Hier der Code:

#!/usr/bin/perl -w  
  
use strict;  
use me::Date;  
use CGI;  
use CGI::Carp qw(fatalsToBrowser);            # Nur während der Entwicklung  
use Net::hostent qw(gethost);  
  
my $cgi = new CGI;  
my $today = me::Date->new('de');  
my $time = time();  
my $month = @{$today->this_month}[0];  
my $year = $today->full_year;  
  
my $logfile = $month eq 'März' ? 'me/Maerz_'.$year : 'me/'.$month.'_'.$year;  
my $monthsfile = 'me/Monate_'.$year;  
my $sep = "\x07";                             # Separator ist das Bullet-Zeichen: •  
my $pic = 'http://old.atomic-eggs.com/old_pics/stats.gif';  
  
getHostName();  
  
sub getHostName {  
  my $h = gethost($ENV{REMOTE_ADDR}) || "";  
  my $host = $h ? $h->name : 'na';  
  write_log($host);  
}  
  
sub write_log  {  
  my $host = shift;  
  my $ua = $ENV{HTTP_USER_AGENT};  
  my $ip = $ENV{REMOTE_ADDR};  
  my $ref = $cgi->param('ref') || 'da';  
  my $page = $cgi->param('page') || 'np';  
  my $res = $cgi->param('res') || 'oj';  
  my $cDp = $cgi->param('cdp') || 'ne';  
  
  $ua =~ s#<script(.*?)</script># - Murks im User-Agent! - #gi;  
  $ua =~ s/^<noscript>.*$/Murks im User-Agent!/gi;  
  
  for ($host,$ua,$ref) {  
    $_ =~ s/$sep/-/g;  
  }  
  
  $ref = 'oj' if ($ref eq 'da' && $res eq 'oj' && $cDp eq 'ne');  
  
  my @logdata = ($time,$page,$host,$ip,$ua,$ref,$res,$cDp);  
  #                0     1    2     3   4    5   6    7  
  
  $| = 1;  
  
  my @lflines;  
  my @mflines;  
  my $count = 0;  
  
          # Logdatei öffnen, wenn existiert  
          # Wenn ja, Inhalt in @lflines einlesen, Anzahl Zeilen ermitteln und $count zuweisen  
          # Wenn nicht (else): @lflines ist ein leeres Array  
  if (-e "$logfile.txt") {  
    open FILE,"$logfile.txt" or die "Kann Logdatei $logfile.txt nicht öffnen. Grund: $^E.";  
    flock FILE, 2;  
    @lflines=<FILE>;  
    $count = $.;  
    close FILE;  
  } else { @lflines = (); }  
  
   open LOG,">$logfile.txt" or die "Kann Logdatei $logfile.txt nicht öffnen. Grund: $^E.";  
   flock LOG, 2;  
   $count++;  
   print LOG join ($sep, @logdata),"\n";  
   print LOG @lflines;  
   close LOG;  
  
          # Monatsdatei (Monate_YYYY.txt) öffnen, wenn existiert  
          # Wenn ja, Inhalt in @mflines einlesen, in letzter Zeile prüfen ob aktueller Monat  
          ##### - wenn aktueller Monat in letzter Zeile gefunden, nur die Page-Views-Zahl ändern  
          ##### - wenn nicht, Zeile mit aktuellem Monat hinzufügen  
          # Wenn Datei noch nicht existiert, Array @mflines's erstes Element definieren  
          # Die Datei wird im zweiten OPEN geöffnet und neu geschrieben (wenn nicht existent, wird angelegt und geschrieben)  
  if (-e "$monthsfile.txt") {  
    open MONTHS,"$monthsfile.txt" or die "Kann Logdatei $monthsfile.txt nicht öffnen. Grund: $^E.";  
    flock MONTHS, 2;  
    @mflines=<MONTHS>;  
    close MONTHS;  
    if ((split /$sep/, $mflines[-1])[0] eq $month) {  
      $mflines[-1] = join($sep, ($month,$count));  
    } else {  
      push @mflines, join($sep, ($month,$count));  
    }  
  } else { $mflines[0] = join($sep, ($month,$count)); }  
  
   open MONTHS,">$monthsfile.txt" or die "Kann Logdatei $monthsfile.txt nicht öffnen. Grund: $^E.";  
   flock MONTHS, 2;  
   print MONTHS @mflines, "\n";  
   close MONTHS;  
  
   print "Location: $pic\n\n";  
}

Oder hat die Tatsache irgendeinen Einfluß, dass bei den auskommentierten Zeilen das #-Zeichen nicht als erstes Zeichen steht, sondern diese eingerückt sind (das Forumsscript zeigt die Kommentare nicht grau an...)?

Viele Grüße aus Frankfurt/Main,
Patrick

[hotti]

hi Patrick,

Wie kommt sowas? Durch das Speichern des Rückgabewerts von time() in $time?

$time = time; # ist OK

Ich sehe nur eine Unbekannte, Verdächtige:

use me::Date;

Evnt. wird hier die time() Funktion verbogen? Oder der Wert in $time? Das Modul scheinst Du nicht zu verwenden, wenn Du ohnehin nur den Timestamp speicherst, nimms mal raus.

Hotte

[Patrick Andrieu]

Hallo hotti!

»» Wie kommt sowas? Durch das Speichern des Rückgabewerts von time() in $time?
$time = time; # ist OK

Eigentlich denke ich das auch, time() gibt lediglich eine Zahl zurück, kein Array, kein Grund zum Fehler...

Ich sehe nur eine Unbekannte, Verdächtige:
»» use me::Date;

Date.pm ist eine leicht abgeänderte Form meines Today.pm Moduls (Date::Today: Date::Today. Date.pm kann, im Gegensatz zu Today.pm, einen Timestamp entgegennehmen, z.B. einem aus der Datei gespeicherten. So wandle ich im Auswertungsskript den in der Flatfile gespeicherten Timestamp wieder in ein Datum um.

Hier brauche ich Date.pm nur, um den Monat und das Jahr zu ermitteln, es wird also an der Ausgabe von time() nichts umgebogen...

Viele Grüße aus Frankfurt/Main,
Patrick

[hotti]

hi Patrick,

Hier brauche ich Date.pm nur, um den Monat und das Jahr zu ermitteln, es wird also an der Ausgabe von time() nichts umgebogen...

Ach wer weiß, was da war. Trotzdem noch ne Frage: Wenn Du die fehlende Ziffer selbst ergänzt mit einer Ziffer von 0..9, ergibt sich da ein Datum/Uhrzeit, was in die Reihe passt? Wenn das passt, ist irgendwo ein "Stringproblem", ansonsten ist $time irgendwo total zertrampelt ;-)

Viele Grüße ausm Garten,
Hotte

[Patrick Andrieu]

Hallo hotti!

Ach wer weiß, was da war. Trotzdem noch ne Frage: Wenn Du die fehlende Ziffer selbst ergänzt mit einer Ziffer von 0..9, ergibt sich da ein Datum/Uhrzeit, was in die Reihe passt?

Genau. Der falsche Timestamp war in einer Zeile, die mit ca. 10 anderen von dem selben Besucher herrührten (IP und UA gleich). Die Ziffer 7 als vierte Ziffer von rechts im Timestamp fehlte, und nachdem ich sie wieder händisch eingetippt hatte, passte alles wieder: es passte zu dem »Weg«, den dieser bestimmte User auf der Site »gegangen« war.

Wenn das passt, ist irgendwo ein "Stringproblem", ansonsten ist $time irgendwo total zertrampelt ;-)

Ich habe echt keinen Plan. Ich arbeite nicht zum ersten Mal mit time(), aber es ist das erste Mal, dass ich sowas sehe.

Viele Grüße aus Frankfurt/Main,
Patrick

[Patrick Andrieu]

Re!

Heute war die Flatfile nur noch eine ganze Zeile lang, irgendwas funktioniert mit meinem File-Locking oder im restlichen Code anscheinend nicht richtig... Sieht so aus, als wäre der else-Zweig ausgeführt worden, obwohl die Datei existiert.

Viele Grüße aus Frankfurt/Main,
Patrick

[Struppi]

Heute war die Flatfile nur noch eine ganze Zeile lang, irgendwas funktioniert mit meinem File-Locking oder im restlichen Code anscheinend nicht richtig... Sieht so aus, als wäre der else-Zweig ausgeführt worden, obwohl die Datei existiert.

Oh, damit hatte ich auch schon zu kämpfen.

Was bei deinem Code auffällt, ist, dass du die Datei zwar lockst, aber dann wieder schliesst. Ein fundamentaler Fehler, da zwischen close und open ein anderer Prozess zugreifen kann.

Im Prinzip kann das auch zwischen open und flock passieren (und ist mir auch passiert), was aber wesentlich unwahrscheinlicher ist. Ein zuverlässiger Filelock ist sau schwierig.

Struppi.

[Patrick Andrieu]

Hallo Struppi!

Oh, damit hatte ich auch schon zu kämpfen.

Na, da fühlt man sich nicht so alleine ;)

Was bei deinem Code auffällt, ist, dass du die Datei zwar lockst, aber dann wieder schliesst. Ein fundamentaler Fehler, da zwischen close und open ein anderer Prozess zugreifen kann.

Du meinst hier:

  if (-e "$logfile.txt") {  
    open FILE,"$logfile.txt" or die "Kann Logdatei $logfile.txt nicht öffnen. Grund: $^E.";  
    flock FILE, 2;  
    @lflines=<FILE>;  
    $count = $.;  
    close FILE;  
  } else { @lflines = (); }  
  
   open LOG,">$logfile.txt" or die "Kann Logdatei $logfile.txt nicht öffnen. Grund: $^E.";  
   flock LOG, 2;  
   $count++;  
   print LOG join ($sep, @logdata),"\n";  
   print LOG @lflines;  
   close LOG;

?

Das Problem ist, dass ich gerne den jeweils letzten Eintrag oben in der Datei hätte. Zwar könnte ich im Auswertskript mit reverse arbeiten, aber das ist wieder ein Umkopieren von Arrays...

Deswegen erst öffnen zum Lesen, danach neu öffnen zum Schreiben. Im Code vom alten Counter gab es bisher nie Probleme (was sicher nicht bedeutet, dass es OK ist)... Wie könnte ich die Sperre besser setzen?

Ein zuverlässiger Filelock ist sau schwierig.

Den Eindruck habe ich auch... ;)

Viele Grüße aus Frankfurt/Main,
Patrick

[Alexander (HH)]

Moin Moin!

»» Ein zuverlässiger Filelock ist sau schwierig.

Den Eindruck habe ich auch... ;)

Und genau deswegen überlasse ich das Problem lieber einem RDBMS.

Oder notfalls lese ich hier nach, wie es richtig geht.

Alexander

[Patrick Andrieu]

Hallo Alexander!

Oder notfalls lese ich hier nach, wie es richtig geht.

Und ich bin gerade dabei, Christians Artikel neu zu studieren...

Viele Grüße aus Frankfurt/Main,
Patrick

[Patrick Andrieu]

Hallo Alexander!

Oder notfalls lese ich hier nach, wie es richtig geht.

Wäre diese (nur lokal getestete und dort funzende™) Lösung ok:

sub checkIfLogfile {  
  my $logfile = (@{getFilesName()})[0];  
  if (-e $logfile) {  
    write_log($logfile);  
  } else {  
    create_log($logfile);  
  }  
}  
  
sub create_log {  
  my $logfile = shift;  
  my @logdata = @{getLogData()};  
  my $count = 1;  
  open LOG,'>', $logfile or die "Kann Logdatei $logfile nicht öffnen. Grund: $^E.";  
  flock LOG, LOCK_EX or die "Sperren der Logdatei $logfile fehlgeschlagen. Grund: $^E";  
  print LOG join ($sep, @logdata),"\n";  
  close LOG;  
  #checkIfMonthsfile($count);  
}  
  
sub write_log {  
  my $logfile = shift;  
  my @logdata = @{getLogData()};  
  open LOG,'+<', $logfile or die "Kann Logdatei $logfile nicht öffnen. Grund: $^E.";  
  flock LOG, LOCK_EX or die "Sperren der Logdatei $logfile fehlgeschlagen. Grund: $^E";  
  my @lines = <LOG>;  
  seek LOG, 0, 0;  
  truncate LOG, 0;  
  print LOG join ($sep, @logdata),"\n";  
  print LOG @lines;  
  close LOG;  
  #checkIfMonthsfile($count);  
}

Viele Grüße aus Frankfurt/Main,
Patrick

[Struppi]

Wäre diese (nur lokal getestete und dort funzende™) Lösung ok:

Ich würde mich auf flock nicht verlassen, bzw. war mein Eindruck (man kann sowas ja nur bedingt testen) dass es auch fehlschlagen kann. Ich hatte trotz flock immer wieder Datenverluste, als eine ehemalige Seite von mir relativ hohe Zugriffszahlen hatte.

Ich denke der einzige halbwegs sichere Weg ist ein lock-file (Semaphore) mit der Prozessnummer. Wie es z.b. File::TinyLock macht. Oder eben wie es Alexander vorschlug, eine Lösung die es nicht braucht.

Struppi.

[Patrick Andrieu]

Hallo Struppi!

Ich denke der einzige halbwegs sichere Weg ist ein lock-file (Semaphore) mit der Prozessnummer. Wie es z.b. File::TinyLock macht.

Danke, werde ich ausprobieren, sobald die neue Lösung ebenfalls zu Probleme führt.

BTW, um auf die Frage vorhin zurückzukommen... ist Prüfen auf Vorhandensein einer Datei mit -e (if (-e "datei")) zuverlässig?

Viele Grüße aus Frankfurt/Main,
Patrick

[Alexander (HH)]

Moin Moin!

BTW, um auf die Frage vorhin zurückzukommen... ist Prüfen auf Vorhandensein einer Datei mit -e (if (-e "datei")) zuverlässig?

Nur insoweit, als dass das Ergebnis Dir sagt, dass zum Zeitpunkt des stat()-Syscalls eine Datei "datei" existierte. Was in den folgenden CPU-Zyklen passiert (z.B. ein zwischenzeitlicher Taskwechsel zu "rm -f datei"), garantiert dir niemand.

Der große Haken an Locking ist, dass es ATOMAR sein muß. Alles andere funktioniert nur zufällig so lange, bis wirklich mal zwei oder mehr Instanzen parallel laufen. Richtig interessant wird Locking, wenn mehr als ein CPU-Kern im Spiel ist, egal ob simuliert in Hyperthreading, oder echt (Mehrkern-CPUs, Mehr-CPU-Systeme). Wenn man Locking richtig testen will, braucht man ein System mit mehr als einem CPU-Kern, idealerweise mit zwei oder mehr unabhängigen CPUs.

Jedes ernst zu nehmende RDBMS hat diese Probleme gelöst. PostgreSQL und Oracle haben interne Locking-Mechanismen, die auch auf Mehr-CPU-Systemen absolut sicher funktionieren. MS SQL Server ist beim Locking gelegentlich "etwas" vermurkst und rennt gerne mal in einen Deadlock, der wird aber erkannt und gemeldet. Nicht schön, aber handhabbar. Die SQLite-Doku behauptet auch, dass SQLite mit parallelen Prozessen auf dem selben File umgehen kann. MySQL ist wohl meistens auch unproblematisch, je nach Storage. Genaue Erfahrungen mit SQLite und MySQL fehlen mir, deswegen die etwas wagen Formulierungen.

Alexander

[Patrick Andrieu]

Hallo Alexander!

Danke für die Erläuterungen.

MySQL

...steht bald auf dem Programm, wird für eine Aufgabe gefordert ;)

Viele Grüße aus Frankfurt/Main,
Patrick

[Beat]

Oder notfalls lese ich hier nach, wie es richtig geht.

http://perl.plover.com/yak/flock/samples/slide006.html
Trick #2a
        flock DATA, LOCK_EX | LOCK_NB  or exit;
        ...
        __DATA__

Auf so was muss man erst kommen.

mfg Beat

[Alexander (HH)]

Moin Moin!

»» Oder notfalls lese ich hier nach, wie es richtig geht.

http://perl.plover.com/yak/flock/samples/slide006.html
Trick #2a
        flock DATA, LOCK_EX | LOCK_NB  or exit;
        ...
        __DATA__

Auf so was muss man erst kommen.

Ja, das ist durchaus pervers. Vor allem ist __DATA__ notwendig, darf nicht weggelassen werden.

(Und es hat außer der Nutzung von flock nichts mit Patricks demolierter Datei zu tun.)

Alexander