PHP Yii 1.1 log() is not writing to file as expected

Question

I have been given an application to keep running that is using Yii 1.1. For the time being I can not update it to Yii 2.0. The problem I'm having is that I'm trying to do some debugging with Yii::log() but it is only writing the first call of log() to the log file. I can't show the exact code but the idea is as follows.

public static function foo(){
   Yii::log('Entered foo()', 'dev', 'My.Code.Example');
   $thing = aDataBaseQuery();

   if($thing !== null){
      Yii::log('foo(): thing is not null', 'dev', 'My.Code.Example');
      Example::bar($thing);
   }
}

public static function bar($thing){
   Yii::log('Entered bar()', 'dev', 'My.Code.Example');

   if($thing !== null && $thing->column_name!='none'){
      Yii::log('bar(): got past first if', 'dev', 'My.Code.Example');
      
      $thing->setAttribute("column_name","some");
      $thing->save();
   }
}

The log file shows the 'Entered foo()' message, but none of the others. But I know it must be entering the if statment in bar() because the column_name of the expected database entry is updated to "some". So my question is, what could be causing the other 3 log lines to not write to the log?

EDIT: So after messing around with it for a while I'm more confused then when I started. I just added an else to the if statement in foo() so that it is:

public static function foo(){
   Yii::log('Entered foo()', 'dev', 'My.Code.Example');

   $criteria = new CDbCriteria();
   $criteria->condition = "status='false'";
   $thing = CActiveRecord::model()->find($criteria);

   if($thing !== null){
      Yii::log('foo(): thing is not null', 'dev', 'My.Code.Example');
      Example::bar($thing);
   } else {
      Yii::log('foo(): thing is null', 'dev', 'My.Code.Example');
   }
}

public static function bar($thing){
   Yii::log('Entered bar()', 'dev', 'My.Code.Example');

   if($thing !== null && $thing->column_name!='none'){
      Yii::log('bar(): got past first if', 'dev', 'My.Code.Example');
      
      $thing->setAttribute("column_name","some");
      $thing->save();
   }
}

The log reads

[dev] [My.Code.Example] Entered foo()
[dev] [My.Code.Example] foo(): thing is null

But when I query the database, the entry is updated so that column_name is some.

blue_dog_01 · Answer

Pretty confident I found the problem. There is a race condition somewhere in the application causing things to go wild.

Edit: So the problem is that logging happens after execution completes. There was a failure somewhere else in the application where a function was trying to recursively query over 274,000 rows forming an almost infinite loop.

So what happened was, the functions my question is about got called, it got far enough to change one attribute in the database entry, then it got stuck in the loop until it failed and no logging occurred for that run. On failure the function is set to try again, at which point it executes and displays that it can't find the database entry because it was edited enough for the query to not return that entry anymore.

PHP Yii 1.1 log() is not writing to file as expected

1 Answers