Clean up some logging, and some other misc. cleanup
authorMichael J. Rubinsky <mrubinsk@horde.org>
Wed, 7 Apr 2010 19:44:12 +0000 (15:44 -0400)
committerMichael M Slusarz <slusarz@curecanti.org>
Thu, 8 Apr 2010 19:27:12 +0000 (13:27 -0600)
framework/ActiveSync/lib/Horde/ActiveSync.php
framework/ActiveSync/lib/Horde/ActiveSync/Driver/Horde.php
framework/ActiveSync/lib/Horde/ActiveSync/Request/Base.php
framework/ActiveSync/lib/Horde/ActiveSync/Request/Ping.php
framework/ActiveSync/lib/Horde/ActiveSync/Request/Sync.php
framework/ActiveSync/lib/Horde/ActiveSync/State/File.php
framework/ActiveSync/lib/Horde/ActiveSync/Sync.php

index dde6389..03255e1 100644 (file)
@@ -457,6 +457,13 @@ class Horde_ActiveSync
     const CONFLICT_OVERWRITE_PIM = 1;
 
     /**
+     * Logger
+     *
+     * @var Horde_Log_Logger
+     */
+    protected $_logger;
+
+    /**
      * Provisioning support
      *
      * @var string (TODO _constant this)
@@ -992,6 +999,7 @@ class Horde_ActiveSync
 
     public function provisioningRequired()
     {
+        $this->_logger->info('HTTP/1.1 449 Retry after sending a PROVISION command');
         self::provisionHeader();
         self::activeSyncHeader();
         self::versionHeader();
@@ -1229,29 +1237,6 @@ class Horde_ActiveSync
     }
 
     /**
-     * Read input from the php input stream
-     *
-     * @TODO: Get rid of this - the wbxml classes have a php:// stream already
-     *        and when we need *just* the stream and not wbxml, we can use
-     *        $request->body
-     *
-     * @return string
-     */
-    public function readStream()
-    {
-        $s = "";
-        while (1) {
-            $data = fread($this->_inputStream, 4096);
-            if (strlen($data) == 0) {
-                break;
-            }
-            $s .= $data;
-        }
-
-        return $s;
-    }
-
-    /**
      * Send the MS_Server-ActiveSync header
      * (This is the version Exchange 2003 implements)
      *
index 74b57c1..2a6be12 100644 (file)
@@ -73,10 +73,8 @@ class Horde_ActiveSync_Driver_Horde extends Horde_ActiveSync_Driver_Base
      */
     public function logon($username, $password, $domain = null)
     {
-        $this->_logger->debug('Horde_ActiveSync_Driver_Horde::logon');
+        $this->_logger->info('Horde_ActiveSync_Driver_Horde::logon attempt for: ' . $username);
         parent::logon($username, $password, $domain);
-
-        $this->_startProfiling();
         $auth = Horde_Auth::singleton($GLOBALS['conf']['auth']['driver']);
 
         return $auth->authenticate($username, array('password' => $password));
@@ -89,8 +87,7 @@ class Horde_ActiveSync_Driver_Horde extends Horde_ActiveSync_Driver_Base
      */
     public function Logoff()
     {
-        $this->_logger->debug('Horde_ActiveSync_Driver_Horde::logoff');
-        $this->_endProfiling();
+        $this->_logger->info('Horde_ActiveSync_Driver_Horde::logoff');
         return true;
     }
 
@@ -105,7 +102,6 @@ class Horde_ActiveSync_Driver_Horde extends Horde_ActiveSync_Driver_Base
      */
     public function setup($user)
     {
-        $this->_logger->debug('Horde::Setup(' . $user . ')');
         parent::setup($user);
         $this->_modCache = array();
         return true;
@@ -332,7 +328,6 @@ class Horde_ActiveSync_Driver_Horde extends Horde_ActiveSync_Driver_Base
      */
     public function StatMessage($folderid, $id)
     {
-        $this->_logger->debug('Horde::StatMessage(' . $folderid . ', ' . $id . ')');
         return $this->_smartStatMessage($folderid, $id, true);
     }
 
@@ -481,27 +476,6 @@ class Horde_ActiveSync_Driver_Horde extends Horde_ActiveSync_Driver_Base
     }
 
     /**
-     * Start profiling data
-     *
-     * @return void
-     */
-    private function _startProfiling()
-    {
-        $this->_starttime = microtime(true);
-    }
-
-    /**
-     * End profiling
-     *
-     * @return void
-     */
-    private function _endProfiling()
-    {
-        $this->_logger->debug('Session lasted ' . sprintf('%0.3f',microtime(true) - $this->_starttime) . ' s');
-    }
-
-
-    /**
      * Create a hash suitable for importing into contacts/import or
      * contacts/replace from a Horde_ActiveSync_Message_Base object.
      *
index 0909e22..298c647 100644 (file)
@@ -129,6 +129,8 @@ abstract class Horde_ActiveSync_Request_Base
             }
         }
 
+        $this->_logger->debug('Policykey: ' . $sentKey . ' verified.');
+
         return true;
     }
 
@@ -146,6 +148,29 @@ abstract class Horde_ActiveSync_Request_Base
     {
         $this->_version = $activeSync->getProtocolVersion();
         $this->_devId = $devId;
+        $this->_logger->info('Request received from device: ' . $devId . ' Supporting protocol version: ' . $this->_version);
     }
 
+    /**
+     * Read input from the php input stream
+     *
+     * @TODO: Get rid of this - the wbxml classes have a php:// stream already
+     *        and when we need *just* the stream and not wbxml, we can use
+     *        $request->body
+     *
+     * @return string
+     */
+    protected function _readStream()
+    {
+        $s = "";
+        while (1) {
+            $data = fread($this->_inputStream, 4096);
+            if (strlen($data) == 0) {
+                break;
+            }
+            $s .= $data;
+        }
+
+        return $s;
+    }
 }
