CLOUDSTACK-1047: tracking in logs using job id.

This commit is contained in:
Sanjay Tripathi 2013-06-17 17:01:39 +05:30 committed by Devdeep Singh
parent 3e8edd74b9
commit 2e8d16b365
2 changed files with 81 additions and 61 deletions

View File

@ -213,7 +213,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
job.setSyncSource(null);
scheduleExecution(job, scheduleJobExecutionInContext);
if(s_logger.isDebugEnabled()) {
s_logger.debug("submit async job-" + job.getId() + ", details: " + job.toString());
s_logger.debug("submit async job-" + job.getId() + " = [ " + job.getUuid() + " ], details: " + job.toString());
}
publishOnEventBus(job, "submit");
return job.getId();
@ -227,25 +227,25 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
@Override @DB
public void completeAsyncJob(long jobId, int jobStatus, int resultCode, Object resultObject) {
if(s_logger.isDebugEnabled()) {
s_logger.debug("Complete async job-" + jobId + ", jobStatus: " + jobStatus +
", resultCode: " + resultCode + ", result: " + resultObject);
AsyncJobVO job = _jobDao.findById(jobId);
String jobUuid = null;
if (job != null) {
jobUuid = job.getUuid();
if(s_logger.isDebugEnabled()) {
s_logger.debug("Complete async job-" + jobId + " = [ " + jobUuid + " ], jobStatus: " + jobStatus +
", resultCode: " + resultCode + ", result: " + resultObject);
}
} else {
if(s_logger.isDebugEnabled()) {
s_logger.debug("job-" + jobId + " no longer exists, we just log completion info here. " + jobStatus +
", resultCode: " + resultCode + ", result: " + resultObject);
}
return;
}
Transaction txt = Transaction.currentTxn();
try {
txt.start();
AsyncJobVO job = _jobDao.findById(jobId);
if(job == null) {
if(s_logger.isDebugEnabled()) {
s_logger.debug("job-" + jobId + " no longer exists, we just log completion info here. " + jobStatus +
", resultCode: " + resultCode + ", result: " + resultObject);
}
txt.rollback();
return;
}
job.setCompleteMsid(getMsid());
job.setStatus(jobStatus);
job.setResultCode(resultCode);
@ -264,31 +264,31 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
_jobDao.update(jobId, job);
txt.commit();
} catch(Exception e) {
s_logger.error("Unexpected exception while completing async job-" + jobId, e);
s_logger.error("Unexpected exception while completing async job-" + jobId + " = [ " + jobUuid + " ]", e);
txt.rollback();
}
}
@Override @DB
public void updateAsyncJobStatus(long jobId, int processStatus, Object resultObject) {
if(s_logger.isDebugEnabled()) {
s_logger.debug("Update async-job progress, job-" + jobId + ", processStatus: " + processStatus +
", result: " + resultObject);
AsyncJobVO job = _jobDao.findById(jobId);
String jobUuid = null;
if (job != null) {
jobUuid = job.getUuid();
if(s_logger.isDebugEnabled()) {
s_logger.debug("Update async-job progress, job-" + jobId + " = [ " + jobUuid + " ], processStatus: " + processStatus +
", result: " + resultObject);
}
} else {
if(s_logger.isDebugEnabled()) {
s_logger.debug("job-" + jobId + " no longer exists, we just log progress info here. progress status: " + processStatus);
}
return;
}
Transaction txt = Transaction.currentTxn();
try {
txt.start();
AsyncJobVO job = _jobDao.findById(jobId);
if(job == null) {
if(s_logger.isDebugEnabled()) {
s_logger.debug("job-" + jobId + " no longer exists, we just log progress info here. progress status: " + processStatus);
}
txt.rollback();
return;
}
job.setProcessStatus(processStatus);
if(resultObject != null) {
job.setResult(ApiSerializerHelper.toSerializedStringOld(resultObject));
@ -298,23 +298,32 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
publishOnEventBus(job, "update");
txt.commit();
} catch(Exception e) {
s_logger.error("Unexpected exception while updating async job-" + jobId + " status: ", e);
s_logger.error("Unexpected exception while updating async job-" + jobId + " = [ " + jobUuid + " ] status: ", e);
txt.rollback();
}
}
@Override @DB
public void updateAsyncJobAttachment(long jobId, String instanceType, Long instanceId) {
if(s_logger.isDebugEnabled()) {
s_logger.debug("Update async-job attachment, job-" + jobId + ", instanceType: " + instanceType +
", instanceId: " + instanceId);
AsyncJobVO job = _jobDao.findById(jobId);
String jobUuid = null;
if (job != null) {
jobUuid = job.getUuid();
if(s_logger.isDebugEnabled()) {
s_logger.debug("Update async-job attachment, job-" + jobId + " = [ " + jobUuid + " ], instanceType: "
+ instanceType + ", instanceId: " + instanceId);
}
} else {
if(s_logger.isDebugEnabled()) {
s_logger.debug("job-" + jobId + " no longer exists, instanceType: " + instanceType + ", instanceId: "
+ instanceId);
}
return;
}
Transaction txt = Transaction.currentTxn();
try {
txt.start();
AsyncJobVO job = _jobDao.createForUpdate();
//job.setInstanceType(instanceType);
job.setInstanceId(instanceId);
job.setLastUpdated(DateUtil.currentGMTTime());
@ -322,7 +331,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
txt.commit();
} catch(Exception e) {
s_logger.error("Unexpected exception while updating async job-" + jobId + " attachment: ", e);
s_logger.error("Unexpected exception while updating async job-" + jobId + " = [ " + jobUuid + " ] attachment: ", e);
txt.rollback();
}
}
@ -339,7 +348,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
}
if(s_logger.isDebugEnabled()) {
s_logger.debug("Sync job-" + job.getId() + " execution on object " + syncObjType + "." + syncObjId);
s_logger.debug("Sync job-" + job.getId() + " = [ " + job.getUuid() + " ] execution on object " + syncObjType + "." + syncObjId);
}
SyncQueueVO queue = null;
@ -363,7 +372,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
if (queue == null) {
throw new CloudRuntimeException("Unable to insert queue item into database, DB is full?");
} else {
throw new AsyncCommandQueued(queue, "job-" + job.getId() + " queued");
throw new AsyncCommandQueued(queue, "job-" + job.getId() + " = [ " + job.getUuid() + " ] queued");
}
}
@ -383,7 +392,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
if (caller.getType() == Account.ACCOUNT_TYPE_NORMAL) {
//regular user can see only jobs he owns
if (caller.getId() != jobOwner.getId()) {
throw new PermissionDeniedException("Account " + caller + " is not authorized to see job id=" + job.getId());
throw new PermissionDeniedException("Account " + caller + " is not authorized to see job-" + job.getId() + " = [ " + job.getUuid() + " ]");
}
} else if (caller.getType() == Account.ACCOUNT_TYPE_DOMAIN_ADMIN) {
_accountMgr.checkAccess(caller, null, true, jobOwner);
@ -396,8 +405,17 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
@Override @DB
public AsyncJobResult queryAsyncJobResult(long jobId) {
if(s_logger.isTraceEnabled()) {
s_logger.trace("Query async-job status, job-" + jobId);
AsyncJobVO job = _jobDao.findById(jobId);
String jobUuid = null;
if (job != null) {
jobUuid = job.getUuid();
if(s_logger.isTraceEnabled()) {
s_logger.trace("Query async-job status, job-" + jobId + " = [ " + jobUuid + " ]");
}
} else {
if(s_logger.isDebugEnabled()) {
s_logger.debug("Async job-" + jobId + " does not exist, invalid job id?");
}
}
Transaction txt = Transaction.currentTxn();
@ -405,7 +423,6 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
try {
txt.start();
AsyncJobVO job = _jobDao.findById(jobId);
if(job != null) {
jobResult.setCmdOriginator(job.getCmdOriginator());
jobResult.setJobStatus(job.getStatus());
@ -418,23 +435,23 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
job.getStatus() == AsyncJobResult.STATUS_FAILED) {
if(s_logger.isDebugEnabled()) {
s_logger.debug("Async job-" + jobId + " completed");
s_logger.debug("Async job-" + jobId + " = [ " + jobUuid + " ] completed");
}
} else {
job.setLastPolled(DateUtil.currentGMTTime());
_jobDao.update(jobId, job);
}
} else {
if(s_logger.isDebugEnabled()) {
s_logger.debug("Async job-" + jobId + " does not exist, invalid job id?");
}
jobResult.setJobStatus(AsyncJobResult.STATUS_FAILED);
jobResult.setResult("job-" + jobId + " does not exist");
}
txt.commit();
} catch(Exception e) {
s_logger.error("Unexpected exception while querying async job-" + jobId + " status: ", e);
if (jobUuid == null) {
s_logger.error("Unexpected exception while querying async job-" + jobId + " status: ", e);
} else {
s_logger.error("Unexpected exception while querying async job-" + jobId + " = [ " + jobUuid + " ] status: ", e);
}
jobResult.setJobStatus(AsyncJobResult.STATUS_FAILED);
jobResult.setResult("Exception: " + e.toString());
@ -471,17 +488,18 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
try {
JmxUtil.registerMBean("AsyncJobManager", "Active Job " + job.getId(), new AsyncJobMBeanImpl(job));
} catch(Exception e) {
s_logger.warn("Unable to register active job " + job.getId() + " to JMX monitoring due to exception " + ExceptionUtil.toString(e));
s_logger.warn("Unable to register active job [ " + job.getId() + " ] = [ " + job.getUuid() + " ] to JMX monitoring due to exception " + ExceptionUtil.toString(e));
}
BaseAsyncCmd cmdObj = null;
Transaction txn = Transaction.open(Transaction.CLOUD_DB);
try {
jobId = job.getId();
NDC.push("job-" + jobId);
String jobUuid = job.getUuid();
NDC.push("job-" + jobId + " = [ " + jobUuid + " ]");
if(s_logger.isDebugEnabled()) {
s_logger.debug("Executing " + job.getCmd() + " for job-" + jobId);
s_logger.debug("Executing " + job.getCmd() + " for job-" + jobId + " = [ " + jobUuid + " ]");
}
Class<?> cmdClass = Class.forName(job.getCmd());
@ -526,13 +544,13 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
}
if (s_logger.isDebugEnabled()) {
s_logger.debug("Done executing " + job.getCmd() + " for job-" + jobId);
s_logger.debug("Done executing " + job.getCmd() + " for job-" + job.getId() + " = [ " + jobUuid + " ]");
}
} catch(Throwable e) {
if (e instanceof AsyncCommandQueued) {
if (s_logger.isDebugEnabled()) {
s_logger.debug("job " + job.getCmd() + " for job-" + jobId + " was queued, processing the queue.");
s_logger.debug("job " + job.getCmd() + " for job-" + jobId + " = [ " + job.getUuid() + " ] was queued, processing the queue.");
}
checkQueue(((AsyncCommandQueued)e).getQueue().getId());
} else {
@ -571,7 +589,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
try {
JmxUtil.unregisterMBean("AsyncJobManager", "Active Job " + job.getId());
} catch(Exception e) {
s_logger.warn("Unable to unregister active job " + job.getId() + " from JMX monitoring");
s_logger.warn("Unable to unregister active job [ " + job.getId() + " ] = [ " + job.getUuid() + " ] from JMX monitoring");
}
txn.close();
@ -588,10 +606,12 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
}
private void executeQueueItem(SyncQueueItemVO item, boolean fromPreviousSession) {
long jobId = item.getContentId();
AsyncJobVO job = _jobDao.findById(item.getContentId());
if (job != null) {
String jobUuid = job.getUuid();
if(s_logger.isDebugEnabled()) {
s_logger.debug("Schedule queued job-" + job.getId());
s_logger.debug("Schedule queued job-" + jobId + " = [ " + jobUuid + " ]");
}
job.setFromPreviousSession(fromPreviousSession);
@ -603,7 +623,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
try {
scheduleExecution(job);
} catch(RejectedExecutionException e) {
s_logger.warn("Execution for job-" + job.getId() + " is rejected, return it to the queue for next turn");
s_logger.warn("Execution for job-" + jobId + " = [ " + jobUuid + " ] is rejected, return it to the queue for next turn");
_queueMgr.returnItem(item.getId());
}
@ -620,7 +640,7 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager,
public void releaseSyncSource(AsyncJobExecutor executor) {
if(executor.getSyncSource() != null) {
if(s_logger.isDebugEnabled()) {
s_logger.debug("Release sync source for job-" + executor.getJob().getId() + " sync source: "
s_logger.debug("Release sync source for job-" + executor.getJob().getId() + " = [ " + executor.getJob().getUuid() + " ] sync source: "
+ executor.getSyncSource().getContentType() + "-"
+ executor.getSyncSource().getContentId());
}

View File

@ -1869,8 +1869,8 @@ public class VolumeManagerImpl extends ManagerBase implements VolumeManager {
if (s_logger.isInfoEnabled()) {
s_logger.info("Trying to attaching volume " + volumeId
+ " to vm instance:" + vm.getId()
+ ", update async job-" + job.getId()
+ " progress status");
+ ", update async job-" + job.getId() + " = [ " + job.getUuid()
+ " ] progress status");
}
_asyncMgr.updateAsyncJobAttachment(job.getId(), "volume", volumeId);
@ -1976,8 +1976,8 @@ public class VolumeManagerImpl extends ManagerBase implements VolumeManager {
if (s_logger.isInfoEnabled()) {
s_logger.info("Trying to attaching volume " + volumeId
+ "to vm instance:" + vm.getId()
+ ", update async job-" + job.getId()
+ " progress status");
+ ", update async job-" + job.getId() + " = [ " + job.getUuid()
+ " ] progress status");
}
_asyncMgr.updateAsyncJobAttachment(job.getId(), "volume", volumeId);