diff --git a/server/src/com/cloud/async/AsyncJobManagerImpl.java b/server/src/com/cloud/async/AsyncJobManagerImpl.java index 37b97278bad..d3efdeec3f8 100644 --- a/server/src/com/cloud/async/AsyncJobManagerImpl.java +++ b/server/src/com/cloud/async/AsyncJobManagerImpl.java @@ -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()); } diff --git a/server/src/com/cloud/storage/VolumeManagerImpl.java b/server/src/com/cloud/storage/VolumeManagerImpl.java index c2678fc6f9e..16185744a33 100644 --- a/server/src/com/cloud/storage/VolumeManagerImpl.java +++ b/server/src/com/cloud/storage/VolumeManagerImpl.java @@ -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);