Finally added a logging mechanism. Only one file has been converted at the moment. I'll go in pieces, as debugging goes on.

git-svn-id: file:///svn-source/pmgr/branches/yafr_20090716/site@436 97e9348a-65ac-dc4b-aefc-98561f571b83

app_model.php

@@ -42,6 +42,90 @@ class AppModel extends Model {
   var $useNullForEmpty = true;
   var $formatDateFields = true;
 
+  // Default Log Level, if not specified at the function level
+  var $default_log_level = 1;
+
+  // Function specific log levels
+  var $function_log_level = array();
+
+  // Force the module to log at LEAST at this level
+  var $min_log_level;
+
+  // Force logging of nothing higher than this level
+  var $max_log_level;
+
+
+  /**************************************************************************
+   **************************************************************************
+   **************************************************************************
+   * function: pr
+   *  - Prints out debug information, if the log level allows
+   */
+
+  function prFunctionLevel($level) {
+    $trace = debug_backtrace(false);
+    $caller = array_shift($trace);
+    $caller = array_shift($trace);
+    $function = $caller['function'];
+    $this->function_log_level[$function] = $level;
+  }
+
+  function _pr($level, $mixed, $checkpoint = null) {
+    $log_level = $this->default_log_level;
+
+    $trace = debug_backtrace(false);
+
+    // Get rid of pr/prEnter/prExit
+    $caller = array_shift($trace);
+
+    // The next entry shows where pr was called from, but it
+    // shows _what_ was called, which is pr/prEntry/prExit.
+    $caller = array_shift($trace);
+    $file = $caller['file'];
+    $line = $caller['line'];
+
+    // So, this caller holds the calling function name
+    $caller = array_shift($trace);
+    $function = $caller['function'];
+    $class    = $caller['class'];
+    //$class = $this->name;
+
+    // Adjust the log level from default, if necessary
+    if (isset($this->function_log_level[$function]))
+      $log_level = $this->function_log_level[$function];
+    if (isset($this->min_log_level))
+      $log_level = max($log_level, $this->min_log_level);
+    if (isset($this->max_log_level))
+      $log_level = min($log_level, $this->max_log_level);
+
+    // If the level is insufficient, bail out
+    if ($level > $log_level)
+      return;
+
+    if (!empty($checkpoint)) {
+      $chk = array("checkpoint" => $checkpoint);
+      if (is_array($mixed))
+	$mixed = $chk + $mixed;
+      else
+	$mixed = $chk + array($mixed);
+    }
+
+    pr(array("{$class}::{$function} (line {$line})" => $mixed));
+  }
+
+  function pr($level, $mixed, $checkpoint = null) {
+    $this->_pr($level, $mixed, $checkpoint);
+  }
+
+  function prEnter($args, $level = 15) {
+    $this->_pr($level, $args, 'Function Entry');
+  }
+
+  function prExit($retval, $level = 16) {
+    $this->_pr($level, $retval, 'Function Exit');
+    return $retval;
+  }
+
 
   /**************************************************************************
    **************************************************************************

models/statement_entry.php

@@ -22,6 +22,7 @@ class StatementEntry extends AppModel {
 
 	);
 
+	var $default_log_level = 30;
 
   /**************************************************************************
    **************************************************************************
@@ -64,20 +65,18 @@ class StatementEntry extends AppModel {
    *    (not in a pre-existing statement entry)
    */
   function verifyStatementEntry($entry) {
-/*     pr(array("StatementEntry::verifyStatementEntry()" */
+    $this->prFunctionLevel(10);
-/* 	     => compact('entry'))); */
+    $this->prEnter(compact('entry'));
 
     if (empty($entry['type']) ||
 	//empty($entry['effective_date']) ||
 	empty($entry['account_id']) ||
 	empty($entry['amount'])
 	) {
-/*       pr(array("StatementEntry::verifyStatementEntry()" */
+      return $this->prExit(false);
-/* 	       => "Entry verification failed")); */
-      return false;
     }
 
-    return true;
+    return $this->prExit(true);
   }
 
 
@@ -88,23 +87,21 @@ class StatementEntry extends AppModel {
    *  - Inserts new Statement Entry into the database
    */
   function addStatementEntry($entry) {
-/*     pr(array('StatementEntry::addStatementEntry' => */
+    $this->prEnter(compact('entry'));
-/* 	     compact('entry'))); */
 
     $ret = array();
     if (!$this->verifyStatementEntry($entry))
       return array('error' => true, 'verify_data' => $entry) + $ret;
 
-/*     pr(array('StatementEntry::addStatementEntry' => */
+    $this->pr(20, array('checkpoint' => 'Pre-Save')
-/* 	     array('checkpoint' => 'Pre-Save') */
+	      + compact('entry'));
-/* 	     + compact('entry'))); */
 
     $this->create();
     if (!$this->save($entry))
       return array('error' => true, 'save_data' => $entry) + $ret;
 
     $ret['statement_entry_id'] = $this->id;
-    return $ret + array('error' => false);
+    return $this->prExit($ret + array('error' => false));
   }
 
 
@@ -161,8 +158,7 @@ OPTION 2
    *
    */
   function reverse($ledger_entries, $stamp = null) {
-    pr(array('Entry::reverse',
+    $this->prEnter(compact('ledger_entries', 'stamp'));
-	     compact('ledger_entries', 'stamp')));
 
     // If the user only wants to reverse one ID, we'll allow it
     if (!is_array($ledger_entries))
@@ -188,7 +184,7 @@ OPTION 2
       elseif (isset($entry['credit_ledger_id']))
 	$refund_account_id = $this->Ledger->accountID($entry['credit_ledger_id']);
       else
-	return null;
+	return $this->prExit(null);
 
       // post new refund in the income account
       $ids = $A->postEntry
@@ -211,14 +207,14 @@ OPTION 2
 	 );
 
       if ($ids['error'])
-	return null;
+	return $this->prExit(null);
       $transaction_id = $ids['transaction_id'];
 
-      pr(array('checkpoint' => 'Posted Refund Ledger Entry',
+      $this->pr(15, compact('ids', 'amount', 'refund_account_id', 'ar_account_id'),
-	       compact('ids', 'amount', 'refund_account_id', 'ar_account_id')));
+		'Posted Refund Ledger Entry');
     }
 
-    return true;
+    return $this->prExit(true);
   }
 
 