index 040c96f..1a1d045 100644 (file)
@@ -45,7 +45,7 @@ class Horde_ActiveSync_Request_Ping extends Horde_ActiveSync_Request_Base
 
         // FIXME
         $timeout = 3;
-        $this->_logger->info('Ping received for: ' . $this->_devId);
+        $this->_logger->info('[' . $devId . '] Ping received.');
 
         /* Glass half full kinda guy... */
         $this->_statusCode = self::STATUS_NOCHANGES;
@@ -61,7 +61,6 @@ class Horde_ActiveSync_Request_Ping extends Horde_ActiveSync_Request_Base
 
         /* Build the $collections array if we receive request from PIM */
         if ($this->_decoder->getElementStartTag(SYNC_PING_PING)) {
-            $this->_logger->debug('Ping init');
             if ($this->_decoder->getElementStartTag(SYNC_PING_LIFETIME)) {
                 $lifetime = $this->_decoder->getElementContent();
                 $state->setPingLifetime($lifetime);
@@ -102,7 +101,7 @@ class Horde_ActiveSync_Request_Ping extends Horde_ActiveSync_Request_Base
 
         /* Start waiting for changes, but only if we don't have any errors */
         if ($this->_statusCode == self::STATUS_NOCHANGES) {
-            $this->_logger->info(sprintf('Waiting for changes... (lifetime %d)', $lifetime));
+            $this->_logger->info(sprintf('[%s] Waiting for changes (lifetime: %d)', $this->_devId, $lifetime));
             // FIXME
             //for ($n = 0; $n < $lifetime / $timeout; $n++) {
             for ($n = 0; $n < 10; $n++) {
@@ -151,13 +150,13 @@ class Horde_ActiveSync_Request_Ping extends Horde_ActiveSync_Request_Base
                 }
 
                 if ($dataavailable) {
-                    $this->_logger->info('Found changes');
+                    $this->_logger->info('[' . $this->_devId . '] Changes available');
                     break;
                 }
                 sleep($timeout);
             }
         }
-        $this->_logger->debug('Starting StartWBXML output');
+        $this->_logger->info('[' . $this->_devId . '] Sending response for PING.');
         $this->_encoder->StartWBXML();
 
         $this->_encoder->startTag(SYNC_PING_PING);
index 52e9658..5b6dfa5 100644 (file)
@@ -29,7 +29,7 @@ class Horde_ActiveSync_Request_Sync extends Horde_ActiveSync_Request_Base
     public function handle(Horde_ActiveSync $activeSync, $devId)
     {
         parent::handle($activeSync, $devId);
-        $this->_logger->info('[Horde_ActiveSync::handleSync] Handling SYNC command.');
+        $this->_logger->info('[' . $this->_devId . '] Handling SYNC command.');
 
         /* Check policy */
         if (!$this->checkPolicyKey($activeSync->getPolicyKey())) {
@@ -65,7 +65,7 @@ class Horde_ActiveSync_Request_Sync extends Horde_ActiveSync_Request_Base
             }
 
             $collection['class'] = $this->_decoder->getElementContent();
-            $this->_logger->debug('[Horde_ActiveSync::handleSync] Folder class: ' . $collection['class']);
+            $this->_logger->info('[' . $this->_devId . '] Syncing folder class: ' . $collection['class']);
             if (!$this->_decoder->getElementEndTag()) {
                 throw new Horde_ActiveSync_Exception('Protocol error');
             }
@@ -80,7 +80,7 @@ class Horde_ActiveSync_Request_Sync extends Horde_ActiveSync_Request_Base
 
             if ($this->_decoder->getElementStartTag(SYNC_FOLDERID)) {
                 $collection['id'] = $this->_decoder->getElementContent();
-                $this->_logger->debug('[Horde_ActiveSync::handleSync] Folder collectionid: ' . $collection['id']);
+                $this->_logger->info('[' . $this->_devId . '] Folder server id: ' . $collection['id']);
                 if (!$this->_decoder->getElementEndTag()) {
                     throw new Horde_ActiveSync_Exception('Protocol error');
                 }
@@ -325,7 +325,7 @@ class Horde_ActiveSync_Request_Sync extends Horde_ActiveSync_Request_Base
                     }
                 }
 
-                $this->_logger->debug(sprintf('[Horde_ActiveSync::handleSync] Processed %d incoming changes', $nchanges));
+                $this->_logger->debug(sprintf('[%s] Processed %d incoming changes', $this->_devId, $nchanges));
 
                 if (!$this->_decoder->getElementEndTag()) {
                     // end commands
@@ -356,6 +356,7 @@ class Horde_ActiveSync_Request_Sync extends Horde_ActiveSync_Request_Base
         }
 
         /* Start output to PIM */
+        $this->_logger->info('[' . $this->_devId . '] Beginning SYNC Response.');
         $this->_encoder->startWBXML();
         $this->_encoder->startTag(SYNC_SYNCHRONIZE);
         $this->_encoder->startTag(SYNC_FOLDERS);
@@ -456,7 +457,7 @@ class Horde_ActiveSync_Request_Sync extends Horde_ActiveSync_Request_Base
                     $n++;
 
                     if (!empty($collection['windowsize']) && $n >= $collection['windowsize']) {
-                        $this->_logger->info(sprintf('[Horde_ActiveSync::handleSync] Exported maxItems of messages: %d - more available.',  $collection['windowsize']));
+                        $this->_logger->info(sprintf('[%s] Exported maxItems of messages: %d - more available.', $this->_devId, $collection['windowsize']));
                         break;
                     }
                 }
