diff --git a/lib/ext/Syncroton/Server.php b/lib/ext/Syncroton/Server.php index a4d7840..51c9214 100644 --- a/lib/ext/Syncroton/Server.php +++ b/lib/ext/Syncroton/Server.php @@ -1,459 +1,462 @@ */ /** * class to handle incoming http ActiveSync requests * * @package Syncroton */ class Syncroton_Server { const PARAMETER_ATTACHMENTNAME = 0; const PARAMETER_COLLECTIONID = 1; const PARAMETER_ITEMID = 3; const PARAMETER_OPTIONS = 7; const MAX_HEARTBEAT_INTERVAL = 3540; // 59 minutes protected $_body; /** * informations about the currently device * * @var Syncroton_Backend_IDevice */ protected $_deviceBackend; /** * @var Zend_Log */ protected $_logger; /** * @var Zend_Controller_Request_Http */ protected $_request; protected $_userId; public function __construct($userId, Zend_Controller_Request_Http $request = null, $body = null) { if (Syncroton_Registry::isRegistered('loggerBackend')) { $this->_logger = Syncroton_Registry::get('loggerBackend'); } $this->_userId = $userId; $this->_request = $request instanceof Zend_Controller_Request_Http ? $request : new Zend_Controller_Request_Http(); $this->_body = $body !== null ? $body : fopen('php://input', 'r'); $this->_deviceBackend = Syncroton_Registry::getDeviceBackend(); } public function handle() { if ($this->_logger instanceof Zend_Log) $this->_logger->debug(__METHOD__ . '::' . __LINE__ . ' REQUEST METHOD: ' . $this->_request->getMethod()); switch($this->_request->getMethod()) { case 'OPTIONS': $this->_handleOptions(); break; case 'POST': $this->_handlePost(); break; case 'GET': echo "It works!
Your userid is: {$this->_userId} and your IP address is: {$_SERVER['REMOTE_ADDR']}."; break; } } /** * handle options request */ protected function _handleOptions() { $command = new Syncroton_Command_Options(); $this->_sendHeaders($command->getHeaders()); } protected function _sendHeaders(array $headers) { foreach ($headers as $name => $value) { header($name . ': ' . $value); } } /** * handle post request */ protected function _handlePost() { $requestParameters = $this->_getRequestParameters($this->_request); if ($this->_logger instanceof Zend_Log) $this->_logger->debug(__METHOD__ . '::' . __LINE__ . ' REQUEST ' . print_r($requestParameters, true)); $className = 'Syncroton_Command_' . $requestParameters['command']; if (!class_exists($className)) { if ($this->_logger instanceof Zend_Log) $this->_logger->notice(__METHOD__ . '::' . __LINE__ . " command not supported: " . $requestParameters['command']); header("HTTP/1.1 501 not implemented"); return; } // get user device $device = $this->_getUserDevice($this->_userId, $requestParameters); if ($requestParameters['contentType'] == 'application/vnd.ms-sync.wbxml' || $requestParameters['contentType'] == 'application/vnd.ms-sync') { // decode wbxml request try { $decoder = new Syncroton_Wbxml_Decoder($this->_body); $requestBody = $decoder->decode(); if ($this->_logger instanceof Zend_Log) { - $requestBody->formatOutput = true; - $this->_logger->debug(__METHOD__ . '::' . __LINE__ . " xml request:\n" . $requestBody->saveXML()); + $this->_logDomDocument($requestBody, 'request', __METHOD__, __LINE__); } } catch(Syncroton_Wbxml_Exception_UnexpectedEndOfFile $e) { if ($this->_logger instanceof Zend_Log) $this->_logger->warn(__METHOD__ . '::' . __LINE__ . " unexpected end of file."); $requestBody = NULL; } } else { $requestBody = $this->_body; } header("MS-Server-ActiveSync: 14.00.0536.000"); // avoid sending HTTP header "Content-Type: text/html" for empty sync responses ini_set('default_mimetype', 'application/vnd.ms-sync.wbxml'); try { $command = new $className($requestBody, $device, $requestParameters); $response = $command->handle(); if (!$response) { $response = $command->getResponse(); } } catch (Syncroton_Exception_ProvisioningNeeded $sepn) { if ($this->_logger instanceof Zend_Log) $this->_logger->info(__METHOD__ . '::' . __LINE__ . " provisioning needed"); header("HTTP/1.1 449 Retry after sending a PROVISION command"); if (version_compare($device->acsversion, '14.0', '>=')) { $response = $sepn->domDocument; } else { // pre 14.0 method return; } } catch (Exception $e) { if ($this->_logger instanceof Zend_Log) $this->_logger->err(__METHOD__ . '::' . __LINE__ . " unexpected exception occured: " . get_class($e)); if ($this->_logger instanceof Zend_Log) $this->_logger->err(__METHOD__ . '::' . __LINE__ . " exception message: " . $e->getMessage()); if ($this->_logger instanceof Zend_Log) $this->_logger->err(__METHOD__ . '::' . __LINE__ . " " . $e->getTraceAsString()); header("HTTP/1.1 500 Internal server error"); return; } if ($response instanceof DOMDocument) { if ($this->_logger instanceof Zend_Log) { - $this->_logDomDocument(Zend_Log::DEBUG, $response, __METHOD__, __LINE__); + $this->_logDomDocument($response, 'response', __METHOD__, __LINE__); } if (isset($command) && $command instanceof Syncroton_Command_ICommand) { $this->_sendHeaders($command->getHeaders()); } $outputStream = fopen("php://temp", 'r+'); $encoder = new Syncroton_Wbxml_Encoder($outputStream, 'UTF-8', 3); try { $encoder->encode($response); } catch (Syncroton_Wbxml_Exception $swe) { if ($this->_logger instanceof Zend_Log) { $this->_logger->err(__METHOD__ . '::' . __LINE__ . " Could not encode output: " . $swe); } header("HTTP/1.1 500 Internal server error"); return; } if ($requestParameters['acceptMultipart'] == true) { $parts = $command->getParts(); // output multipartheader $bodyPartCount = 1 + count($parts); // number of parts (4 bytes) $header = pack('i', $bodyPartCount); $partOffset = 4 + (($bodyPartCount * 2) * 4); // wbxml body start and length $streamStat = fstat($outputStream); $header .= pack('ii', $partOffset, $streamStat['size']); $partOffset += $streamStat['size']; // calculate start and length of parts foreach ($parts as $partId => $partStream) { rewind($partStream); $streamStat = fstat($partStream); // part start and length $header .= pack('ii', $partOffset, $streamStat['size']); $partOffset += $streamStat['size']; } echo $header; } // output body rewind($outputStream); fpassthru($outputStream); // output multiparts if (isset($parts)) { foreach ($parts as $partStream) { rewind($partStream); fpassthru($partStream); } } } } /** * write (possible big) DOMDocument in smaller chunks to log file * - * @param int $priority * @param DOMDocument $dom + * @param string $action * @param string $method * @param int $line */ - protected function _logDomDocument($priority, DOMDocument $dom, $method, $line) + protected function _logDomDocument(DOMDocument $dom, $action, $method, $line) { + if (method_exists($this->_logger, 'hasDebug') && !$this->_logger->hasDebug()) { + return; + } + $tempStream = tmpfile(); $meta_data = stream_get_meta_data($tempStream); $filename = $meta_data["uri"]; $dom->formatOutput = true; $dom->save($filename); $dom->formatOutput = false; rewind($tempStream); $loops = 0; while (!feof($tempStream)) { - $this->_logger->log($method . '::' . $line . " xml response($loops):\n" . fread($tempStream, 1048576), $priority); + $this->_logger->debug("{$method}::{$line} xml {$action} ({$loops}):\n" . fread($tempStream, 1048576)); $loops++; } fclose($tempStream); } /** * return request params * * @return array */ protected function _getRequestParameters(Zend_Controller_Request_Http $request) { if (strpos($request->getRequestUri(), '&') === false) { $commands = array( 0 => 'Sync', 1 => 'SendMail', 2 => 'SmartForward', 3 => 'SmartReply', 4 => 'GetAttachment', 9 => 'FolderSync', 10 => 'FolderCreate', 11 => 'FolderDelete', 12 => 'FolderUpdate', 13 => 'MoveItems', 14 => 'GetItemEstimate', 15 => 'MeetingResponse', 16 => 'Search', 17 => 'Settings', 18 => 'Ping', 19 => 'ItemOperations', 20 => 'Provision', 21 => 'ResolveRecipients', 22 => 'ValidateCert' ); $requestParameters = substr($request->getRequestUri(), strpos($request->getRequestUri(), '?')); $stream = fopen("php://temp", 'r+'); fwrite($stream, base64_decode($requestParameters)); rewind($stream); // unpack the first 4 bytes $unpacked = unpack('CprotocolVersion/Ccommand/vlocale', fread($stream, 4)); // 140 => 14.0 $protocolVersion = substr($unpacked['protocolVersion'], 0, -1) . '.' . substr($unpacked['protocolVersion'], -1); $command = $commands[$unpacked['command']]; $locale = $unpacked['locale']; // unpack deviceId $length = ord(fread($stream, 1)); if ($length > 0) { $toUnpack = fread($stream, $length); $unpacked = unpack("H" . ($length * 2) . "string", $toUnpack); $deviceId = $unpacked['string']; } // unpack policyKey $length = ord(fread($stream, 1)); if ($length > 0) { $unpacked = unpack('Vstring', fread($stream, $length)); $policyKey = $unpacked['string']; } // unpack device type $length = ord(fread($stream, 1)); if ($length > 0) { $unpacked = unpack('A' . $length . 'string', fread($stream, $length)); $deviceType = $unpacked['string']; } while (! feof($stream)) { $tag = ord(fread($stream, 1)); $length = ord(fread($stream, 1)); // If the stream is at the end we'll get a 0-length if (!$length) { continue; } switch ($tag) { case self::PARAMETER_ATTACHMENTNAME: $unpacked = unpack('A' . $length . 'string', fread($stream, $length)); $attachmentName = $unpacked['string']; break; case self::PARAMETER_COLLECTIONID: $unpacked = unpack('A' . $length . 'string', fread($stream, $length)); $collectionId = $unpacked['string']; break; case self::PARAMETER_ITEMID: $unpacked = unpack('A' . $length . 'string', fread($stream, $length)); $itemId = $unpacked['string']; break; case self::PARAMETER_OPTIONS: $options = ord(fread($stream, 1)); $saveInSent = !!($options & 0x01); $acceptMultiPart = !!($options & 0x02); break; default: if ($this->_logger instanceof Zend_Log) $this->_logger->crit(__METHOD__ . '::' . __LINE__ . " found unhandled command parameters"); } } $result = array( 'protocolVersion' => $protocolVersion, 'command' => $command, 'deviceId' => $deviceId, 'deviceType' => isset($deviceType) ? $deviceType : null, 'policyKey' => isset($policyKey) ? $policyKey : null, 'saveInSent' => isset($saveInSent) ? $saveInSent : false, 'collectionId' => isset($collectionId) ? $collectionId : null, 'itemId' => isset($itemId) ? $itemId : null, 'attachmentName' => isset($attachmentName) ? $attachmentName : null, 'acceptMultipart' => isset($acceptMultiPart) ? $acceptMultiPart : false ); } else { $result = array( 'protocolVersion' => $request->getServer('HTTP_MS_ASPROTOCOLVERSION'), 'command' => $request->getQuery('Cmd'), 'deviceId' => $request->getQuery('DeviceId'), 'deviceType' => $request->getQuery('DeviceType'), 'policyKey' => $request->getServer('HTTP_X_MS_POLICYKEY'), 'saveInSent' => $request->getQuery('SaveInSent') == 'T', 'collectionId' => $request->getQuery('CollectionId'), 'itemId' => $request->getQuery('ItemId'), 'attachmentName' => $request->getQuery('AttachmentName'), 'acceptMultipart' => $request->getServer('HTTP_MS_ASACCEPTMULTIPART') == 'T' ); } $result['userAgent'] = $request->getServer('HTTP_USER_AGENT', $result['deviceType']); $result['contentType'] = $request->getServer('CONTENT_TYPE'); return $result; } /** * get existing device of owner or create new device for owner * * @param unknown_type $ownerId * @param unknown_type $deviceId * @param unknown_type $deviceType * @param unknown_type $userAgent * @param unknown_type $protocolVersion * @return Syncroton_Model_Device */ protected function _getUserDevice($ownerId, $requestParameters) { try { $device = $this->_deviceBackend->getUserDevice($ownerId, $requestParameters['deviceId']); $device->useragent = $requestParameters['userAgent']; $device->acsversion = $requestParameters['protocolVersion']; if ($device->isDirty()) { $device = $this->_deviceBackend->update($device); } } catch (Syncroton_Exception_NotFound $senf) { $device = $this->_deviceBackend->create(new Syncroton_Model_Device(array( 'owner_id' => $ownerId, 'deviceid' => $requestParameters['deviceId'], 'devicetype' => $requestParameters['deviceType'], 'useragent' => $requestParameters['userAgent'], 'acsversion' => $requestParameters['protocolVersion'], 'policyId' => Syncroton_Registry::isRegistered(Syncroton_Registry::DEFAULT_POLICY) ? Syncroton_Registry::get(Syncroton_Registry::DEFAULT_POLICY) : null ))); } return $device; } public static function validateSession() { $validatorFunction = Syncroton_Registry::getSessionValidator(); return $validatorFunction(); } } diff --git a/lib/kolab_sync_logger.php b/lib/kolab_sync_logger.php index 1d7fd84..7b31525 100644 --- a/lib/kolab_sync_logger.php +++ b/lib/kolab_sync_logger.php @@ -1,170 +1,181 @@ | +--------------------------------------------------------------------------+ | Author: Aleksander Machniak | +--------------------------------------------------------------------------+ */ /** * Class for logging messages into log file(s) */ class kolab_sync_logger extends Zend_Log { public $mode; protected $logfile; protected $format; protected $log_dir; protected $username; /** * Constructor */ function __construct($mode = null) { $rcube = rcube::get_instance(); $this->mode = intval($mode); $this->logfile = $rcube->config->get('activesync_log_file'); $this->format = $rcube->config->get('log_date_format', 'd-M-Y H:i:s O'); $this->log_dir = $rcube->config->get('log_dir'); $r = new ReflectionClass($this); $this->_priorities = $r->getConstants(); } public function __call($method, $params) { $method = strtoupper($method); if ($this->_priorities[$method] <= $this->mode) { $this->log(array_shift($params), $method); } } + /** + * Check whether debug logging is enabled + * + * @return bool + */ + public function hasDebug() + { + // This is what we check in self::log() below + return !empty($this->log_dir) && $this->mode >= self::NOTICE; + } + /** * Message logger * * @param string $message Log message * @param int|string $method Message severity */ public function log($message, $method, $extras = null) { if (is_numeric($method)) { $mode = $method; $method = array_search($method, $this->_priorities); } else { $mode = $this->_priorities[$method]; } // Don't log messages with lower prio than the configured one if ($mode > $this->mode) { return; } // Don't log debug messages if it's disabled e.g. by per_user_logging if (empty($this->log_dir) && $mode >= self::NOTICE) { return; } $rcube = rcube::get_instance(); $log_dir = $this->log_dir ?: $rcube->config->get('log_dir'); $logfile = $this->logfile; // if log_file is configured all logs will go to it // otherwise use separate file for info/debug and warning/error if (!$logfile) { switch ($mode) { case self::DEBUG: case self::INFO: case self::NOTICE: $file = 'console'; break; default: $file = 'errors'; break; } $logfile = $log_dir . DIRECTORY_SEPARATOR . $file; if (version_compare(version_parse(RCUBE_VERSION), '1.4.0') >= 0) { $logfile .= $rcube->config->get('log_file_ext', '.log'); } } else if ($logfile[0] != '/') { $logfile = $log_dir . DIRECTORY_SEPARATOR . $logfile; } if (!is_string($message)) { $message = var_export($message, true); } // add user/request information to the log if ($mode <= self::WARN) { $device = array(); $params = array('cmd' => 'Cmd', 'device' => 'DeviceId', 'type' => 'DeviceType'); if (!empty($this->username)) { $device['user'] = $this->username; } foreach ($params as $key => $val) { if ($val = $_GET[$val]) { $device[$key] = $val; } } if (!empty($device)) { $message = @json_encode($device) . ' ' . $message; } } $date = rcube_utils::date_format($this->format); $logline = sprintf("[%s]: [%s] %s\n", $date, $method, $message); if ($fp = @fopen($logfile, 'a')) { fwrite($fp, $logline); fflush($fp); fclose($fp); return; } if ($mode <= self::WARN) { // send error to PHPs error handler if write to file didn't succeed trigger_error($message, E_USER_WARNING); } } /** * Set current user name to add into error log */ public function set_username($username) { $this->username = $username; } /** * Set log directory */ public function set_log_dir($dir) { $this->log_dir = $dir; } }