N°6408 - Add logs, changed modification test of current object and prevent calling OnDBUpdate() when object is not modified

This commit is contained in:
Eric Espie
2023-06-23 17:02:31 +02:00
parent 68ee12bf5e
commit c3469e43bc
24 changed files with 123 additions and 29 deletions

View File

@@ -4513,6 +4513,7 @@ HTML;
*/
public function DBInsertNoReload()
{
$this->LogCRUDEnter(__METHOD__);
try {
$res = parent::DBInsertNoReload();
@@ -4521,6 +4522,8 @@ HTML;
// Invoke extensions after insertion (the object must exist, have an id, etc.)
/** @var \iApplicationObjectExtension $oExtensionInstance */
foreach (MetaModel::EnumPlugins('iApplicationObjectExtension') as $oExtensionInstance) {
$sExtensionClass = get_class($oExtensionInstance);
$this->LogCRUDDebug(__METHOD__, "Calling $sExtensionClass::OnDBInsert()");
$oExtensionInstance->OnDBInsert($this, self::GetCurrentChange());
}
} finally {
@@ -4530,6 +4533,7 @@ HTML;
static::FireEventDbLinksChangedForAllObjects();
}
}
$this->LogCRUDExit(__METHOD__);
return $res;
}
@@ -4558,7 +4562,13 @@ HTML;
public function DBUpdate()
{
$this->LogCRUDEnter(__METHOD__);
try {
if (count($this->ListChanges()) === 0) {
$this->LogCRUDExit(__METHOD__);
return $this->GetKey();
}
$res = parent::DBUpdate();
$this->SetWarningsAsSessionMessages('update');
@@ -4568,7 +4578,7 @@ HTML;
if (!MetaModel::StartReentranceProtection($this)) {
$sClass = get_class($this);
$sKey = $this->GetKey();
IssueLog::Debug("CRUD: DBUpdate $sClass::$sKey Rejected (reentrance)", LogChannels::DM_CRUD);
$this->LogCRUDExit(__METHOD__, 'Rejected (reentrance)');
return $res;
}
@@ -4577,6 +4587,8 @@ HTML;
// Invoke extensions after the update (could be before)
/** @var \iApplicationObjectExtension $oExtensionInstance */
foreach (MetaModel::EnumPlugins('iApplicationObjectExtension') as $oExtensionInstance) {
$sExtensionClass = get_class($oExtensionInstance);
$this->LogCRUDDebug(__METHOD__, "Calling $sExtensionClass::OnDBUpdate()");
$oExtensionInstance->OnDBUpdate($this, self::GetCurrentChange());
}
}
@@ -4587,7 +4599,7 @@ HTML;
$aChanges = $this->ListChanges();
if (count($aChanges) != 0) {
$this->iUpdateLoopCount++;
if ($this->iUpdateLoopCount > self::MAX_UPDATE_LOOP_COUNT) {
if ($this->iUpdateLoopCount >= self::MAX_UPDATE_LOOP_COUNT) {
$sClass = get_class($this);
$sKey = $this->GetKey();
$aPlugins = [];
@@ -4595,9 +4607,11 @@ HTML;
$aPlugins[] = get_class($oExtensionInstance);
}
$sPlugins = implode(', ', $aPlugins);
IssueLog::Error("CRUD: DBUpdate $sClass::$sKey Update loop detected plugins: $sPlugins", LogChannels::DM_CRUD);
$this->LogCRUDError(__METHOD__, "Update loop detected among plugins: $sPlugins");
} else {
return $this->DBUpdate();
$sKey = $this->DBUpdate();
$this->LogCRUDExit(__METHOD__);
return $sKey;
}
}
} finally {
@@ -4605,6 +4619,7 @@ HTML;
static::FireEventDbLinksChangedForAllObjects();
}
}
$this->LogCRUDExit(__METHOD__);
return $res;
}
@@ -4628,6 +4643,7 @@ HTML;
public function DBDelete(&$oDeletionPlan = null)
{
$this->LogCRUDEnter(__METHOD__);
try {
parent::DBDelete($oDeletionPlan);
} finally {
@@ -4637,6 +4653,7 @@ HTML;
static::FireEventDbLinksChangedForAllObjects();
}
}
$this->LogCRUDExit(__METHOD__);
return $oDeletionPlan;
}
@@ -4665,9 +4682,12 @@ HTML;
/** @var \iApplicationObjectExtension $oExtensionInstance */
foreach(MetaModel::EnumPlugins('iApplicationObjectExtension') as $oExtensionInstance)
{
if ($oExtensionInstance->OnIsModified($this))
{
$sExtensionClass = get_class($oExtensionInstance);
if ($oExtensionInstance->OnIsModified($this)) {
$this->LogCRUDDebug(__METHOD__, "Calling $sExtensionClass::OnIsModified() -> true");
return true;
} else {
$this->LogCRUDDebug(__METHOD__, "Calling $sExtensionClass::OnIsModified() -> false");
}
}
@@ -6028,7 +6048,7 @@ JS
MetaModel::StartReentranceProtection($oObject);
$oObject->FireEvent(EVENT_DB_LINKS_CHANGED);
MetaModel::StopReentranceProtection($oObject);
if ($oObject->IsModified()) {
if (count($oObject->ListChanges()) !== 0) {
$oObject->DBUpdate();
}
}

View File

@@ -469,7 +469,10 @@ abstract class CMDBObject extends DBObject
*/
public function DBDelete(&$oDeletionPlan = null)
{
return $this->DBDeleteTracked_Internal($oDeletionPlan);
$this->LogCRUDEnter(__METHOD__);
$oDeletionPlan = $this->DBDeleteTracked_Internal($oDeletionPlan);
$this->LogCRUDExit(__METHOD__);
return $oDeletionPlan;
}
/**
@@ -519,14 +522,6 @@ abstract class CMDBObject extends DBObject
utils::PopArchiveMode();
}
}
public function DBUpdate()
{
if (count($this->ListChanges()) === 0) {
return $this->GetKey();
}
return parent::DBUpdate(); // TODO: Change the autogenerated stub
}
}

View File

@@ -601,6 +601,10 @@ abstract class DBObject implements iDisplay
*/
public function Set($sAttCode, $value)
{
if (!utils::StartsWith(get_class($this), 'CMDBChange') && $this->GetKey() > 0) {
$this->LogCRUDEnter(__METHOD__, "$sAttCode => $value");
}
$sMessage = $this->IsReadOnly();
if ($sMessage !== false) {
throw new CoreException($sMessage);
@@ -622,6 +626,9 @@ abstract class DBObject implements iDisplay
// First time Set is called... ensure that the object gets fully loaded
// Otherwise we would lose the values on a further Reload
// + consistency does not make sense !
$sFullyLoaded = $this->m_bFullyLoaded ? 'true' : 'false';
$sDirty = $this->m_bDirty ? 'true' : 'false';
$this->LogCRUDDebug(__METHOD__, "IsInDB: $this->m_bIsInDB, FullyLoaded: $sFullyLoaded, Dirty: $sDirty");
$this->Reload();
}
@@ -2926,6 +2933,8 @@ abstract class DBObject implements iDisplay
*/
public function DBInsert()
{
$this->LogCRUDEnter(__METHOD__);
$this->DBInsertNoReload();
foreach ($this->m_aLoadedAtt as $sAttCode => $bLoaded) {
@@ -2939,6 +2948,7 @@ abstract class DBObject implements iDisplay
}
}
$this->LogCRUDExit(__METHOD__);
return $this->m_iKey;
}
@@ -3217,7 +3227,7 @@ abstract class DBObject implements iDisplay
MetaModel::StopReentranceProtection($this);
}
if ($this->IsModified()) {
if ((count($this->ListChanges()) !== 0)) {
$this->DBUpdate();
}
}
@@ -3283,6 +3293,7 @@ abstract class DBObject implements iDisplay
*/
public function DBUpdate()
{
$this->LogCRUDEnter(__METHOD__);
if (!$this->m_bIsInDB)
{
throw new CoreException("DBUpdate: could not update a newly created object, please call DBInsert instead");
@@ -3291,7 +3302,7 @@ abstract class DBObject implements iDisplay
$sClass = get_class($this);
$sKey = $this->GetKey();
if (!MetaModel::StartReentranceProtection($this)) {
IssueLog::Debug("CRUD: DBUpdate $sClass::$sKey Rejected (reentrance)", LogChannels::DM_CRUD);
$this->LogCRUDExit(__METHOD__, 'Rejected (reentrance)');
return false;
}
@@ -3311,7 +3322,7 @@ abstract class DBObject implements iDisplay
if (count($aChanges) == 0)
{
// Attempting to update an unchanged object
IssueLog::Debug("CRUD: DBUpdate $sClass::$sKey Aborted (no change)", LogChannels::DM_CRUD);
$this->LogCRUDExit(__METHOD__, 'Aborted (no change)');
return $this->m_iKey;
}
@@ -3485,7 +3496,7 @@ abstract class DBObject implements iDisplay
$this->FireEventAfterWrite($aChanges, false);
$this->AfterUpdate();
// Save the status as it is reset just after...
$bModifiedByUpdateDone = $this->IsModified();
$bModifiedByUpdateDone = (count($this->ListChanges()) !== 0);
// Reset original values although the object has not been reloaded
foreach ($this->m_aLoadedAtt as $sAttCode => $bLoaded) {
@@ -3524,6 +3535,7 @@ abstract class DBObject implements iDisplay
}
catch (Exception $e)
{
$this->LogCRUDExit(__METHOD__, 'Error: '.$e->getMessage());
$aErrors = [$e->getMessage()];
throw new CoreException($e->getMessage(), ['id' => $this->GetKey(), 'class' => $sClass, 'issues' => $aErrors]);
}
@@ -3534,11 +3546,12 @@ abstract class DBObject implements iDisplay
$this->RemoveCurrentObjectInCrudStack();
}
if ($this->IsModified() || $bModifiedByUpdateDone) {
if ((count($this->ListChanges()) !== 0) || $bModifiedByUpdateDone) {
// Controlled reentrance
$this->DBUpdate();
}
$this->LogCRUDExit(__METHOD__);
return $this->m_iKey;
}
@@ -3718,6 +3731,7 @@ abstract class DBObject implements iDisplay
private function DBDeleteSingleTable($sTableClass)
{
$sTable = MetaModel::DBGetTable($sTableClass);
$this->LogCRUDEnter(__METHOD__, ' table: '.$sTable);
// Abstract classes or classes having no specific attribute do not have an associated table
if ($sTable == '') return;
@@ -3726,6 +3740,7 @@ abstract class DBObject implements iDisplay
$sDeleteSQL = "DELETE FROM `$sTable` WHERE $sPKField = $sKey";
CMDBSource::DeleteFrom($sDeleteSQL);
$this->LogCRUDExit(__METHOD__, ' table: '.$sTable);
}
/**
@@ -3740,8 +3755,10 @@ abstract class DBObject implements iDisplay
*/
protected function DBDeleteSingleObject()
{
$this->LogCRUDEnter(__METHOD__);
if (MetaModel::DBIsReadOnly())
{
$this->LogCRUDExit(__METHOD__, 'DB is read-only');
return;
}
@@ -3847,6 +3864,7 @@ abstract class DBObject implements iDisplay
}
}
}
$this->LogCRUDError(__METHOD__, ' Error: '.$e->getMessage());
throw $e;
}
}
@@ -3859,6 +3877,8 @@ abstract class DBObject implements iDisplay
// Fix for N°926: do NOT reset m_iKey as it can be used to have it for reporting purposes (see the REST service to delete
// objects, reported as bug N°926)
// Thought the key is not reset, using DBInsert or DBWrite will create an object having the same characteristics and a new ID. DBUpdate is protected
$this->LogCRUDExit(__METHOD__);
}
/**
@@ -3885,6 +3905,8 @@ abstract class DBObject implements iDisplay
*/
public function DBDelete(&$oDeletionPlan = null)
{
$this->LogCRUDEnter(__METHOD__);
static $iLoopTimeLimit = null;
if ($iLoopTimeLimit == null)
{
@@ -3900,6 +3922,7 @@ abstract class DBObject implements iDisplay
if ($oDeletionPlan->FoundStopper())
{
$aIssues = $oDeletionPlan->GetIssues();
$this->LogCRUDError(__METHOD__, ' Errors: '.implode(', ', $aIssues));
throw new DeleteException('Found issue(s)', array('target_class' => get_class($this), 'target_id' => $this->GetKey(), 'issues' => implode(', ', $aIssues)));
}
@@ -3950,6 +3973,7 @@ abstract class DBObject implements iDisplay
set_time_limit(intval($iPreviousTimeLimit));
$this->LogCRUDExit(__METHOD__);
return $oDeletionPlan;
}
@@ -6321,5 +6345,37 @@ abstract class DBObject implements iDisplay
{
return count(self::$m_aCrudStack) === 0;
}
protected function LogCRUDEnter($sFunction, $sComment = '')
{
$sClass = get_class($this);
$sKey = $this->GetKey();
$sPadding = str_pad('', count(self::$m_aCrudStack), '-');
IssueLog::Trace("CRUD +$sPadding> $sFunction $sClass:$sKey $sComment", LogChannels::DM_CRUD);
}
protected function LogCRUDExit($sFunction, $sComment = '')
{
$sClass = get_class($this);
$sKey = $this->GetKey();
$sPadding = str_pad('', count(self::$m_aCrudStack), '-');
IssueLog::Trace("CRUD <$sPadding+ $sFunction $sClass:$sKey $sComment", LogChannels::DM_CRUD);
}
protected function LogCRUDDebug($sFunction, $sComment = '')
{
$sClass = get_class($this);
$sKey = $this->GetKey();
$sPadding = str_pad('', count(self::$m_aCrudStack), '-');
IssueLog::Debug("CRUD --$sPadding $sFunction $sClass:$sKey $sComment", LogChannels::DM_CRUD);
}
protected function LogCRUDError($sFunction, $sComment = '')
{
$sClass = get_class($this);
$sKey = $this->GetKey();
$sPadding = str_pad('', count(self::$m_aCrudStack), '!');
IssueLog::Error("CRUD !!$sPadding Error $sFunction $sClass:$sKey $sComment", LogChannels::DM_CRUD);
}
}

