From: Michael J. Rubinsky Date: Wed, 7 Apr 2010 19:44:12 +0000 (-0400) Subject: Clean up some logging, and some other misc. cleanup X-Git-Url: https://git.internetallee.de/?a=commitdiff_plain;h=5db04384dab1d772076aa01a196fe6a44fdc709e;p=horde.git Clean up some logging, and some other misc. cleanup --- diff --git a/framework/ActiveSync/lib/Horde/ActiveSync.php b/framework/ActiveSync/lib/Horde/ActiveSync.php index dde63899d..03255e1dd 100644 --- a/framework/ActiveSync/lib/Horde/ActiveSync.php +++ b/framework/ActiveSync/lib/Horde/ActiveSync.php @@ -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) * diff --git a/framework/ActiveSync/lib/Horde/ActiveSync/Driver/Horde.php b/framework/ActiveSync/lib/Horde/ActiveSync/Driver/Horde.php index 74b57c198..2a6be1205 100644 --- a/framework/ActiveSync/lib/Horde/ActiveSync/Driver/Horde.php +++ b/framework/ActiveSync/lib/Horde/ActiveSync/Driver/Horde.php @@ -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. * diff --git a/framework/ActiveSync/lib/Horde/ActiveSync/Request/Base.php b/framework/ActiveSync/lib/Horde/ActiveSync/Request/Base.php index 0909e22de..298c64754 100644 --- a/framework/ActiveSync/lib/Horde/ActiveSync/Request/Base.php +++ b/framework/ActiveSync/lib/Horde/ActiveSync/Request/Base.php @@ -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; + } } diff --git a/framework/ActiveSync/lib/Horde/ActiveSync/Request/Ping.php b/framework/ActiveSync/lib/Horde/ActiveSync/Request/Ping.php index 040c96fce..1a1d0455f 100644 --- a/framework/ActiveSync/lib/Horde/ActiveSync/Request/Ping.php +++ b/framework/ActiveSync/lib/Horde/ActiveSync/Request/Ping.php @@ -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); diff --git a/framework/ActiveSync/lib/Horde/ActiveSync/Request/Sync.php b/framework/ActiveSync/lib/Horde/ActiveSync/Request/Sync.php index 52e965864..5b6dfa5aa 100644 --- a/framework/ActiveSync/lib/Horde/ActiveSync/Request/Sync.php +++ b/framework/ActiveSync/lib/Horde/ActiveSync/Request/Sync.php @@ -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"])); } } } diff --git a/framework/ActiveSync/lib/Horde/ActiveSync/State/File.php b/framework/ActiveSync/lib/Horde/ActiveSync/State/File.php index 3547208d9..f813b7166 100644 --- a/framework/ActiveSync/lib/Horde/ActiveSync/State/File.php +++ b/framework/ActiveSync/lib/Horde/ActiveSync/State/File.php @@ -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; diff --git a/framework/ActiveSync/lib/Horde/ActiveSync/Sync.php b/framework/ActiveSync/lib/Horde/ActiveSync/Sync.php index 78dab1b2e..435584e68 100644 --- a/framework/ActiveSync/lib/Horde/ActiveSync/Sync.php +++ b/framework/ActiveSync/lib/Horde/ActiveSync/Sync.php @@ -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];