0011590: improve concurrent update check performance
[tine20] / tine20 / Tinebase / Timemachine / ModificationLog.php
1 <?php
2 /**
3  * Tine 2.0
4  * 
5  * @package     Tinebase
6  * @subpackage  Timemachine 
7  * @license     http://www.gnu.org/licenses/agpl.html AGPL Version 3
8  * @author      Cornelius Weiss <c.weiss@metaways.de>
9  * @copyright   Copyright (c) 2007-2012 Metaways Infosystems GmbH (http://www.metaways.de)
10  *
11  */
12
13 /**
14  * ModificationLog tracks and supplies the logging of modifications on a field 
15  * basis of records. It's an generic approach which could be usesed by any 
16  * application. Besides, providing a logbook, the real power of ModificationLog 
17  * depends the combination with the Timemachine.
18  * 
19  * ModificationLog logges differences of complete fields. This is in contrast to
20  * changetracking of other products which have sub field resolution. As in
21  * general, the sub field approach offers most felxibility, the complete field 
22  * solution is an adequate compromise for usage and performace.
23  * 
24  * ModificationLog is used by Tinebase_Timemachine_Abstract. If an application
25  * backened extends Tinebase_Timemachine_Abstract, it MUST use 
26  * Tinebase_Timemachine_ModificationLog to track modifications
27  * 
28  * NOTE: Maximum time resolution is one second. If there are more than one
29  * modifications in a second, they are distinguished by the accounts which made
30  * the modifications and a autoincement key of the underlaying database table.
31  * NOTE: Timespans are allways defined, with the beginning point excluded and
32  * the end point included. Mathematical: (_from, _until]
33  * 
34  * @package Tinebase
35  * @subpackage Timemachine
36  * 
37  * @todo Add registry for logbook starttime and methods to throw away logbook 
38  *       entries. Throw exceptions when times are requested which are not in the 
39  *       log anymore!
40  * @todo refactor this to use generic sql backend + remove Tinebase_Db_Table usage
41  */
42 class Tinebase_Timemachine_ModificationLog
43 {
44     /**
45      * Tablename SQL_TABLE_PREFIX . timemachine_modificationlog
46      *
47      * @var string
48      */
49     protected $_tablename = 'timemachine_modlog';
50     
51     /**
52      * Holds table instance for timemachine_history table
53      *
54      * @var Tinebase_Db_Table
55      */
56     protected $_table = NULL;
57     
58     /**
59      * holds names of meta properties in record
60      * 
61      * @var array
62      * 
63      * @todo move 'toOmit' fields to record (getModlogOmitFields)
64      * @todo allow notes modlog
65      * 
66      * @see 0007494: add changes in notes to modlog/history
67      */
68     protected $_metaProperties = array(
69         'created_by',
70         'creation_time',
71         'last_modified_by',
72         'last_modified_time',
73         'is_deleted',
74         'deleted_time',
75         'deleted_by',
76         'seq',
77     // @todo allow notes modlog
78         'notes',
79     // record specific properties / no meta properties 
80     // @todo to be moved to (contact) record definition
81         'jpegphoto',
82     );
83     
84     /**
85      * the sql backend
86      * 
87      * @var Tinebase_Backend_Sql
88      */
89     protected $_backend;
90     
91     /**
92      * holds the instance of the singleton
93      *
94      * @var Tinebase_Timemachine_ModificationLog
95      */
96     private static $instance = NULL;
97
98     /**
99      * holds the applicationId of the current context temporarily.
100      *
101      * @var string
102      */
103     protected $_applicationId = NULL;
104     
105     /**
106      * the singleton pattern
107      *
108      * @return Tinebase_Timemachine_ModificationLog
109      */
110     public static function getInstance() 
111     {
112         if (self::$instance === NULL) {
113             self::$instance = new Tinebase_Timemachine_ModificationLog();
114         }
115         
116         return self::$instance;
117     }
118     
119     /**
120      * the constructor
121      *
122      */
123     private function __construct()
124     {
125         $this->_tablename = SQL_TABLE_PREFIX . $this->_tablename;
126         
127         $this->_table = new Tinebase_Db_Table(array('name' => $this->_tablename));
128         $this->_table->setRowClass('Tinebase_Model_ModificationLog');
129         
130         $this->_backend = new Tinebase_Backend_Sql(array(
131             'modelName' => 'Tinebase_Model_ModificationLog',
132             'tableName' => 'timemachine_modlog',
133         ));
134     }
135     
136     /**
137      * Returns modification of a given record in a given timespan
138      * 
139      * @param string $_application application of given identifier  
140      * @param string $_id identifier to retrieve modification log for
141      * @param string $_type 
142      * @param string $_backend 
143      * @param Tinebase_DateTime $_from beginning point of timespan, excluding point itself
144      * @param Tinebase_DateTime $_until end point of timespan, including point itself 
145      * @param int $_modifierId optional
146      * @return Tinebase_Record_RecordSet RecordSet of Tinebase_Model_ModificationLog
147      * 
148      * @todo use backend search() + Tinebase_Model_ModificationLogFilter
149      */
150     public function getModifications($_application, $_id, $_type = NULL, $_backend = 'Sql', DateTime $_from = NULL, DateTime $_until = NULL,  $_modifierId = NULL)
151     {
152         $id = ($_id instanceof Tinebase_Record_Abstract) ? $_id->getId() : $_id;
153         $application = Tinebase_Application::getInstance()->getApplicationByName($_application);
154         
155         $isoDef = 'Y-m-d\TH:i:s';
156         
157         $db = $this->_table->getAdapter();
158         $select = $db->select()
159             ->from($this->_tablename)
160             ->order('modification_time ASC')
161             ->where($db->quoteInto($db->quoteIdentifier('application_id') . ' = ?', $application->id))
162             ->where($db->quoteInto($db->quoteIdentifier('record_id') . ' = ?', $id));
163         
164         if ($_from) {
165             $select->where($db->quoteInto($db->quoteIdentifier('modification_time') . ' > ?', $_from->toString($isoDef)));
166         }
167         
168         if ($_until) {
169             $select->where($db->quoteInto($db->quoteIdentifier('modification_time') . ' <= ?', $_until->toString($isoDef)));
170         }
171         
172         if ($_type) {
173             $select->where($db->quoteInto($db->quoteIdentifier('record_type') . ' LIKE ?', $_type));
174         }
175         
176         if ($_backend) {
177             $select->where($db->quoteInto($db->quoteIdentifier('record_backend') . ' LIKE ?', $_backend));
178         }
179         
180         if ($_modifierId) {
181             $select->where($db->quoteInto($db->quoteIdentifier('modification_account') . ' = ?', $_modifierId));
182         }
183        
184         $stmt = $db->query($select);
185         $resultArray = $stmt->fetchAll(Zend_Db::FETCH_ASSOC);
186        
187         $modifications = new Tinebase_Record_RecordSet('Tinebase_Model_ModificationLog', $resultArray);
188         return $modifications;
189     }
190
191     /**
192      * get modifications by seq
193      *
194      * @param string $applicationId
195      * @param Tinebase_Record_Abstract $newRecord
196      * @param integer $currentSeq
197      * @return Tinebase_Record_RecordSet RecordSet of Tinebase_Model_ModificationLog
198      */
199     public function getModificationsBySeq($applicationId, Tinebase_Record_Abstract $newRecord, $currentSeq)
200     {
201         $filter = new Tinebase_Model_ModificationLogFilter(array(
202             array('field' => 'seq',            'operator' => 'greater', 'value' => $newRecord->seq),
203             array('field' => 'seq',            'operator' => 'less',    'value' => $currentSeq + 1),
204             array('field' => 'record_type',    'operator' => 'equals',  'value' => get_class($newRecord)),
205             array('field' => 'record_id',      'operator' => 'equals',  'value' => $newRecord->getId()),
206             array('field' => 'application_id', 'operator' => 'equals',  'value' => $applicationId),
207         ));
208         $paging = new Tinebase_Model_Pagination(array(
209             'sort' => 'seq'
210         ));
211         
212         return $this->_backend->search($filter, $paging);
213     }
214     
215     /**
216      * Computes effective difference from a set of modifications
217      * 
218      * If a attribute got changed more than once, the returned diff has all
219      * properties of the last change to the attribute, besides the 
220      * 'modified_from', which holds the modified_from of the first change.
221      * 
222      * @param Tinebase_Record_RecordSet $modifications
223      * @return Tinebase_Record_RecordSet differences
224      */
225     public function computeDiff(Tinebase_Record_RecordSet $modifications)
226     {
227         $diff = array();
228         foreach ($modifications as $modification) {
229             if ((isset($diff[$modification->modified_attribute]) || array_key_exists($modification->modified_attribute, $diff))) {
230                 $modification->old_value = $diff[$modification->modified_attribute]->old_value;
231             }
232             $diff[$modification->modified_attribute] = $modification;
233         }
234         return new Tinebase_Record_RecordSet('Tinebase_Model_ModificationLog', $diff);
235     }
236     
237     /**
238      * Returns a single logbook entry identified by an logbook identifier
239      * 
240      * @param   string _id
241      * @return  Tinebase_Model_ModificationLog
242      * @throws  Tinebase_Exception_NotFound
243      */
244     public function getModification($_id)
245     {
246         $db = $this->_table->getAdapter();
247         $stmt = $db->query($db->select()
248            ->from($this->_tablename)
249            ->where($this->_table->getAdapter()->quoteInto($db->quoteIdentifier('id') . ' = ?', $_id))
250         );
251         $RawLogEntry = $stmt->fetchAll(Zend_Db::FETCH_ASSOC);
252         
253         if (empty($RawLogEntry)) {
254             throw new Tinebase_Exception_NotFound("Modification Log with id: $_id not found!");
255         }
256         return new Tinebase_Model_ModificationLog($RawLogEntry[0], true);
257     }
258     
259     /**
260      * Saves a logbook record
261      * 
262      * @param Tinebase_Model_ModificationLog $modification
263      * @return string id
264      */
265     public function setModification(Tinebase_Model_ModificationLog $modification)
266     {
267         $modification->isValid(TRUE);
268         
269         $id = $modification->generateUID();
270         $modification->setId($id);
271         $modification->convertDates = true;
272         $modificationArray = $modification->toArray();
273         if (is_array($modificationArray['new_value'])) {
274             throw new Tinebase_Exception_Record_Validation("New value is an array! \n" . print_r($modificationArray['new_value'], true));
275         }
276         if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
277             . " Inserting modlog: " . print_r($modificationArray, TRUE));
278         try {
279             $this->_table->insert($modificationArray);
280         } catch (Zend_Db_Statement_Exception $zdse) {
281             if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
282                 $zdse->getMessage() . ' ' . print_r($modification->toArray(), TRUE));
283             
284             // check if unique key constraint failed
285             $filter = new Tinebase_Model_ModificationLogFilter(array(
286                 array('field' => 'seq',                'operator' => 'equals',  'value' => $modification->seq),
287                 array('field' => 'record_type',        'operator' => 'equals',  'value' => $modification->record_type),
288                 array('field' => 'record_id',          'operator' => 'equals',  'value' => $modification->record_id),
289                 array('field' => 'modified_attribute', 'operator' => 'equals',  'value' => $modification->modified_attribute),
290             ));
291             $result = $this->_backend->search($filter);
292             if (count($result) > 0) {
293                 throw new Tinebase_Timemachine_Exception_ConcurrencyConflict('Seq ' . $modification->seq . ' for record ' . $modification->record_id . ' already exists');
294             } else {
295                 throw $zdse;
296             }
297         }
298         
299         return $id;
300     }
301     
302     /**
303      * merges changes made to local storage on concurrent updates into the new record 
304      *
305      * @param string $applicationId
306      * @param  Tinebase_Record_Interface $newRecord record from user data
307      * @param  Tinebase_Record_Interface $curRecord record from storage
308      * @return Tinebase_Record_RecordSet with resolved concurrent updates (Tinebase_Model_ModificationLog records)
309      * @throws Tinebase_Timemachine_Exception_ConcurrencyConflict
310      */
311     public function manageConcurrentUpdates($applicationId, Tinebase_Record_Interface $newRecord, Tinebase_Record_Interface $curRecord)
312     {
313         if (! $newRecord->has('seq')) {
314             return $this->manageConcurrentUpdatesByTimestamp($newRecord, $curRecord, get_class($newRecord), 'Sql', $newRecord->getId());
315         }
316
317         $this->_applicationId = $applicationId;
318
319         $resolved = new Tinebase_Record_RecordSet('Tinebase_Model_ModificationLog');
320         if ($curRecord->seq != $newRecord->seq) {
321             
322             if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
323                 " Concurrent updates: current record last updated '" .
324                 ($curRecord->last_modified_time instanceof DateTime ? $curRecord->last_modified_time : 'unknown') .
325                 "' where record to be updated was last updated '" .
326                 ($newRecord->last_modified_time instanceof DateTime ? $newRecord->last_modified_time : 
327                     ($curRecord->creation_time instanceof DateTime ? $curRecord->creation_time : 'unknown')) .
328                 "' / current sequence: " . $curRecord->seq . " - new record sequence: " . $newRecord->seq);
329             
330             $loggedMods = $this->getModificationsBySeq($applicationId, $newRecord, $curRecord->seq);
331             
332             // effective modifications made to the record after current user got his record
333             $diffs = $this->computeDiff($loggedMods);
334             
335             if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
336                 " During the concurrent update, the following changes have been made: " .
337                 print_r($diffs->toArray(),true));
338             
339             $this->_resolveDiffs($resolved, $diffs, $newRecord);
340             
341         } else {
342             if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__ . " No concurrent updates.");
343         }
344         
345         return $resolved;
346     }
347     
348     /**
349      * we loop over the diffs! -> changes over fields which have no diff in storage are not in the loop!
350      * 
351      * @param Tinebase_Record_RecordSet $resolved
352      * @param Tinebase_Record_RecordSet $diffs
353      * @param Tinebase_Record_Interface $newRecord
354      */
355     protected function _resolveDiffs(Tinebase_Record_RecordSet $resolved, Tinebase_Record_RecordSet $diffs, Tinebase_Record_Interface $newRecord)
356     {
357         foreach ($diffs as $diff) {
358             $newUserValue = isset($newRecord[$diff->modified_attribute]) ? Tinebase_Helper::normalizeLineBreaks($newRecord[$diff->modified_attribute]) : NULL;
359             
360             if (isset($newRecord[$diff->modified_attribute]) && $newUserValue == Tinebase_Helper::normalizeLineBreaks($diff->new_value)) {
361                 $this->_resolveScalarSameValue($newRecord, $diff);
362             
363             } else if (! isset($newRecord[$diff->modified_attribute]) || $newUserValue == Tinebase_Helper::normalizeLineBreaks($diff->old_value)) {
364                 $this->_resolveScalarMergeUpdate($newRecord, $diff);
365             
366             } else if ($newRecord[$diff->modified_attribute] instanceof Tinebase_Record_RecordSet) {
367                 $this->_resolveRecordSetMergeUpdate($newRecord, $diff);
368             
369             } else {
370                 $this->_nonResolvableConflict($newUserValue, $diff);
371             }
372             
373             $resolved->addRecord($diff);
374         }
375     }
376     
377     /**
378      * Update to same value, nothing to do
379      * 
380      * @param Tinebase_Record_Interface $newRecord
381      * @param Tinebase_Record_Diff $diff
382      */
383     protected function _resolveScalarSameValue(Tinebase_Record_Interface $newRecord, Tinebase_Model_ModificationLog $diff)
384     {
385         if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
386             . " User updated to same value for field '" . $diff->modified_attribute . "', nothing to do.");
387     }
388
389     /**
390      * Merge current value into update data, as it was not changed in update request
391      * 
392      * @param Tinebase_Record_Interface $newRecord
393      * @param Tinebase_Record_Diff $diff
394      */
395     protected function _resolveScalarMergeUpdate(Tinebase_Record_Interface $newRecord, Tinebase_Model_ModificationLog $diff)
396     {
397         if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
398             . " Merge current value into update data, as it was not changed in update request.");
399         $newRecord[$diff->modified_attribute] = $diff->new_value;
400     }
401
402     /**
403      * record set diff resolving
404      * 
405      * @param Tinebase_Record_Interface $newRecord
406      * @param Tinebase_Model_ModificationLog $diff
407      */
408     protected function _resolveRecordSetMergeUpdate(Tinebase_Record_Interface $newRecord, Tinebase_Model_ModificationLog $diff)
409     {
410         $attribute = $diff->modified_attribute;
411         
412         if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
413             . " Try to merge record set changes of record attribute " . $attribute);
414         if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
415             . ' New record: ' . print_r($newRecord->toArray(), TRUE));
416         if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
417             . ' Mod log: ' . print_r($diff->toArray(), TRUE));
418         
419         $concurrentChangeDiff = new Tinebase_Record_RecordSetDiff(Zend_Json::decode($diff->new_value));
420         
421         if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
422             . ' RecordSet diff: ' . print_r($concurrentChangeDiff->toArray(), TRUE));
423         
424         foreach ($concurrentChangeDiff->added as $added) {
425             $addedRecord = new $concurrentChangeDiff->model($added);
426             if (! $newRecord->$attribute->getById($addedRecord->getId())) {
427                 if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
428                     . " Adding recently added record " . $addedRecord->getId());
429                 $newRecord->$attribute->addRecord($addedRecord);
430             }
431         }
432         
433         foreach ($concurrentChangeDiff->removed as $removed) {
434             $removedRecord = new $concurrentChangeDiff->model($removed);
435             $recordToRemove = $newRecord->$attribute->getById($removedRecord->getId());
436             if ($recordToRemove) {
437                 if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
438                     . " Removing record " . $recordToRemove->getId());
439                 $newRecord->$attribute->removeRecord($recordToRemove);
440             }
441         }
442         
443         foreach ($concurrentChangeDiff->modified as $modified) {
444             if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
445                 . ' modified diff: ' . print_r($modified, TRUE));
446             
447             $modifiedRecord = new $concurrentChangeDiff->model(array_merge(array('id' => $modified['id']), $modified['diff']), TRUE);
448             $newRecordsRecord = $newRecord->$attribute->getById($modifiedRecord->getId());
449             if ($newRecordsRecord && ($newRecordsRecord->has('seq') || $newRecordsRecord->has('last_modified_time'))) {
450                 if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
451                     . ' Managing updates for ' . get_class($newRecordsRecord) . ' record ' . $newRecordsRecord->getId());
452                 if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
453                     . ' new record: ' . print_r($newRecordsRecord->toArray(), TRUE));
454                 if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
455                     . ' modified record: ' . print_r($modifiedRecord->toArray(), TRUE));
456
457                 if (null === $this->_applicationId) {
458                     throw new Tinebase_Exception_UnexpectedValue('application_id needs to be set here');
459                 }
460                 $this->manageConcurrentUpdates($this->_applicationId, $newRecordsRecord, $modifiedRecord);
461             } else {
462                 throw new Tinebase_Timemachine_Exception_ConcurrencyConflict('concurrency conflict - modified record changes could not be merged!');
463             }
464         }
465         
466         if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
467             . ' New record after merge: ' . print_r($newRecord->toArray(), TRUE));
468     }
469     
470     /**
471      * Non resolvable concurrency conflict detected
472      * 
473      * @param string $newUserValue
474      * @param Tinebase_Record_Diff $diff
475      * @throws Tinebase_Timemachine_Exception_ConcurrencyConflict
476      */
477     protected function _nonResolvableConflict($newUserValue, Tinebase_Model_ModificationLog $diff)
478     {
479         if (Tinebase_Core::isLogLevel(Zend_Log::ERR)) Tinebase_Core::getLogger()->err(__METHOD__ . '::' . __LINE__ 
480             . " Non resolvable conflict for field '" . $diff->modified_attribute . "'!");
481         if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
482             . ' New user value: ' . var_export($newUserValue, TRUE)
483             . ' New diff value: ' . var_export($diff->new_value, TRUE)
484             . ' Old diff value: ' . var_export($diff->old_value, TRUE));
485         
486         throw new Tinebase_Timemachine_Exception_ConcurrencyConflict('concurrency conflict!');
487     }
488     
489     /**
490      * merges changes made to local storage on concurrent updates into the new record 
491      * 
492      * @param  Tinebase_Record_Interface $_newRecord record from user data
493      * @param  Tinebase_Record_Interface $_curRecord record from storage
494      * @param  string $_model
495      * @param  string $_backend
496      * @param  string $_id
497      * @return Tinebase_Record_RecordSet with resolved concurrent updates (Tinebase_Model_ModificationLog records)
498      * @throws Tinebase_Timemachine_Exception_ConcurrencyConflict
499      * 
500      * @deprecated this should be removed when all records have seq(uence)
501      */
502     public function manageConcurrentUpdatesByTimestamp(Tinebase_Record_Interface $_newRecord, Tinebase_Record_Interface $_curRecord, $_model, $_backend, $_id)
503     {
504         if (Tinebase_Core::isLogLevel(Zend_Log::INFO)) Tinebase_Core::getLogger()->info(__METHOD__ . '::' . __LINE__
505             . ' Calling deprecated method. Model ' . $_model . ' should get a seq property.');
506         
507         list($appName, $i, $modelName) = explode('_', $_model);
508         
509         $resolved = new Tinebase_Record_RecordSet('Tinebase_Model_ModificationLog');
510         
511         // handle concurrent updates on unmodified records
512         if (! $_newRecord->last_modified_time instanceof DateTime) {
513             if ($_curRecord->creation_time instanceof DateTime) {
514                 $_newRecord->last_modified_time = clone $_curRecord->creation_time;
515             } else {
516                 Tinebase_Core::getLogger()->warn(__METHOD__ . '::' . __LINE__ 
517                     . ' Something went wrong! No creation_time was set in current record: ' 
518                     . print_r($_curRecord->toArray(), TRUE)
519                 );
520                 return $resolved;
521             }
522         }
523         
524         if ($_curRecord->last_modified_time instanceof DateTime && !$_curRecord->last_modified_time->equals($_newRecord->last_modified_time)) {
525                 if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ . " concurrent updates: current record last updated '" .
526                 $_curRecord->last_modified_time . "' where record to be updated was last updated '" . $_newRecord->last_modified_time . "'");
527             
528             $loggedMods = $this->getModifications($appName, $_id,
529                 $_model, $_backend, $_newRecord->last_modified_time, $_curRecord->last_modified_time);
530             // effective modifications made to the record after current user got his record
531             $diffs = $this->computeDiff($loggedMods);
532                 if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ . " during the concurrent update, the following changes have been made: " .
533                 print_r($diffs->toArray(),true));
534             
535             // we loop over the diffs! -> changes over fields which have no diff in storage are not in the loop!
536             foreach ($diffs as $diff) {
537                 $newUserValue = isset($_newRecord[$diff->modified_attribute]) ? Tinebase_Helper::normalizeLineBreaks($_newRecord[$diff->modified_attribute]) : NULL;
538                 
539                 if (isset($_newRecord[$diff->modified_attribute]) && $newUserValue == Tinebase_Helper::normalizeLineBreaks($diff->new_value)) {
540                     if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
541                         . " User updated to same value for field '" . $diff->modified_attribute . "', nothing to do.");
542                     $resolved->addRecord($diff);
543                 } elseif (! isset($_newRecord[$diff->modified_attribute]) || $newUserValue == Tinebase_Helper::normalizeLineBreaks($diff->old_value)) {
544                     if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
545                         . " Merge current value into update data, as it was not changed in update request.");
546                     $_newRecord[$diff->modified_attribute] = $diff->new_value;
547                     $resolved->addRecord($diff);
548                 } else {
549                     Tinebase_Core::getLogger()->err(__METHOD__ . '::' . __LINE__ . " Non resolvable conflict for field '" . $diff->modified_attribute . "'!");
550                     throw new Tinebase_Timemachine_Exception_ConcurrencyConflict('concurrency conflict!');
551                 }
552             }
553         }
554         
555         return $resolved;
556     }
557     
558     /**
559      * computes changes of records and writes them to the logbook
560      * 
561      * NOTE: expects last_modified_by and last_modified_time to be set
562      * properly in the $_newRecord
563      * 
564      * @param  Tinebase_Record_Abstract $_newRecord record from user data
565      * @param  Tinebase_Record_Abstract $_curRecord record from storage
566      * @param  string $_model
567      * @param  string $_backend
568      * @param  string $_id
569      * @return Tinebase_Record_RecordSet RecordSet of Tinebase_Model_ModificationLog
570      */
571     public function writeModLog($_newRecord, $_curRecord, $_model, $_backend, $_id)
572     {
573         $commonModLog = $this->_getCommonModlog($_model, $_backend, array(
574             'last_modified_time' => $_newRecord->last_modified_time, 
575             'last_modified_by'   => $_newRecord->last_modified_by,
576             'seq'                => ($_newRecord->has('seq')) ? $_newRecord->seq : 0,
577         ), $_id);
578         $diffs = $_curRecord->diff($_newRecord)->diff;
579         
580         if (! empty($diffs) && Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
581             . ' Diffs: ' . print_r($diffs, TRUE));
582         if (! empty($diffs) && Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
583             . ' CurRecord: ' . print_r($_curRecord->toArray(), TRUE));
584         if (! empty($diffs) && Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
585             . ' NewRecord: ' . print_r($_newRecord->toArray(), TRUE));        
586         if (! empty($commonModLog) && Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
587             . ' Common modlog: ' . print_r($commonModLog->toArray(), TRUE));
588         
589         $modifications = new Tinebase_Record_RecordSet('Tinebase_Model_ModificationLog');
590         $this->_loopModifications($diffs, $commonModLog, $modifications, $_curRecord->toArray(), $_curRecord->getModlogOmitFields());
591         
592         if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__
593             . ' Logged ' . count($modifications) . ' modifications.');
594         
595         return $modifications;
596     }
597     
598     /**
599      * creates a common modlog record
600      * 
601      * @param string $_model
602      * @param string $_backend
603      * @param array $_updateMetaData
604      * @param string $_recordId
605      * @return Tinebase_Model_ModificationLog
606      */
607     protected function _getCommonModlog($_model, $_backend, $_updateMetaData = array(), $_recordId = NULL)
608     {
609         if (empty($_updateMetaData)) {
610             list($currentAccountId, $currentTime) = Tinebase_Timemachine_ModificationLog::getCurrentAccountIdAndTime();
611         } else {
612             $currentAccountId = $_updateMetaData['last_modified_by'];
613             $currentTime      = $_updateMetaData['last_modified_time'];
614         }
615         
616         list($appName, $i, $modelName) = explode('_', $_model);
617         $commonModLogEntry = new Tinebase_Model_ModificationLog(array(
618             'application_id'       => Tinebase_Application::getInstance()->getApplicationByName($appName)->getId(),
619             'record_id'            => $_recordId,
620             'record_type'          => $_model,
621             'record_backend'       => $_backend,
622             'modification_time'    => $currentTime,
623             'modification_account' => $currentAccountId,
624             'seq'                  => (isset($_updateMetaData['seq'])) ? $_updateMetaData['seq'] : 0,
625         ), TRUE);
626         
627         return $commonModLogEntry;
628     }
629     
630     /**
631      * loop the modifications
632      * 
633      * @param array $_newData
634      * @param Tinebase_Model_ModificationLog $_commonModlog
635      * @param Tinebase_Record_RecordSet $_modifications
636      * @param array $_currentData
637      * @param array $_toOmit
638      */
639     protected function _loopModifications($_newData, Tinebase_Model_ModificationLog $_commonModlog, Tinebase_Record_RecordSet $_modifications, $_currentData, $_toOmit = array())
640     {
641         $toOmit = array_merge($this->_metaProperties, $_toOmit);
642         foreach ($_newData as $field => $newValue) {
643             if (in_array($field, $toOmit)) {
644                 continue;
645             }
646             
647             $curValue = (isset($_currentData[$field])) ? $_currentData[$field] : '';
648             
649             $curValue = $this->_convertToJsonString($curValue);
650             $newValue = $this->_convertToJsonString($newValue);
651             
652             if ($curValue === $newValue) {
653                 if (Tinebase_Core::isLogLevel(Zend_Log::INFO)) Tinebase_Core::getLogger()->info(__METHOD__ . '::' . __LINE__
654                     . ' Current and new value match. It looks like the diff() failed or you passed identical data for field ' . $field);
655                 continue;
656             }
657             
658             if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
659                 . " Field '$field' changed.");
660             if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__
661                 . " Change: from '$curValue' to '$newValue'");
662             
663             $modLogEntry = clone $_commonModlog;
664             $modLogEntry->modified_attribute = $field;
665             $modLogEntry->old_value = $curValue;
666             $modLogEntry->new_value = $newValue;
667             $modLogEntry->setId($this->setModification($modLogEntry));
668             
669             $_modifications->addRecord($modLogEntry);
670         }
671     }
672     
673     /**
674      * convert to json string
675      * 
676      * @param mixed $_value
677      * @return string
678      */
679     protected function _convertToJsonString($_value)
680     {
681         if (is_scalar($_value)) {
682             return $_value;
683         }
684         
685         $result = $_value;
686         if ($result instanceof Tinebase_Record_RecordSet) {
687             $result = $result->getArrayOfIds();
688         } else if ($result instanceof Tinebase_Record_RecordSetDiff) {
689             $result = $result->toArray();
690         } else if (method_exists($result, 'toString')) {
691             return $result->toString();
692         }
693         
694         return (is_array($result)) ? Zend_Json::encode($result) : '';
695     }
696     
697     /**
698      * write modlog for multiple records
699      * 
700      * @param array $_ids
701      * @param array $_oldData
702      * @param array $_newData
703      * @param string $_model
704      * @param string $_backend
705      * @param array $updateMetaData
706      * @return Tinebase_Record_RecordSet RecordSet of Tinebase_Model_ModificationLog
707      */
708     public function writeModLogMultiple($_ids, $_currentData, $_newData, $_model, $_backend, $updateMetaData = array())
709     {
710         $commonModLog = $this->_getCommonModlog($_model, $_backend, $updateMetaData);
711         
712         $modifications = new Tinebase_Record_RecordSet('Tinebase_Model_ModificationLog');
713         
714         if (Tinebase_Core::isLogLevel(Zend_Log::INFO)) Tinebase_Core::getLogger()->info(__METHOD__ . '::' . __LINE__
715             . ' Writing modlog for ' . count($_ids) . ' records.');
716         
717         foreach ($_ids as $id) {
718             $commonModLog->record_id = $id;
719             if (isset($updateMetaData['recordSeqs']) && (isset($updateMetaData['recordSeqs'][$id]) || array_key_exists($id, $updateMetaData['recordSeqs']))) {
720                 $commonModLog->seq = (! empty($updateMetaData['recordSeqs'][$id])) ? $updateMetaData['recordSeqs'][$id] + 1 : 1;
721             }
722             $this->_loopModifications($_newData, $commonModLog, $modifications, $_currentData);
723         }
724         
725         return $modifications;
726     }
727     
728     /**
729      * undo modlog records defined by filter
730      * 
731      * @param Tinebase_Model_ModificationLogFilter $filter
732      * @param boolean $overwrite should changes made after the detected change be overwritten?
733      * @param boolean $dryrun
734      * @return integer count of reverted changes
735      * 
736      * @todo use iterator?
737      * @todo return updated records/exceptions?
738      * @todo create result model / should be used in Tinebase_Controller_Record_Abstract::updateMultiple, too
739      * @todo use transaction with rollback for dryrun?
740      * @todo allow to undo tags/customfields/...
741      */
742     public function undo(Tinebase_Model_ModificationLogFilter $filter, $overwrite = FALSE, $dryrun = FALSE)
743     {
744         $notUndoableFields = array('tags', 'customfields', 'relations');
745         
746         if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__ .
747             ' Filter: ' . print_r($filter->toArray(), TRUE));
748         
749         $modlogRecords = $this->_backend->search($filter, new Tinebase_Model_Pagination(array(
750             'sort' => array('record_type', 'modification_time')
751         )));
752         
753         if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
754             ' Found ' . count($modlogRecords) . ' modlog records matching the filter.');
755         
756         $updateCount = 0;
757         $failCount = 0;
758         $undoneModlogs = new Tinebase_Record_RecordSet('Tinebase_Model_ModificationLog');
759         $currentRecordType = NULL;
760         
761         foreach ($modlogRecords as $modlog) {
762             if ($currentRecordType !== $modlog->record_type || ! isset($controller)) {
763                 $currentRecordType = $modlog->record_type;
764                 $controller = Tinebase_Core::getApplicationInstance($modlog->record_type);
765             }
766
767             if (Tinebase_Core::isLogLevel(Zend_Log::TRACE)) Tinebase_Core::getLogger()->trace(__METHOD__ . '::' . __LINE__ .
768                 ' Modlog: ' . print_r($modlog->toArray(), TRUE));
769             
770             try {
771                 $record = $controller->get($modlog->record_id);
772                 
773                 if (! in_array($modlog->modified_attribute, $notUndoableFields) && ($overwrite || $record->seq === $modlog->seq)) {
774                     if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
775                         ' Reverting change id ' . $modlog->getId());
776                     
777                     $record->{$modlog->modified_attribute} = $modlog->old_value;
778                     if (! $dryrun) {
779                         $controller->update($record);
780                     }
781                     $updateCount++;
782                     $undoneModlogs->addRecord($modlog);
783                 } else {
784                     if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
785                         ' Not reverting change of ' . $modlog->modified_attribute . ' of record ' . $modlog->record_id);
786                 }
787             } catch (Exception $e) {
788                 if (Tinebase_Core::isLogLevel(Zend_Log::NOTICE)) Tinebase_Core::getLogger()->notice(__METHOD__ . '::' . __LINE__ . ' ' . $e);
789                 $failCount++;
790             }
791         }
792         
793         if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
794             ' Reverted ' . $updateCount . ' modlog changes.');
795         
796         return array(
797             'totalcount'     => $updateCount,
798             'failcount'      => $failCount,
799             'undoneModlogs'  => $undoneModlogs,
800 //             'exceptions' => NULL,
801 //             'results'    => NULL,
802         );
803     }
804     
805     /**
806      * sets record modification data and protects it from spoofing
807      * 
808      * @param   Tinebase_Record_Abstract $_newRecord record from user data
809      * @param   string                    $_action    one of {create|update|delete}
810      * @param   Tinebase_Record_Abstract $_curRecord record from storage
811      * @throws  Tinebase_Exception_InvalidArgument
812      */
813     public static function setRecordMetaData($_newRecord, $_action, $_curRecord = NULL)
814     {
815         // disable validation as this is slow and we are setting valid data here
816         $bypassFilters = $_newRecord->bypassFilters;
817         $_newRecord->bypassFilters = TRUE;
818         
819         list($currentAccountId, $currentTime) = self::getCurrentAccountIdAndTime();
820         
821         // spoofing protection
822         $_newRecord->created_by         = $_curRecord ? $_curRecord->created_by : NULL;
823         $_newRecord->creation_time      = $_curRecord ? $_curRecord->creation_time : NULL;
824         $_newRecord->last_modified_by   = $_curRecord ? $_curRecord->last_modified_by : NULL;
825         $_newRecord->last_modified_time = $_curRecord ? $_curRecord->last_modified_time : NULL;
826         $_newRecord->is_deleted         = $_curRecord ? $_curRecord->is_deleted : 0;
827         $_newRecord->deleted_time       = $_curRecord ? $_curRecord->deleted_time : NULL;
828         $_newRecord->deleted_by         = $_curRecord ? $_curRecord->deleted_by : NULL;
829         
830         switch ($_action) {
831             case 'create':
832                 $_newRecord->created_by    = $currentAccountId;
833                 $_newRecord->creation_time = $currentTime;
834                 if ($_newRecord->has('seq')) {
835                     $_newRecord->seq       = 1;
836                 }
837                 break;
838             case 'update':
839                 $_newRecord->last_modified_by   = $currentAccountId;
840                 $_newRecord->last_modified_time = $currentTime;
841                 self::increaseRecordSequence($_newRecord, $_curRecord);
842                 break;
843             case 'delete':
844                 $_newRecord->deleted_by   = $currentAccountId;
845                 $_newRecord->deleted_time = $currentTime;
846                 $_newRecord->is_deleted   = true;
847                 self::increaseRecordSequence($_newRecord, $_curRecord);
848                 break;
849             default:
850                 throw new Tinebase_Exception_InvalidArgument('Action must be one of {create|update|delete}.');
851                 break;
852         }
853         
854         $_newRecord->bypassFilters = $bypassFilters;
855     }
856     
857     /**
858      * increase record sequence
859      * 
860      * @param Tinebase_Record_Abstract $newRecord
861      * @param Tinebase_Record_Abstract $curRecord
862      */
863     public static function increaseRecordSequence($newRecord, $curRecord = NULL)
864     {
865         if (is_object($curRecord) && $curRecord->has('seq')) {
866             $newRecord->seq = (int) $curRecord->seq +1;
867             
868             if (Tinebase_Core::isLogLevel(Zend_Log::DEBUG)) Tinebase_Core::getLogger()->debug(__METHOD__ . '::' . __LINE__ .
869                 ' Increasing seq of ' . get_class($newRecord) . ' with id ' . $newRecord->getId() .
870                 ' from ' . ($newRecord->seq - 1) . ' to ' . $newRecord->seq);
871         }
872     }
873     
874     /**
875      * returns current account id and time
876      * 
877      * @return array
878      */
879     public static function getCurrentAccountIdAndTime()
880     {
881         $currentAccount   = Tinebase_Core::getUser();
882         $currentAccountId = $currentAccount instanceof Tinebase_Record_Abstract ? $currentAccount->getId(): NULL;
883         $currentTime      = new Tinebase_DateTime();
884
885         return array($currentAccountId, $currentTime);
886     }
887
888     /**
889      * removes modlog entries for that application
890      *
891      * @param Tinebase_Model_Application $applicationName
892      *
893      * @return void
894      */
895     public function removeApplication(Tinebase_Model_Application $_application)
896     {
897         $this->_backend->deleteByProperty($_application->getId(), 'application_id');
898     }
899 }