@@ -471,7 +472,7 @@ class Horde_ActiveSync_Request_Sync extends Horde_ActiveSync_Request_Base
                     $state->setNewSyncKey($collection['newsynckey']);
                     $state->save();
                 } else {
-                    $this->_logger->err(sprintf('[Horde_ActiveSync::handleSync] Error saving %s - no state information available.', $collection["newsynckey"]));
+                    $this->_logger->err(sprintf('[%s] Error saving %s - no state information available.', $this->_devId, $collection["newsynckey"]));
                 }
             }
         }
index 3547208..f813b71 100644 (file)
@@ -425,7 +425,7 @@ class Horde_ActiveSync_State_File extends Horde_ActiveSync_State_Base
 
         /* Initialize state for this collection */
         if (!$haveState) {
-            $this->_logger->debug('Empty state for '. $pingCollection['class']);
+            $this->_logger->info('[' . $this->_devId . '] Empty state for '. $pingCollection['class']);
 
             /* Init members for the getChanges call */
             $this->_syncKey = $this->_devId;
@@ -477,6 +477,7 @@ class Horde_ActiveSync_State_File extends Horde_ActiveSync_State_Base
         $state = serialize(array('lifetime' => $this->_pingState['lifetime'],
                                  'collections' => $this->_pingState['collections']));
 
+        $this->_logger->info('[' . $this->_devId . '] Saving new PING state.');
         return file_put_contents($this->_stateDir . '/' . $this->_backend->getUser() . '/' . $this->_devId, $state);
     }
 