@@ -253,14 +249,15 @@ OPTION 2
   }
 
   function reconciledSet($set, $query = null, $unrec = false) {
+    $this->prEnter(compact('set', 'query', 'unrec'));
     $lquery = $this->reconciledSetQuery($set, $query);
     $result = $this->find('all', $lquery);
 
-    //pr(array('StatementEntry::reconciledSet' => compact('set', 'unrec', 'lquery', 'result')));
+    $this->pr(20, compact('lquery', 'result'));
 
     $resultset = array();
     foreach ($result AS $i => $entry) {
-      //pr(compact('entry'));
+      $this->pr(25, compact('entry'));
       if (!empty($entry[0]))
 	$entry['StatementEntry'] = $entry[0] + $entry['StatementEntry'];
       unset($entry[0]);
@@ -280,12 +277,8 @@ OPTION 2
       }
     }
 
-    //pr(array('StatementEntry::reconciledSet' => compact('resultset')));
+    return $this->prExit(array('entries' => $resultset,
-
+			       'summary' => $this->stats(null, $query)));
-    //$resultset['stats'] = $this->stats(null, $query);
-    //pr($this->stats(null, $query));
-    return array('entries' => $resultset,
-		 'summary' => $this->stats(null, $query));
   }
 
 
@@ -314,16 +307,14 @@ OPTION 2
   }
 
   function reconciledEntries($id, $query = null) {
+    $this->prEnter(compact('id', 'query'));
     $lquery = $this->reconciledEntriesQuery($id, $query);
 
-    //pr(array('reconciledEntries', compact('entry', 'contain')));
     $result = $this->find('all', $lquery);
     foreach (array_keys($result) AS $i)
       unset($result[$i]['StatementEntry']);
 
-    //pr(array('StatementEntry::reconciledEntries()' => compact('result')));
+    return $this->prExit(array('entries' => $result));
-    return array('entries' => $result);
-    //'summary' => $this->stats($id, $query));
   }
 
 