View File

@@ -583,6 +583,12 @@ class LogChannels
*/
public const DM_CRUD = 'DMCRUD';
/**
* @var string Everything related to the datamodel CRUD
* @since 3.1.0
*/
public const WEB_REQUEST = 'WebRequest';
/**
* @var string Everything related to the event service
* @since 3.1.0

View File

@@ -301,7 +301,7 @@ require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/wizardhelper.class.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
try
{
$oKPI = new ExecutionKPI();

View File

@@ -24,6 +24,7 @@ require_once(APPROOT.'/application/applicationcontext.class.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
LoginWebPage::DoLogin(); // Check user rights and prompt if needed
ApplicationMenu::CheckMenuIdEnabled('UniversalSearchMenu');
@@ -123,4 +124,3 @@ if ($oFilter != null)
}
$oP->add("</div>\n");
$oP->output();
?>

View File

@@ -194,6 +194,7 @@ try
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
LoginWebPage::DoLogin(); // Check user rights and prompt if needed

View File

@@ -34,6 +34,7 @@ try
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
$oPage = new DownloadPage("");

View File

@@ -30,6 +30,7 @@ try
{
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/user.preferences.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
$oKPI = new ExecutionKPI();
$oKPI->ComputeAndReport('Data model loaded');

View File

@@ -11,6 +11,7 @@ use Combodo\iTop\Application\UI\Base\Component\Html\Html;
require_once('../approot.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
try
{

View File

@@ -144,8 +144,8 @@ try
{
require_once('../approot.inc.php');
require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
$bSelectionAuditRulesByDefault = utils::GetConfig()->Get('audit.enable_selection_landing_page');
$operation = utils::ReadParam('operation', $bSelectionAuditRulesByDefault ? 'selection' : 'audit');

View File

@@ -36,6 +36,7 @@ try {
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
if (utils::SetMinMemoryLimit('256M') === false) {
IssueLog::Warning('csvimport : cannot set minimum memory_limit !');

View File

@@ -24,6 +24,7 @@ require_once('../approot.inc.php');
// Needed to read the parameters (with sanitization)
require_once(APPROOT.'application/utils.inc.php');
require_once(APPROOT.'core/metamodel.class.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
utils::InitTimeZone();

View File

@@ -24,6 +24,7 @@ require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/utils.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
LoginWebPage::DoLogin(); // Check user rights and prompt if needed
/**
@@ -154,5 +155,3 @@ else
header('Content-Disposition: inline; filename="'.$sClass.'.png"');
readfile($sImageFilePath);
}
?>

View File

@@ -24,6 +24,7 @@ require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/wizardhelper.class.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
$oAppContext = new ApplicationContext();
$currentOrganization = utils::ReadParam('org_id', '');
$operation = utils::ReadParam('operation', '');

View File

@@ -27,6 +27,7 @@ require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
LoginWebPage::DoLogin(); // Check user rights and prompt if needed
ApplicationMenu::CheckMenuIdEnabled("NotificationsMenu");

View File

@@ -5,6 +5,7 @@ use Combodo\iTop\Controller\OAuth\OAuthLandingController;
require_once('../approot.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
$sTemplates = APPROOT.'templates/pages/backoffice/oauth';

View File

@@ -20,7 +20,7 @@
require_once('../approot.inc.php');
require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
$sFullUrl = utils::GetAbsoluteUrlAppRoot().'pages/UI.php';
$sICOFullUrl = utils::GetAbsoluteUrlAppRoot().'/images/favicon.ico';

View File

@@ -24,6 +24,7 @@ use Combodo\iTop\Application\UI\Preferences\BlockShortcuts\BlockShortcuts;
require_once('../approot.inc.php');
require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
/**
* Displays the user's changeable preferences

View File

@@ -26,6 +26,7 @@ require_once('../approot.inc.php');
require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
LoginWebPage::DoLogin(); // Check user rights and prompt if needed
ApplicationMenu::CheckMenuIdEnabled('RunQueriesMenu');

View File

@@ -19,6 +19,7 @@ require_once(APPROOT.'/application/application.inc.php');
require_once(APPROOT.'/application/startup.inc.php');
require_once(APPROOT.'/application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
LoginWebPage::DoLogin(); // Check user rights and prompt if needed
ApplicationMenu::CheckMenuIdEnabled('DataModelMenu');

View File

@@ -21,6 +21,7 @@ require_once('../approot.inc.php');
require_once(APPROOT.'application/application.inc.php');
require_once(APPROOT.'application/startup.inc.php');
require_once(APPROOT.'application/loginwebpage.class.inc.php');
IssueLog::Trace('----- Request: '.utils::GetRequestUri(), LogChannels::WEB_REQUEST);
try
{

View File

@@ -95,7 +95,7 @@ final class EventService
self::$aEventListeners[$sEvent] = $aEventCallbacks;
$sSource = self::GetSourcesAsString($sEventSource);
EventServiceLog::Debug("Registering Listener '$sName' for event '$sEvent' source '$sSource' from '$sModuleId'");
EventServiceLog::Trace("Registering Listener '$sName' for event '$sEvent' source '$sSource' from '$sModuleId'");
return $sId;
}

View File

@@ -49,7 +49,7 @@ class ApplicationObjectExtensionTest extends \Combodo\iTop\Test\UnitTest\ItopDat
self::$iCalls = 0;
}
public function testUpdateReentranceProtection()
public function testExtensionCalled()
{
// Check that extension is called
$oPerson = $this->CreatePerson(1);
@@ -58,6 +58,11 @@ class ApplicationObjectExtensionTest extends \Combodo\iTop\Test\UnitTest\ItopDat
self::ResetCallCount();
$oPerson->DBUpdate();
$this->assertEquals(1, self::$iCalls);
}
public function testUpdateReentranceProtection()
{
$oPerson = $this->CreatePerson(1);
// Check that loop limit is 10
$i = 15;