PHP-Created Logs Are Getting Corrupted While Writing

Question

I was capturing webpage viewer logs based on the PHP code below...

$viewerlog = "../SiteLogFiles/live-smoothstreaming-" . date('Ymd') . ".txt";
$fp = fopen($viewerlog,"a");
if ($fp) {
    fputs($fp,"-----------------------------------------------------------------------\r\n");
    fputs($fp,"Server Date:           $now\r\n");
    fputs($fp,"IP Address:            $ip\r\n");
    fputs($fp,"City:                  $city\r\n");
    fputs($fp,"State:                 $state\r\n");
    fputs($fp,"Country Name:          $countryname\r\n");
    fputs($fp,"Continent:             $continent\r\n");
    fputs($fp,"-----------------------------------------------------------------------\r\n");
    fclose($fp);
}

And it produces a log like this...

-----------------------------------------------------------------------
Server Date:           2013-01-06T05:32:06-06:00
IP Address:            157.55.32.61
City:                  Unknown
State:                 Unknown
Country Name:          United States
Continent:             North America
-----------------------------------------------------------------------
-----------------------------------------------------------------------
Server Date:           2013-01-06T06:02:40-06:00
IP Address:            157.55.32.187
City:                  Unknown
State:                 Unknown
Country Name:          United States
Continent:             North America
-----------------------------------------------------------------------

But every now and then, the logs would get corrupted and look like this...

-----------------------------------------------------------------------
Server Date:           2012-12-21T18:27:27-06:00
IP Address:            99.54.103.128
City:                  Columbus
State:                 Ohio
Country Name:          United States
Continent:             North America
-----------------------------------------------------------------------
-----------------------------------------------------------------------
Server Date:           2012-12-21T18:27:53-06:00
IP Address:            75.97.98.115
City:                  Palmerton
State:                 Pennsylvania
--------------------------------------Continent:             North America
Server Date:           2012-12-21T18:27:54-06:00
---------------------
IP Address:            70.76.36.232
City:                  Saskatoon
State:                 Saskatchewan
Country Name:          Canada
Continent:             North America
-----------------------------------------------------------------------
-----------------------------------------------------------------------
Server Date:           2012-12-21T18:28:04-06:00
IP Address:            173.17.240.190
City:                  Springfield
State:                 Missouri
Country Name:          United States
Continent:             North America
-----------------------------------------------------------------------

It may be worth noting that I'm using using http://www.easyjquery.com to get the location information from the IP address.

So, various people recommended using an SQL database for the logging, instead of the flat text log. With those recommendations, I was able to set up said SQL database. I was able to write 7 records in 1 second (as fast as I could hit F5), without issue.

The PHP code in use is as follows...

try {
    $dbh = new PDO("sqlsrv:Server=localhost;Database=ViewerLogs", "", "");
    $dbh->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION);
    $stmt = $dbh->query("INSERT INTO dbo.LiveSmoothStreaming (DateTime, Ip, City, State, Country, Continent) VALUES('$now', '$ip', '$city', '$state', '$countryname', '$continent')");
    $stmt->setFetchMode(PDO::FETCH_ASSOC);
    $dbh = null;
}
catch(PDOException $e) {
    echo $e->getMessage();
}

There is one problem, though. My flat text logs seem to be capturing more records than the SQL logs.

The flat text log is producing...

Tue 5:58pm  68.55.34.32 Laurel      Maryland    United States   North America
Tue 5:58pm  70.88.57.62 Port Charlotte  Florida United States   North America
Tue 5:59pm  98.19.198.54    Eastview        Kentucky    United States   North America
Tue 5:59pm  71.3.202.110    Cape Coral      Florida United States   North America
Tue 5:59pm  173.218.32.154  Branson     Missouri    United States   North America
Tue 5:59pm  184.38.238.64   Unknown     Unknown United States   North America
Tue 5:59pm  67.239.18.161   Naples      Florida United States   North America

And the SQL log is producing...

2013-02-05T17:58:45-06:00   68.55.34.32 Laurel      Maryland    United States   North America
2013-02-05T17:58:52-06:00   70.88.57.62 Port Charlotte  Florida     United States   North America
2013-02-05T17:59:06-06:00   71.3.202.110    Cape Coral  Florida     United States   North America
2013-02-05T17:59:23-06:00   67.239.18.161   Naples      Florida     United States   North America

You can see that, in just a couple of minutes, there are differences. Over the course of a couple of hours, the differences could be in the hundreds.

There was no corruption, in this particular flat text log, so I don't see how it could be wrong. That would point to an issue with the SQL logs. I looked in my PHP error log for possible issues and didn't see anything obvious (I just searched for the page in question and looked at those errors).

Are there any ideas about why SQL wouldn't be capturing records that the flat text log is? In my code, the SQL logging comes directly after the flat text logging (maybe putting SQL before flat text would produce inverse results?).

Answer 1

As far as I can see you can either use file locking, or syslog. Since you seem to want to have your app write uninterrupted blocks of text I think locking would be advisable.

$lockwait = 2;       // seconds to wait for lock
$waittime = 250000;  // microseconds to wait between lock attempts
// 2s / 250000us = 8 attempts.
$myfile = '/path/to/file.log';

if( $fh = fopen($myfile, 'a') ) {
  $waitsum = 0;
  // attempt to get exclusive, non-blocking lock
  $locked = flock($fh, LOCK_EX | LOCK_NB); 
  while( !$locked && ($waitsum <= $lockwait) ) {
    $waitsum += $waittime/1000000; // microseconds to seconds
    usleep($waittime);
    $locked = flock($fh, LOCK_EX | LOCK_NB);
  }
  if( !$locked ) {
    echo "Could not lock $myfile for write within $lockwait seconds.";
  } else {
    // write out your data here
    flock($fh, LOCK_UN);  // ALWAYS unlock
  }
  fclose($fh);            // ALWAYS close your file handle
} else {
  echo "Could not open $myfile";
  exit 1;
}

You can also use this slightly more complex algorithm to do a random 'backoff' wait similar to what TCP and CSMA/CD use to avoid congestion.

$max_wait   = 1000000; //  1 s

$min_interval = 10000; // 10 ms
$max_interval = 50000; // 50 ms

$cur_wait = $min_interval;
$tot_wait = 0;
$locked = flock($fh, LOCK_EX | LOCK_NB); 

while( !$locked && ($tot_wait <= $max_wait) ) {
  tot_wait += $cur_wait;
  usleep($cur_wait);
  cur_wait += rand($min_interval, $max_interval);
  $locked = flock($fh, LOCK_EX | LOCK_NB);
}
if( !$locked ) {
  echo "Could not lock $myfile for write within $lockwait seconds.";
} else {
  // write out your data here
  flock($fh, LOCK_UN);
}
fclose($fh);

If unable to get a lock the script gradually waits longer and longer periods of time between lock attempts until the time defined in $max_wait is exceeded.

After writing all this I'm thinking you might just want to consider inserting all of this into a database, and if you require a log file then have a cron job run once per day to write the file out in one go, and optionally empty the table.