Enhancement:

- Add more debug traces (if 'synchro_trace' == 'save')
- Show debug traces (if any) at the bottom of the status page
- Protect against time differences between the MySQL server and the PHP server, when running 'synchro_import.php'

SVN:2.2.0[4393]
This commit is contained in:
Denis Flaven
2016-09-12 12:39:59 +00:00
parent f01e5a5468
commit 960f63d1d0
2 changed files with 44 additions and 1 deletions

View File

@@ -322,7 +322,10 @@ try
$sSep = "\t";
}
$oLoadStartDate = new DateTime(); // Now
// In case there is a difference between the web server time and the DB server time,
// use the DB server time as a reference since this date/time will be compared with the "status_last_seen"
// column, which is populated by MySQL triggers (and so based on the DB server time)
$oLoadStartDate = new DateTime(CMDBSource::QueryToScalar('SELECT NOW()')); // Now... but as read from the database
// Note about date formatting: These MySQL settings are read-only... and in fact unused :-(
// SET SESSION date_format = '%d/%m/%Y';

View File

@@ -340,6 +340,7 @@ class SynchroDataSource extends cmdbAbstractObject
ToggleSynoptics('#cw_obj_new_unchanged_warnings', aValues['obj_new_unchanged_warnings'] > 0);
ToggleSynoptics('#cw_obj_updated_warnings', aValues['obj_updated_warnings'] > 0);
ToggleSynoptics('#cw_obj_unchanged_warnings', aValues['obj_unchanged_warnings'] > 0);
$('#status_traces').html(aValues['traces']);
}
EOF
;
@@ -391,6 +392,7 @@ EOF
$oPage->add($this->HtmlBox('obj_new_errors', $aData, '#C00', '', " <a style=\"color:#fff\" href=\"../synchro/replica.php?operation=oql&datasource=$iDSid&oql=$sOQL\" id=\"new_errors_link\">Show</a>"));
$oPage->add("</tr>\n</table>\n");
$oPage->add('</td></tr></table>');
$oPage->add('<div id="status_traces" style="overflow-x:auto"></div>');
$oPage->add_ready_script("UpdateSynoptics('$iLastLog')");
}
else
@@ -445,6 +447,14 @@ EOF
$aData['repl_ignored'] = $iIgnored;
$aData['nb_obj_total'] = $iNew + $iExisting + $iDisappeared;
$aData['nb_replica_total'] = $aData['nb_obj_total'] + $iIgnored;
if(strlen($oLastLog->Get('traces')) > 0)
{
$aData['traces'] = '<fieldset><legend>Debug traces</legend><pre>'.htmlentities($oLastLog->Get('traces'), ENT_QUOTES, 'UTF-8').'</pre></fieldset>';
}
else
{
$aData['traces'] = '';
}
return $aData;
}
@@ -1639,6 +1649,7 @@ class SynchroReplica extends DBObject implements iDisplay
public function Synchro($oDataSource, $aReconciliationKeys, $aAttributes, $oChange, &$oStatLog)
{
$oStatLog->AddTrace(">>> Beginning of SyncroReplica::Synchro, replica status is '".$this->Get('status')."'.", $this);
$this->ResetWarnings();
switch($this->Get('status'))
{
@@ -1671,11 +1682,14 @@ class SynchroReplica extends DBObject implements iDisplay
$oStatLog->AddTrace("Could not reconcile on null value for attribute '$sFilterCode'", $this);
$this->SetLastError("Could not reconcile on null value for attribute '$sFilterCode'");
$oStatLog->Inc('stats_nb_replica_reconciled_errors');
$oStatLog->AddTrace("<<< End of SyncroReplica::Synchro (error could not reconcile on null value for attribute '$sFilterCode').", $this);
return;
}
}
$oDestSet = new DBObjectSet(self::$aSearches[$oDataSource->GetKey()], array(), $aFilterValues);
$iCount = $oDestSet->Count();
$sDebugOQL = $oDestSet->GetFilter()->ToOQL(true);
$oStatLog->AddTrace("Reconciliation query: '$sDebugOQL' returned $iCount object(s).", $this);
$aConditions = array();
foreach($aFilterValues as $sCode => $sValue)
{
@@ -1689,6 +1703,7 @@ class SynchroReplica extends DBObject implements iDisplay
$oStatLog->AddTrace("Nothing found on: $sConditionDesc", $this);
if ($oDataSource->Get('action_on_zero') == 'create')
{
$oStatLog->AddTrace("Calling CreateObjectFromReplica", $this);
$bCreated = $this->CreateObjectFromReplica($oDataSource->GetTargetClass(), $aAttributes, $oChange, $oStatLog);
if ($bCreated)
{
@@ -1717,6 +1732,7 @@ class SynchroReplica extends DBObject implements iDisplay
if ($oDataSource->Get('action_on_one') == 'update')
{
$oDestObj = $oDestSet->Fetch();
$oStatLog->AddTrace("Calling UpdateObjectFromReplica(".(get_class($oDestObj).'::'.$oDestObj->GetKey()).")", $this);
$bModified = $this->UpdateObjectFromReplica($oDestObj, $aAttributes, $oChange, $oStatLog, 'stats_nb_obj_new', 'stats_nb_replica_reconciled_errors');
$this->Set('dest_id', $oDestObj->GetKey());
$this->Set('dest_class', get_class($oDestObj));
@@ -1819,6 +1835,7 @@ class SynchroReplica extends DBObject implements iDisplay
default: // Do nothing in all other cases
}
$oStatLog->AddTrace("<<< End of SyncroReplica::Synchro.", $this);
}
/**
@@ -2281,6 +2298,11 @@ class SynchroExecution
$this->m_oStatLog->Set('stats_nb_replica_total', $this->m_iCountAllReplicas);
$this->m_oStatLog->DBInsertTracked($this->m_oChange);
$sLastFullLoad = is_object($this->m_oLastFullLoadStartDate) ? $this->m_oLastFullLoadStartDate->format('Y-m-d H:i:s') : 'not specified';
$this->m_oStatLog->AddTrace("###### STARTING SYNCHRONIZATION ##### Total: {$this->m_iCountAllReplicas} replica(s). Last full load: '$sLastFullLoad' ");
$sSql = 'SELECT NOW();';
$sDBNow = CMDBSource::QueryToScalar($sSql);
$this->m_oStatLog->AddTrace("Database server current date/time is '$sDBNow', web server current date/time is: '".date('Y-m-d H:i:s')."'");
}
/**
@@ -2616,6 +2638,7 @@ class SynchroExecution
*/
protected function DoJob1($iMaxReplica = null, $iCurrPos = -1)
{
$this->m_oStatLog->AddTrace(">>> Beginning of DoJob1(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos)");
$sLimitDate = $this->m_oLastFullLoadStartDate->Format('Y-m-d H:i:s');
// Get all the replicas that were not seen in the last import and mark them as obsolete
@@ -2625,6 +2648,8 @@ class SynchroExecution
$sSelectToObsolete = "SELECT SynchroReplica WHERE id > :curr_pos AND sync_source_id = :source_id AND status IN ('new', 'synchronized', 'modified', 'orphan') AND status_last_seen < :last_import";
$oSetScope = new DBObjectSet(DBObjectSearch::FromOQL($sSelectToObsolete), array() /* order by*/, array('source_id' => $this->m_oDataSource->GetKey(), 'last_import' => $sLimitDate, 'curr_pos' => $iCurrPos));
$iCountScope = $oSetScope->Count();
$sDebugOql = $oSetScope->GetFilter()->ToOQL(true);
$this->m_oStatLog->AddTrace("Searching for replicas to mark as obsolete using query: '$sDebugOql', returned $iCountScope replica(s).");
if (($this->m_iCountAllReplicas > 10) && ($this->m_iCountAllReplicas == $iCountScope) && MetaModel::GetConfig()->Get('synchro_prevent_delete_all'))
{
throw new SynchroExceptionNotStarted(Dict::S('Core:SyncTooManyMissingReplicas'));
@@ -2693,6 +2718,7 @@ class SynchroExecution
{
// Continue with this job!
$this->m_oStatLog->Set('status_curr_pos', $iLastReplicaProcessed);
$this->m_oStatLog->AddTrace("<<< End of DoJob1(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos) (returning true => more replicas to process)");
return true;
}
}
@@ -2707,6 +2733,7 @@ class SynchroExecution
// Job complete!
$this->m_oStatLog->Set('status_curr_job', 2);
$this->m_oStatLog->Set('status_curr_pos', -1);
$this->m_oStatLog->AddTrace("<<< End of DoJob1(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos) (completed)");
return false;
}
@@ -2718,13 +2745,17 @@ class SynchroExecution
*/
protected function DoJob2($iMaxReplica = null, $iCurrPos = -1)
{
$this->m_oStatLog->AddTrace(">>> Beginning of DoJob2(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos)");
$sLimitDate = $this->m_oLastFullLoadStartDate->Format('Y-m-d H:i:s');
$this->m_oStatLog->AddTrace("\$sLimitDate = '$sLimitDate'");
// Get all the replicas that are 'new' or modified or synchronized with a warning
//
$sSelectToSync = "SELECT SynchroReplica WHERE id > :curr_pos AND (status = 'new' OR status = 'modified' OR (status = 'synchronized' AND status_last_warning != '')) AND sync_source_id = :source_id AND status_last_seen >= :last_import";
$oSetScope = new DBObjectSet(DBObjectSearch::FromOQL($sSelectToSync), array() /* order by*/, array('source_id' => $this->m_oDataSource->GetKey(), 'last_import' => $sLimitDate, 'curr_pos' => $iCurrPos), $this->m_aExtDataSpec);
$iCountScope = $oSetScope->Count();
$sDebugOQL = $oSetScope->GetFilter()->ToOQL(true);
$this->m_oStatLog->AddTrace("Looking for - new, modified or synchonized with a warning - replicas using the OQL query: '$sDebugOQL', returned $iCountScope replicas.");
if ($iMaxReplica)
{
@@ -2742,7 +2773,9 @@ class SynchroExecution
while($oReplica = $oSetToProcess->Fetch())
{
$iLastReplicaProcessed = $oReplica->GetKey();
$this->m_oStatLog->AddTrace("Synchronizing replica id=$iLastReplicaProcessed.");
$oReplica->Synchro($this->m_oDataSource, $this->m_aReconciliationKeys, $this->m_aAttributes, $this->m_oChange, $this->m_oStatLog);
$this->m_oStatLog->AddTrace("Updating replica id=$iLastReplicaProcessed.");
$oReplica->DBUpdateTracked($this->m_oChange);
}
@@ -2752,6 +2785,7 @@ class SynchroExecution
{
// Continue with this job!
$this->m_oStatLog->Set('status_curr_pos', $iLastReplicaProcessed);
$this->m_oStatLog->AddTrace("<<< End of DoJob2(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos) (returning true => more replicas to process)");
return true;
}
}
@@ -2759,6 +2793,7 @@ class SynchroExecution
// Job complete!
$this->m_oStatLog->Set('status_curr_job', 3);
$this->m_oStatLog->Set('status_curr_pos', -1);
$this->m_oStatLog->AddTrace("<<< End of DoJob2(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos) (completed)");
return false;
}
@@ -2770,12 +2805,15 @@ class SynchroExecution
*/
protected function DoJob3($iMaxReplica = null, $iCurrPos = -1)
{
$this->m_oStatLog->AddTrace(">>> Beginning of DoJob3(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos)");
$sDeletePolicy = $this->m_oDataSource->Get('delete_policy');
if ($sDeletePolicy != 'update_then_delete')
{
$this->m_oStatLog->AddTrace("\$sDeletePoliciy = $sDeletePolicy != 'update_then_delete', nothing to do!");
// Job complete!
$this->m_oStatLog->Set('status_curr_job', 0);
$this->m_oStatLog->Set('status_curr_pos', -1);
$this->m_oStatLog->AddTrace("<<< End of DoJob3(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos) (completed)");
return false;
}
@@ -2825,12 +2863,14 @@ class SynchroExecution
{
// Continue with this job!
$this->m_oStatLog->Set('status_curr_pos', $iLastReplicaProcessed);
$this->m_oStatLog->AddTrace("<<< End of DoJob3\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos) (returning true => more replicas to process)");
return true;
}
}
// Job complete!
$this->m_oStatLog->Set('status_curr_job', 0);
$this->m_oStatLog->Set('status_curr_pos', -1);
$this->m_oStatLog->AddTrace("<<< End of DoJob3(\$iMaxReplica = $iMaxReplica, \$iCurrPos = $iCurrPos) (completed)");
return false;
}
}