@@ -527,6 +528,7 @@ class Horde_ActiveSync_State_File extends Horde_ActiveSync_State_Base
         $info = $this->getDeviceInfo($devId);
         $info->policykey = $key;
         $this->setDeviceInfo($devId, $info);
+        $this->_logger->info('[' . $devId . '] New policykey saved: ' . $key);
     }
 
     /**
@@ -555,6 +557,7 @@ class Horde_ActiveSync_State_File extends Horde_ActiveSync_State_Base
         $info = $this->getDeviceInfo($devId);
         $info->rwstatus = $status;
         $this->setDeviceInfo($devId, $info);
+        $this->_logger->info('[' . $devId . '] Setting DeviceRWStatus: ' . $status);
     }
 
     /**
@@ -571,13 +574,13 @@ class Horde_ActiveSync_State_File extends Horde_ActiveSync_State_Base
 
         if (!empty($this->_collection['id'])) {
             $folderId = $this->_collection['id'];
-            $this->_logger->debug('Initializing message diff engine');
+            $this->_logger->info('[' . $this->_devId . '] Initializing message diff engine.');
             if (!$syncState) {
                 $syncState = array();
             }
-            $this->_logger->debug(count($syncState) . ' messages in state');
+            $this->_logger->debug('[' . $this->_devId . ']' . count($syncState) . ' messages in state.');
 
-            //do nothing if it is a dummy folder
+            /* do nothing if it is a dummy folder */
             if ($folderId != SYNC_FOLDER_TYPE_DUMMY) {
                 // on ping: check if backend supports alternative PING mechanism & use it
                 if ($this->_collection['class'] === false && $flags == BACKEND_DISCARD_DATA && $this->_backend->AlterPing()) {
@@ -585,7 +588,7 @@ class Horde_ActiveSync_State_File extends Horde_ActiveSync_State_Base
                     // Not even sure if we need this AlterPing?
                     $this->_changes = $this->_backend->AlterPingChanges($folderId, $syncState);
                 } else {
-                    // Get our lists - syncstate (old)  and msglist (new)
+                    /* Get our lists - syncstate (old)  and msglist (new) */
                     $msglist = $this->_backend->GetMessageList($this->_collection['id'], $cutoffdate);
                     if ($msglist === false) {
                         return false;
@@ -593,18 +596,18 @@ class Horde_ActiveSync_State_File extends Horde_ActiveSync_State_Base
                     $this->_changes = $this->_getDiff($syncState, $msglist);
                 }
             }
-            $this->_logger->debug('Found ' . count($this->_changes) . ' message changes');
+            $this->_logger->info('[' . $this->_devId . '] Found ' . count($this->_changes) . ' message changes.');
 
         } else {
 
-            $this->_logger->debug('Initializing folder diff engine');
+            $this->_logger->info('[' . $this->_devId . '] Initializing folder diff engine.');
             $folderlist = $this->_backend->getFolderList();
             if ($folderlist === false) {
                 return false;
             }
 
             $this->_changes = $this->_getDiff($syncState, $folderlist);
-            $this->_logger->debug('Config: Found ' . count($this->_changes) . ' folder changes');
+            $this->_logger->info('[' . $this->_devId . '] Found ' . count($this->_changes) . ' folder changes.');
         }
 
         return $this->_changes;
index 78dab1b..435584e 100644 (file)
@@ -146,7 +146,6 @@ class Horde_ActiveSync_Sync
         $progress = array();
 
         if ($this->_folderId == false) {
-            //@TODO: Folder changes not implemented??
             if ($this->_step < count($this->_changes)) {
                 $change = $this->_changes[$this->_step];