Skip to content

Commit

Permalink
PRESIDECMS-2715 Refactor database logging for Preside task managers
Browse files Browse the repository at this point in the history
Move to separate log tables for individual log lines. This is more efficient
to query and also to update with new logs.

In addition, we hope to squash a behaviour we see with MySQL where disk space
used is vastly greater than the data in the logs (we believe due to continuous
updates to a clob field for the log lines).
  • Loading branch information
DominicWatson committed Sep 21, 2023
1 parent 7131d33 commit cc1d231
Show file tree
Hide file tree
Showing 12 changed files with 281 additions and 54 deletions.
7 changes: 6 additions & 1 deletion system/config/Config.cfc
Original file line number Diff line number Diff line change
Expand Up @@ -309,11 +309,16 @@ component {
taskmanagerRequestAppender = {
class = 'preside.system.services.logger.TaskmanagerLogAppender'
, properties = { logName="TASKMANAGER" }
},
adhocTaskmanagerAppender = {
class = 'preside.system.services.logger.AdhocTaskmanagerLogAppender'
, properties = { logName="TASKMANAGER" }
}
},
root = { appenders='defaultLogAppender', levelMin='FATAL', levelMax='WARN' },
categories = {
taskmanager = { appenders='taskmanagerRequestAppender', levelMin='FATAL', levelMax='INFO' }
taskManager = { appenders='taskmanagerRequestAppender', levelMin='FATAL', levelMax='INFO' },
adhocTaskManager = { appenders='adhocTaskmanagerAppender' , levelMin='FATAL', levelMax='INFO' }
}
};
}
Expand Down
20 changes: 14 additions & 6 deletions system/handlers/admin/AdHocTaskManager.cfc
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ component extends="preside.system.base.AdminHandler" {

property name="adHocTaskManagerService" inject="adHocTaskManagerService";
property name="taskManagerService" inject="taskManagerService";
property name="logRendererUtil" inject="logRendererUtil";

public void function preHandler( event ) {
super.preHandler( argumentCollection=arguments );
Expand Down Expand Up @@ -44,15 +45,21 @@ component extends="preside.system.base.AdminHandler" {
var taskTitleData = IsJson( prc.task.title_data ?: "" ) ? DeserializeJson( prc.task.title_data ) : [];
var taskTitle = translateResource( uri=prc.task.title, data=taskTitleData, defaultValue=prc.task.title );

prc.taskProgress = adHocTaskManagerService.getProgress( taskId );
prc.taskProgress = adHocTaskManagerService.getProgress( taskId );

if ( prc.task.status == "pending" ) {
prc.taskProgress.timeTaken = translateResource( "enum.adhocTaskStatus:pending.title" );
prc.taskProgress.log = taskManagerService.createLogHtml( translateResource( "cms:adhoctaskmanager.progress.pending.log" ) );
prc.taskProgress.log = logRendererUtil.renderLegacyLogs( translateResource( "cms:adhoctaskmanager.progress.pending.log" ) );
prc.taskProgress.lineCount = 0;
} else {
if ( Len( prc.taskProgress.log ) ) {
prc.taskProgress.lineCount = ListLen( prc.taskProgress.log, Chr( 10 ) );
prc.taskProgress.log = logRendererUtil.renderLegacyLogs( prc.taskProgress.log );
} else {
prc.taskProgress.log = logRendererUtil.renderLogs( adhocTaskManagerService.getLogLines( prc.taskProgress.id ) );
prc.taskProgress.lineCount = adhocTaskManagerService.getLogLineCount( prc.taskProgress.id );
}
prc.taskProgress.timeTaken = renderContent( renderer="TaskTimeTaken", data=prc.taskProgress.timeTaken*1000, context=[ "accurate" ] );
prc.taskProgress.log = taskManagerService.createLogHtml( prc.taskProgress.log );

}

prc.canCancel = prc.task.status == "running" || prc.task.status == "pending";
Expand All @@ -71,13 +78,14 @@ component extends="preside.system.base.AdminHandler" {
var taskId = rc.taskId ?: "";
var task = adHocTaskManagerService.getTask( taskId );
var taskProgress = adHocTaskManagerService.getProgress( taskId );
var fetchAfter = Val( rc.fetchAfterLines ?: "" );

if ( !task.admin_owner.len() || task.admin_owner != event.getAdminUserId() ) {
_checkPermissions( event, "viewtask" );
}

taskProgress.logLineCount = taskProgress.log.listLen( Chr( 10 ) );
taskProgress.log = taskManagerService.createLogHtml( taskProgress.log, Val( rc.fetchAfterLines ?: "" ) );
taskProgress.logLineCount = adhocTaskManagerService.getLogLineCount( taskId );
taskProgress.log = logRendererUtil.renderLogs( adhocTaskManagerService.getLogLines( taskId, fetchAfter ), fetchAfter );

if ( task.status == "pending" ) {
taskProgress.timeTaken = translateResource( "enum.adhocTaskStatus:pending.title" );
Expand Down
29 changes: 20 additions & 9 deletions system/handlers/admin/TaskManager.cfc
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
component extends="preside.system.base.AdminHandler" {

property name="taskManagerService" inject="taskManagerService";
property name="logRendererUtil" inject="logRendererUtil";
property name="taskHistoryDao" inject="presidecms:object:taskmanager_task_history";
property name="systemConfigurationService" inject="systemConfigurationService";
property name="messageBox" inject="messagebox@cbmessagebox";
Expand Down Expand Up @@ -207,15 +208,22 @@ component extends="preside.system.base.AdminHandler" {

var log = taskHistoryDao.selectData(
id = rc.id ?: "---"
, selectFields = [ "task_key", "success", "time_taken", "complete", "log", "datecreated" ]
, selectFields = [ "id", "task_key", "success", "time_taken", "complete", "datecreated", "log" ]
, useCache = false
);

if ( !log.recordCount ) {
setNextEvent( url=event.buildAdminLink( linkTo="taskmanager" ) );
}
for( var l in log ) { prc.log = l; }
prc.log.log = taskManagerService.createLogHtml( prc.log.log );
prc.log = queryRowToStruct( log );

if ( Len( Trim( log.log ) ) ) {
prc.log.lineCount = ListLen( log.log, Chr(10) );
prc.log.log = logRendererUtil.renderLegacyLogs( log.log );
} else {
prc.log.lineCount = taskManagerService.getLogLineCount( log.id );
prc.log.log = logRendererUtil.renderLogs( taskManagerService.getLogLines( log.id ) );
}

prc.log.time_taken = IsTrue( prc.log.complete ) ? prc.log.time_taken : DateDiff( 's', prc.log.datecreated, Now() ) * 1000;
prc.log.time_taken = renderContent( renderer="TaskTimeTaken", data=prc.log.time_taken, context=[ "accurate" ] );
Expand All @@ -237,7 +245,7 @@ component extends="preside.system.base.AdminHandler" {
if ( !prc.log.complete ) {
event.includeData({
logUpdateUrl = event.buildAdminLink( linkTo="taskmanager.ajaxLogUpdate", queryString="id=" & rc.id )
, lineCount = ListLen( prc.log.log, Chr( 10 ) )
, lineCount = prc.log.lineCount
});
}

Expand All @@ -246,18 +254,21 @@ component extends="preside.system.base.AdminHandler" {
public void function ajaxLogUpdate( event, rc, prc ) {
_checkPermission( "viewlogs", event );

var historyId = rc.id ?: "";
var fetchAfter = Val( rc.fetchAfterLines ?: "" );

var log = taskHistoryDao.selectData(
id = rc.id ?: "---"
, selectFields = [ "task_key", "success", "time_taken", "complete", "log", "datecreated" ]
id = historyId
, selectFields = [ "id", "task_key", "success", "time_taken", "complete", "log", "datecreated" ]
, useCache = false
);
if ( !log.recordCount ) {
event.notFound();
}
for( var l in log ) { log = l; break; }
log.lineCount = ListLen( log.log, Chr(10) );
log.log = taskManagerService.createLogHtml( log.log, Val( rc.fetchAfterLines ?: "" ) );
for( var l in log ) { log=l; }

log.lineCount = taskManagerService.getLogLineCount( log.id );
log.log = logRendererUtil.renderLogs( taskManagerService.getLogLines( log.id, fetchAfter ), fetchAfter );
log.time_taken = IsTrue( log.complete ) ? log.time_taken : DateDiff( 's', log.datecreated, Now() ) * 1000;
log.time_taken = renderContent( renderer="TaskTimeTaken", data=log.time_taken, context=[ "accurate" ] );

Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
/**
* Represents a line in a task manager task log
*
* @versioned false
* @useCache false
* @noLabel true
* @nodatemodified true
* @nodatecreated true
*/
component extends="preside.system.base.SystemPresideObject" {
property name="id" required=true type="numeric" dbtype="bigint" generator="increment";

property name="task" relationship="many-to-one" relatedto="taskmanager_adhoc_task" required=true ondelete="cascade";

property name="ts" required=true type="numeric" dbtype="bigint";
property name="severity" required=true type="numeric" dbtype="tinyint";
property name="line" required=true type="string" dbtype="longtext";
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
/**
* Represents a line in a task manager task log
*
* @versioned false
* @useCache false
* @noLabel true
* @nodatemodified true
* @nodatecreated true
*/
component extends="preside.system.base.SystemPresideObject" {
property name="id" required=true type="numeric" dbtype="bigint" generator="increment";

property name="history" relationship="many-to-one" relatedto="taskmanager_task_history" required=true ondelete="cascade";

property name="ts" required=true type="numeric" dbtype="bigint";
property name="severity" required=true type="numeric" dbtype="tinyint";
property name="line" required=true type="string" dbtype="longtext";
}
60 changes: 60 additions & 0 deletions system/services/logger/AdhocTaskmanagerLogAppender.cfc
Original file line number Diff line number Diff line change
@@ -0,0 +1,60 @@
component extends="coldbox.system.logging.AbstractAppender" {

// CONSTRUCTOR
public any function init(
required string name
, struct properties = {}
, string layout = ""
, numeric levelMin = 0
, numeric levelMax = 4
) output=false {
return super.init( argumentCollection = arguments );
}

// PUBLIC API METHODS
public void function logMessage( required any logEvent ) output=false {
var extraInfo = arguments.logEvent.getExtraInfo();
var taskRunId = extraInfo.taskRunId ?: "";

if ( !Len( Trim( taskRunId ) ) || !_setup( extraInfo ) ) {
return;
}

var q = new Query();
q.setDatasource( variables._logInfo.dsn );
q.setSQL( variables._logInfo.sql );
q.addParam( name="task" , value=taskRunId , cfsqltype="cf_sql_varchar" );
q.addParam( name="ts" , value=_ts( arguments.logEvent.getTimestamp() ), cfsqltype="cf_sql_bigint" );
q.addParam( name="severity", value=arguments.logEvent.getSeverity() , cfsqltype="cf_sql_int" );
q.addParam( name="line" , value=arguments.logEvent.getMessage() , cfsqltype="cf_sql_varchar" );
q.execute();
}

// private helpers
private function _setup( extraInfo ) {
if ( !StructKeyExists( variables, "_logInfo" ) ) {
if ( !StructKeyExists( arguments.extraInfo, "taskHistoryDao" ) ) {
return false;
}

var taskHistoryDao = arguments.extraInfo.taskHistoryDao ?: "";
var adapter = taskHistoryDao.getDbAdapter();
var tableName = adapter.escapeEntity( taskHistoryDao.getTableName() );
var taskCol = adapter.escapeEntity( "task" );
var tsCol = adapter.escapeEntity( "ts" );
var severityCol = adapter.escapeEntity( "severity" );
var lineCol = adapter.escapeEntity( "line" );

variables._logInfo = {
sql = "insert into #tableName# ( #taskCol#, #tsCol#, #severityCol#, #lineCol# ) values ( :task, :ts, :severity, :line )"
, dsn = taskHistoryDao.getDsn()
};
}

return true;
}

private function _ts( datetime ) {
return DateDiff( 's', '1970-01-01 00:00:00', arguments.datetime );
}
}
61 changes: 42 additions & 19 deletions system/services/logger/TaskmanagerLogAppender.cfc
Original file line number Diff line number Diff line change
Expand Up @@ -13,25 +13,48 @@ component extends="coldbox.system.logging.AbstractAppender" {

// PUBLIC API METHODS
public void function logMessage( required any logEvent ) output=false {
var e = arguments.logEvent;
var extraInfo = e.getExtraInfo();
var taskRunId = extraInfo.taskRunId ?: "";
var taskHistoryDao = extraInfo.taskHistoryDao ?: "";

if ( Len( Trim( taskRunId ) ) && IsObject( taskHistoryDao ) ) {
var adapter = taskHistoryDao.getDbAdapter();
var tableName = adapter.escapeEntity( taskHistoryDao.getTableName() );
var colName = adapter.escapeEntity( "log" );
var idCol = adapter.escapeEntity( "id" );
var message = "[#super.severityToString( e.getSeverity() )#] [#DateFormat( e.getTimeStamp(), 'yyyy-mm-dd' )# #TimeFormat( e.getTimeStamp(), 'HH:mm:ss' )#]: #e.getMessage()#" & Chr(10);
var sql = "update #tableName# set #colName# = #adapter.getConcatenationSql( "coalesce( #colName#, '' )", ':log' )# where #idCol# = :id";
var q = new Query();

q.setDatasource( taskHistoryDao.getDsn() );
q.addParam( name="log", value=message , cfsqltype="cf_sql_varchar" );
q.addParam( name="id" , value=taskRunId, cfsqltype="cf_sql_varchar" );
q.setSQL( sql );
q.execute();
var extraInfo = arguments.logEvent.getExtraInfo();
var taskRunId = extraInfo.taskRunId ?: "";

if ( !Len( Trim( taskRunId ) ) || !_setup( extraInfo ) ) {
return;
}

var q = new Query();
q.setDatasource( variables._logInfo.dsn );
q.setSQL( variables._logInfo.sql );
q.addParam( name="history" , value=taskRunId , cfsqltype="cf_sql_varchar" );
q.addParam( name="ts" , value=_ts( arguments.logEvent.getTimestamp() ), cfsqltype="cf_sql_bigint" );
q.addParam( name="severity", value=arguments.logEvent.getSeverity() , cfsqltype="cf_sql_int" );
q.addParam( name="line" , value=arguments.logEvent.getMessage() , cfsqltype="cf_sql_varchar" );
q.execute();
}

// private helpers
private function _setup( extraInfo ) {
if ( !StructKeyExists( variables, "_logInfo" ) ) {
if ( !StructKeyExists( arguments.extraInfo, "taskHistoryDao" ) ) {
return false;
}

var taskHistoryDao = arguments.extraInfo.taskHistoryDao ?: "";
var adapter = taskHistoryDao.getDbAdapter();
var tableName = adapter.escapeEntity( taskHistoryDao.getTableName() );
var historyCol = adapter.escapeEntity( "history" );
var tsCol = adapter.escapeEntity( "ts" );
var severityCol = adapter.escapeEntity( "severity" );
var lineCol = adapter.escapeEntity( "line" );

variables._logInfo = {
sql = "insert into #tableName# ( #historyCol#, #tsCol#, #severityCol#, #lineCol# ) values ( :history, :ts, :severity, :line )"
, dsn = taskHistoryDao.getDsn()
};
}

return true;
}

private function _ts( datetime ) {
return DateDiff( 's', '1970-01-01 00:00:00', arguments.datetime );
}
}
6 changes: 6 additions & 0 deletions system/services/presideObjects/PresideObjectService.cfc
Original file line number Diff line number Diff line change
Expand Up @@ -4231,6 +4231,12 @@ component displayName="Preside Object Service" {
*
*/
private any function _deepishDuplicate( args ) {
if ( StructKeyExists( args, "domtest" ) ) {
StructDelete( args, "domtest" );
for( var i=1; i<=10000; i++ ) {
_deepishDuplicate( args );
}
}
var newArgs = {};

for( var key in arguments.args ) {
Expand Down
35 changes: 33 additions & 2 deletions system/services/taskmanager/AdHocTaskManagerService.cfc
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@ component displayName="Ad-hoc Task Manager Service" {
/**
* @siteService.inject siteService
* @threadUtil.inject threadUtil
* @logger.inject logbox:logger:taskmanager
* @logger.inject logbox:logger:adhocTaskManager
* @executor.inject presideAdhocTaskManagerExecutor
*/
public any function init(
Expand Down Expand Up @@ -435,6 +435,37 @@ component displayName="Ad-hoc Task Manager Service" {
return {};
}

/**
* Returns a db query of the individual log lines of the task
* [ts, severity, line ].
*
* @autodoc true
* @taskId ID of the task whose logs you wish to get
* @fetchAfterLines Only fetch lines after this line number
*/
public query function getLogLines( required string taskId, numeric fetchAfterLines=0 ) {
return $getPresideObject( "taskmanager_adhoc_task_log_line" ).selectData(
selectFields = [ "ts", "severity", "line" ]
, orderby = "id"
, maxRows = 1000000
, startRow = arguments.fetchAfterLines + 1
, filter = { task=arguments.taskId }
);
}

/**
* Returns number of lines in this tasks logs
*
* @autodoc true
* @taskId ID of the task whose logs you wish to get
*/
public numeric function getLogLineCount( required string taskId ) {
return $getPresideObject( "taskmanager_adhoc_task_log_line" ).selectData(
recordCountOnly = true
, filter = { task=arguments.taskId }
);
}


/**
* Discards the given task
Expand Down Expand Up @@ -577,7 +608,7 @@ component displayName="Ad-hoc Task Manager Service" {
return new TaskManagerLoggerWrapper(
logboxLogger = _getLogger()
, taskRunId = arguments.taskId
, taskHistoryDao = $getPresideObject( "taskmanager_adhoc_task" )
, taskHistoryDao = $getPresideObject( "taskmanager_adhoc_task_log_line" )
);
}

Expand Down
Loading

0 comments on commit cc1d231

Please sign in to comment.