@@ -339,7 +330,7 @@ OPTION 2
    *
    */
   function assignCredits($query = null, $receipt_id = null) {
-/*     pr(array('StatementEntry::assignCredits' => compact('query', 'receipt_id'))); */
+    $this->prEnter( compact('query', 'receipt_id'));
     $this->queryInit($query);
 
     $ret = array();
@@ -349,9 +340,8 @@ OPTION 2
     $lquery['conditions'][] = array('StatementEntry.type' => 'SURPLUS');
     $lquery['order'][] = 'StatementEntry.effective_date ASC';
     $credits = $this->find('all', $lquery);
-/*     pr(array('StatementEntry::assignCredits' =>  */
+    $this->pr(18, compact('credits'),
-/* 	     array('checkpoint' => "Credits Established") */
+	      "Credits Established");
-/* 	     + compact('credits'))); */
 
     // Next, establish credit from the newly added receipt
     $receipt_credit = null;
@@ -373,18 +363,16 @@ OPTION 2
 
       $receipt_credit['balance'] = $receipt_credit['Transaction']['amount'];
 
-/*       pr(array('StatementEntry::assignCredits' =>  */
+      $this->pr(18, compact('receipt_credit'),
-/* 	       array('checkpoint' => "Receipt Credit Added") */
+		"Receipt Credit Added");
-/* 	       + compact('receipt_credit'))); */
     }
 
     // Now find all unpaid charges
     $lquery = $query;
     $lquery['order'] = 'StatementEntry.effective_date ASC';
     $charges = $this->reconciledSet('CHARGE', $query, true);
-/*     pr(array('StatementEntry::assignCredits' =>  */
+    $this->pr(18, compact('charges'),
-/* 	     array('checkpoint' => "Outstanding Charges Determined") */
+	      "Outstanding Charges Determined");
-/* 	     + compact('charges'))); */
 
     // Initialize our list of used credits
     $used_credits = array();
@@ -392,9 +380,8 @@ OPTION 2
     // Work through all unpaid charges, applying payments as we go
     foreach ($charges['entries'] AS $charge) {
 
-/*       pr(array('StatementEntry::assignCredits' => */
+      $this->pr(20, compact('charge'),
-/* 	       array('checkpoint' => 'Process Charge') */
+		'Process Charge');
-/* 	       + compact('charge'))); */
 
       // Check that we have available credits.
       // Technically, this isn't necessary, since the loop
@@ -402,8 +389,7 @@ OPTION 2
       // just saves extra processing if/when there is no
       // means to resolve a charge anyway.
       if (count($credits) == 0 && empty($receipt_credit['balance'])) {
-/* 	pr(array('StatementEntry::assignCredits' => */
+	$this->pr(15, 'No more available credits');
-/* 		 array('checkpoint' => 'No more available credits'))); */
 	break;
       }
 
@@ -411,9 +397,8 @@ OPTION 2
       while ($charge['balance'] > 0 &&
 	     (count($credits) || !empty($receipt_credit['balance']))) {
 
-/* 	pr(array('StatementEntry::assignCredits' => */
+	$this->pr(20, compact('charge'),
-/* 		 array('checkpoint' => 'Attempt Charge Reconciliation') */
+		  'Attempt Charge Reconciliation');
-/* 		 + compact('charge'))); */
 
 	// Use explicit credits before using implicit credits
 	// (Not sure it matters though).
@@ -447,11 +432,10 @@ OPTION 2
 	$credit['applied'] += $payment_amount;
 	$credit['balance'] -= $payment_amount;
 
-/* 	pr(array('StatementEntry::assignCredits' => */
+	$this->pr(20, compact('credit'),
-/* 		 array('checkpoint' => (($credit['balance'] > 0 ? 'Utilized' : 'Exhausted') */
+		  (($credit['balance'] > 0 ? 'Utilized' : 'Exhausted')
-/* 					. (count($credits) ? '' : ' Anon') */
+		   . (count($credits) ? '' : ' Anon')
-/* 					. ' Credit')) */
+		   . ' Credit'));
-/* 		 + compact('credit'))); */
 
 	if ($credit['balance'] < 0)
 	  die("HOW DID WE END UP WITH NEGATIVE SURPLUS BALANCE?");
@@ -477,9 +461,8 @@ OPTION 2
 			 'comment' => null,
 			 );
 
-/* 	pr(array('StatementEntry::assignCredits' => */
+	$this->pr(20, compact('payment'),
-/* 		 array('checkpoint' => 'New Payment Entry') */
+		  'New Payment Entry');
-/* 		 + compact('payment'))); */
 
 	$result = $this->addStatementEntry($payment);
 	$ret['Payment'][] = $result;
@@ -491,9 +474,8 @@ OPTION 2
 	if ($charge['balance'] < 0)
 	  die("HOW DID WE GET A NEGATIVE CHARGE AMOUNT?");
 
-/* 	if ($charge['balance'] <= 0) */
+	if ($charge['balance'] <= 0)
-/* 	  pr(array('StatementEntry::assignCredits' => */
+	  $this->pr(20, 'Fully Paid Charge');
-/* 		   array('checkpoint' => 'Fully Paid Charge'))); */
       }
 
     }
