Skip to content

Commit

Permalink
More logging improvements/cleanup.
Browse files Browse the repository at this point in the history
  • Loading branch information
@mrubinsk
mrubinsk committed Oct 17, 2013
1 parent 7ec9d26 commit b741276
Show file tree
Hide file tree
Showing 7 changed files with 119 additions and 44 deletions.
5 changes: 3 additions & 2 deletions framework/ActiveSync/lib/Horde/ActiveSync/Collections.php
View file
Expand Up @@ -749,8 +749,9 @@ public function initPartialSync()
$csk = $this->_cache->confirmed_synckeys;
if ($csk) {
$this->_logger->info(sprintf(
'Confirmed Synckeys contains %s',
print_r($csk, true))
'[%s] Confirmed Synckeys contains %s',
$this->_procid,
serialize($csk))
);
$this->_logger->err('Some synckeys were not confirmed. Requesting full SYNC');
$this->save();
Expand Down
21 changes: 17 additions & 4 deletions framework/ActiveSync/lib/Horde/ActiveSync/Connector/Exporter.php
View file
Expand Up @@ -101,6 +101,13 @@ class Horde_ActiveSync_Connector_Exporter
*/
protected $_as;

/**
* Process id for logging.
*
* @var integer
*/
protected $_procid;

/**
* Const'r
*
Expand All @@ -116,6 +123,7 @@ public function __construct(
$this->_as = $as;
$this->_encoder = $encoder;
$this->_logger = $as->logger;
$this->_procid = getmypid();
}

/**
Expand Down Expand Up @@ -163,7 +171,7 @@ public function sendNextChange()
} else {
$this->_logger->err(sprintf(
'[%s] Error stating %s: ignoring.',
getmypid(), $change['id']));
$this->_procid, $change['id']));
$stat = array('id' => $change['id'], 'mod' => $change['id'], 0);
}
// Update the state.
Expand Down Expand Up @@ -207,12 +215,17 @@ public function sendNextChange()
$message->flags = (isset($change['flags'])) ? $change['flags'] : 0;
$this->messageChange($change['id'], $message);
} catch (Horde_Exception_NotFound $e) {
$this->_logger->err('Message gone or error reading message from server: ' . $e->getMessage());
$this->_logger->err(sprintf(
'[%s] Message gone or error reading message from server: %s',
$this->_procid, $e->getMessage()));
$this->_as->state->updateState($change['type'], $change);
$this->_step++;
return $e;
} catch (Horde_ActiveSync_Exception $e) {
$this->_logger->err('Unknown backend error skipping message: ' . $e->getMessage());
$this->_logger->err(sprintf(
'[%s] Unknown backend error skipping message: %s',
$this->_procid,
$e->getMessage()));
}
break;

Expand Down Expand Up @@ -287,7 +300,7 @@ public function messageChange($id, Horde_ActiveSync_Message_Base $message)
in_array($id, $this->_seenObjects)) {
$this->_logger->err(sprintf(
'[%s] IGNORING message %s since it looks like it was already sent or does not belong to this collection.',
getmypid(),
$this->_procid,
$id));
return;
}
Expand Down
14 changes: 11 additions & 3 deletions framework/ActiveSync/lib/Horde/ActiveSync/Connector/Importer.php
View file
Expand Up @@ -78,6 +78,13 @@ class Horde_ActiveSync_Connector_Importer
*/
protected $_logger;

/**
* Process id for logging.
*
* @var integer
*/
protected $_procid;

/**
* Const'r
*
Expand All @@ -86,6 +93,7 @@ class Horde_ActiveSync_Connector_Importer
public function __construct(Horde_ActiveSync $as)
{
$this->_as = $as;
$this->_procid = getmypid();
}

/**
Expand Down Expand Up @@ -152,7 +160,7 @@ public function importMessageChange(
if ($conflict && $this->_flags == Horde_ActiveSync::CONFLICT_OVERWRITE_PIM) {
$this->_logger->notice(sprintf(
'[%s] Conflict when updating %s, will overwrite client version on next sync.',
getmypid(), $id)
$this->_procid, $id)
);
return array($id, Horde_ActiveSync_Request_Sync::STATUS_CONFLICT);
}
Expand All @@ -161,7 +169,7 @@ public function importMessageChange(
// Already saw this addition, but PIM never received UID
$this->_logger->notice(sprintf(
'[%s] Duplicate addition for %s',
getmypid(), $uid)
$this->_procid, $uid)
);
return $uid;
}
Expand All @@ -171,7 +179,7 @@ public function importMessageChange(
if (!$stat = $this->_as->driver->changeMessage($this->_folderId, $id, $message, $device)) {
$this->_logger->err(sprintf(
'[%s] Change message failed when updating %s',
getmypid(), $id)
$this->_procid, $id)
);
return false;
}
Expand Down
6 changes: 6 additions & 0 deletions framework/ActiveSync/lib/Horde/ActiveSync/Driver/Base.php
View file
Expand Up @@ -77,6 +77,12 @@ abstract class Horde_ActiveSync_Driver_Base
*/
protected $_state;