@@ -502,24 +484,21 @@ OPTION 2
     if (isset($credits[0]['applied']))
       $used_credits[] = array_shift($credits);
       
-/*     pr(array('StatementEntry::assignCredits' => */
+    $this->pr(18, compact('credits', 'used_credits', 'anon_credits', 'used_anon_credits'),
-/* 	     array('checkpoint' => 'Payments added') */
+	      'Payments added');
-/* 	     + compact('credits', 'used_credits', 'anon_credits', 'used_anon_credits'))); */
 
     // Clean up any explicit credits that have been used
     foreach ($used_credits AS $credit) {
       if ($credit['balance'] > 0) {
-/* 	pr(array('StatementEntry::assignCredits' => */
+	$this->pr(20, compact('credit'),
-/* 		 array('checkpoint' => 'Update Credit Entry') */
+		  'Update Credit Entry');
-/* 		 + compact('credit'))); */
 
  	$this->id = $credit['StatementEntry']['id'];
 	$this->saveField('amount', $credit['balance']);
       }
       else {
-/* 	pr(array('StatementEntry::assignCredits' => */
+	$this->pr(20, compact('credit'),
-/* 		 array('checkpoint' => 'Delete Exhausted Credit Entry') */
+		  'Delete Exhausted Credit Entry');
-/* 		 + compact('credit'))); */
 
 	$this->del($credit['StatementEntry']['id'], false);
       }
@@ -529,9 +508,8 @@ OPTION 2
     if (!empty($receipt_credit['balance'])) {
       $credit =& $receipt_credit;
 
-/*       pr(array('StatementEntry::assignCredits' => */
+      $this->pr(18, compact('credit'),
-/* 	       array('checkpoint' => 'Create Explicit Credit') */
+		'Create Explicit Credit');
-/* 	       + compact('credit'))); */
 
       $result = $this->addStatementEntry
 	(array('type'           => 'SURPLUS',
@@ -546,7 +524,7 @@ OPTION 2
 	$ret['error'] = true;
     }
 
-    return $ret + array('error' => false);
+    return $this->prExit($ret + array('error' => false));
   }
 
 
@@ -557,11 +535,11 @@ OPTION 2
    *  - Returns summary data from the requested statement entry
    */
   function stats($id = null, $query = null) {
+    $this->prEnter(compact('id', 'query'));
+
     $this->queryInit($query);
     unset($query['group']);
 
-/*     pr(array('StatementEntry::stats' => compact('id', 'query'))); */
-
     $stats = array();
     if (isset($id))
       $query['conditions'][] = array('StatementEntry.id' => $id);
@@ -586,9 +564,8 @@ OPTION 2
     $stats['Charge']['balance'] = 
       $stats['Charge']['total'] - $stats['Charge']['reconciled'];
     
-/*     pr(array('StatementEntry::stats' =>  */
+    $this->pr(17, compact('query', 'result'),
-/* 	     array('checkpoint' => 'Charges') */
+	      'Charges');
-/* 	     + compact('query', 'result'))); */
 
     $rquery = $query;
     unset($rquery['link']['PaymentEntry']);
@@ -605,16 +582,10 @@ OPTION 2
       $result[0]['balance'] = 0;
     $stats['Payment'] = $result[0];
 
-/*     pr(array('StatementEntry::stats' =>  */
+    $this->pr(17, compact('rquery', 'result'),
-/* 	     array('checkpoint' => 'Payments') */
+	      'Payments');
-/* 	     + compact('rquery', 'result'))); */
 
-
+    return $this->prExit($stats);
-/*     pr(array('StatementEntry::stats' =>  */
-/* 	     array('checkpoint' => 'return') */
-/* 	     + compact('stats'))); */
-
-    return $stats;
   }
 
 }