/**
* Temporary serverid to uid map. Used when creating the hierarchy
* for the first time
*
* @var array
*/
protected $_tempMap = array();

/**
Expand Down
68 changes: 51 additions & 17 deletions framework/ActiveSync/lib/Horde/ActiveSync/Imap/Adapter.php
View file
Expand Up @@ -41,6 +41,13 @@ class Horde_ActiveSync_Imap_Adapter
*/
protected $_defaultNamespace;

/**
* Process id used for logging.
*
* @var integer
*/
protected $_procid;

/**
* Cont'r
*
Expand All @@ -53,6 +60,7 @@ public function __construct(array $params = array())
$this->_imap = $params['factory'];
Horde_Mime_Part::$defaultCharset = 'UTF-8';
Horde_Mime_Headers::$defaultCharset = 'UTF-8';
$this->_procid = getmypid();
}

/**
Expand Down Expand Up @@ -278,11 +286,16 @@ public function getMessageChanges(
// If we can't status the mailbox, assume it's gone.
throw new Horde_ActiveSync_Exception_FolderGone($e);
}
$this->_logger->info('IMAP status: ' . print_r($status, true));
$this->_logger->info(sprintf(
'[%s] IMAP status: %s',
$this->_procid,
serialize($status))
);
$flags = array();
$modseq = $status[Horde_ActiveSync_Folder_Imap::HIGHESTMODSEQ];
if ($modseq && $folder->modseq() > 0 && $folder->modseq() < $modseq) {
$this->_logger->info('CONDSTORE and CHANGES');
$this->_logger->info(sprintf(
'[%s] CONDSTORE and CHANGES', $this->_procid));
$folder->checkValidity($status);
$query = new Horde_Imap_Client_Fetch_Query();
$query->modseq();
Expand Down Expand Up @@ -311,7 +324,7 @@ public function getMessageChanges(
// Ignore, it's out of the FILTERTYPE range.
$this->_logger->info(sprintf(
'[%s] Ignoring UID %s since it is outside of the FILTERTYPE (%s)',
getmypid(),
$this->_procid,
$uid,
$headers->getValue('Date')));
continue;
Expand Down Expand Up @@ -343,7 +356,7 @@ public function getMessageChanges(
if (!empty($options['softdelete']) && !empty($options['sincedate'])) {
$this->_logger->info(sprintf(
'[%s] Polling for SOFTDELETE in %s before %d',
getmypid(), $folder->serverid(), $options['sincedate']));
$this->_procid, $folder->serverid(), $options['sincedate']));

$query = new Horde_Imap_Client_Search_Query();
$query->dateSearch(
Expand All @@ -355,16 +368,21 @@ public function getMessageChanges(
$query,
array('results' => array(Horde_Imap_Client::SEARCH_RESULTS_MATCH)));
if ($search_ret['count']) {
$this->_logger->info(sprintf('Found %d messages to SOFTDELETE.', count($search_ret['match']->ids)));
$this->_logger->info(sprintf(
'[%s] Found %d messages to SOFTDELETE.',
$this->_procid, count($search_ret['match']->ids)));
$folder->setSoftDeleted($search_ret['match']->ids);
} else {
$this->_logger->info('Found NO messages to SOFTDELETE.');
$this->_logger->info(sprintf(
'[%s] Found NO messages to SOFTDELETE.',
$this->_procid));
}
$folder->setSoftDeleteTimes($options['sincedate'], time());
}

} elseif ($folder->uidnext() == 0) {
$this->_logger->info('INITIAL SYNC');
$this->_logger->info(sprintf(
'[%s] INITIAL SYNC', $this->_procid));
$query = new Horde_Imap_Client_Search_Query();
if (!empty($options['sincedate'])) {
$query->dateSearch(
Expand Down Expand Up @@ -394,7 +412,7 @@ public function getMessageChanges(
} elseif ($modseq == 0) {
$this->_logger->info(sprintf(
'[%s] NO CONDSTORE or per mailbox MODSEQ. minuid: %s, total_messages: %s',
getmypid(), $folder->minuid(), $status['messages']));
$this->_procid, $folder->minuid(), $status['messages']));
$folder->checkValidity($status);
$query = new Horde_Imap_Client_Search_Query();
if (!empty($options['sincedate'])) {
Expand Down Expand Up @@ -900,7 +918,8 @@ protected function _buildMailMessage(
($options['mimesupport'] == Horde_ActiveSync::MIME_SUPPORT_SMIME &&
$imap_message->isSigned()))) {

$this->_logger->info('Sending MIME Message.');
$this->_logger->info(sprintf(
'[%s] Sending MIME Message.', $this->_procid));
// ActiveSync *REQUIRES* all data sent to be in UTF-8, so we
// must convert the body parts to UTF-8. Unfortunately if the
// email is signed (or encrypted for that matter) we can't
Expand Down Expand Up @@ -965,7 +984,8 @@ protected function _buildMailMessage(
// MIME Truncation
$airsync_body->type = Horde_ActiveSync::BODYPREF_TYPE_MIME;
$this->_logger->info(sprintf(
'Checking MIMETRUNCATION: %s, ServerData: %s',
'[%s] Checking MIMETRUNCATION: %s, ServerData: %s',
$this->_procid,
$options['truncation'],
$airsync_body->estimateddatasize));
if (!empty($options['truncation']) &&
Expand All @@ -980,7 +1000,9 @@ protected function _buildMailMessage(
isset($options['bodyprefs'][Horde_ActiveSync::BODYPREF_TYPE_RTF])) {

// Sending non MIME encoded HTML message text.
$this->_logger->info('Sending HTML Message.');
$this->_logger->info(sprintf(
'[%s] Sending HTML Message.',
$this->_procid));
if (empty($message_body_data['html'])) {
$airsync_body->type = Horde_ActiveSync::BODYPREF_TYPE_PLAIN;
$message_body_data['html'] = array(
Expand All @@ -999,7 +1021,8 @@ protected function _buildMailMessage(
} elseif (isset($options['bodyprefs'][Horde_ActiveSync::BODYPREF_TYPE_PLAIN])) {

// Non MIME encoded plaintext
$this->_logger->info('Sending PLAINTEXT Message.');
$this->_logger->info(sprintf(
'[%s] Sending PLAINTEXT Message.', $this->_procid));
$airsync_body->estimateddatasize = $message_body_data['plain']['size'];
$airsync_body->truncated = $message_body_data['plain']['truncated'];
$airsync_body->data = $message_body_data['plain']['body']->stream;
Expand Down Expand Up @@ -1413,7 +1436,8 @@ protected function _getMailMessages(
return $imap->fetch($mbox, $query, array('ids' => $ids));
} catch (Horde_Imap_Client_Exception $e) {
$this->_logger->err(sprintf(
'Unable to fetch message: %s',
'[%s] Unable to fetch message: %s',
$this->_procid,
$e->getMessage()));
throw new Horde_ActiveSync_Exception($e);
}
Expand Down Expand Up @@ -1465,10 +1489,15 @@ protected function _stripNon7BitChars($text)
*/
protected function _validateUtf8($data, $from_charset)
{
$this->_logger->info('Validating UTF-8 data coming from ' . $from_charset);
$this->_logger->info(sprintf(
'[%s] Validating UTF-8 data coming from %s',
$this->_procid,
$from_charset));
$text = Horde_String::convertCharset($data, $from_charset, 'UTF-8');
if (!Horde_String::validUtf8($text)) {
$this->_logger->info('Found invalid UTF-8 data, try different encodings.');
$this->_logger->info(sprintf(
'[%s] Found invalid UTF-8 data, try different encodings.',
$this->_procid));
$test_charsets = array(
'windows-1252',
'UTF-8'
Expand All @@ -1477,7 +1506,10 @@ protected function _validateUtf8($data, $from_charset)
if ($charset != $from_charset) {
$text = Horde_String::convertCharset($data, $charset, 'UTF-8');
if (Horde_String::validUtf8($text)) {
$this->_logger->info('Found valid UTF-8 data when using ' . $charset);
$this->_logger->info(sprintf(
'[%s] Found valid UTF-8 data when using %s',
$this->_procid,
$charset));
return $text;
}
}
Expand All @@ -1487,7 +1519,9 @@ protected function _validateUtf8($data, $from_charset)
// that fails, force a conersion to UTF-8 as a last resort. Need
// to break string into smaller chunks to avoid hitting
// https://bugs.php.net/bug.php?id=37793
$this->_logger->info('Could not encode UTF-8 data. Removing non 7-bit characters.');
$this->_logger->info(sprintf(
'[%s] Could not encode UTF-8 data. Removing non 7-bit characters.',
$this->_procid));
$chunk_size = 4000;
$text = '';
while ($data !== false && strlen($data)) {
Expand Down
20 changes: 9 additions & 11 deletions framework/ActiveSync/lib/Horde/ActiveSync/State/Sql.php
View file
Expand Up @@ -323,17 +323,15 @@ public function save()
$this->_logger->info(
sprintf('[%s] Saving state: %s',
$this->_procid,
print_r(
array(
$params[0],
$params[1],
$params[2],
$params[3],
$params[4],
$params[5],
count($this->_changes),
time()),
true)
serialize(array(
$params[0],
$params[1],
$params[2],
$params[3],
$params[4],
$params[5],
count($this->_changes),
time()))
)
);
try {
Expand Down

0 comments on commit b741276

Please sign in to comment.