From a4dc271253be5d6a504f644bf457cea38070857e Mon Sep 17 00:00:00 2001 From: Koushik Das Date: Fri, 4 Dec 2015 12:45:57 +0530 Subject: [PATCH] CLOUDSTACK-9105: Logging enhancement: Handle/reference to track API calls end to end in the MS logs Added logid to logging framework, now all API call logs can be tracked with this id end to end --- agent/conf/log4j-cloud.xml.in | 4 +- agent/src/com/cloud/agent/Agent.java | 7 + .../apache/cloudstack/context/LogContext.java | 302 ++++++++++++++++++ .../context/LogContextListener.java | 50 +++ client/tomcatconf/log4j-cloud.xml.in | 10 +- .../system/spring-core-system-context.xml | 1 + .../cloud/agent/manager/AgentManagerImpl.java | 4 + .../agent/manager/DirectAgentAttache.java | 13 + .../framework/jobs/dao/AsyncJobDaoImpl.java | 2 +- .../jobs/impl/AsyncJobManagerImpl.java | 25 +- systemvm/conf.dom0/log4j-cloud.xml.in | 2 +- usage/conf/log4j-cloud_usage.xml.in | 2 +- 12 files changed, 408 insertions(+), 14 deletions(-) create mode 100644 api/src/org/apache/cloudstack/context/LogContext.java create mode 100644 api/src/org/apache/cloudstack/context/LogContextListener.java diff --git a/agent/conf/log4j-cloud.xml.in b/agent/conf/log4j-cloud.xml.in index 12228017adb..6bc80f08473 100644 --- a/agent/conf/log4j-cloud.xml.in +++ b/agent/conf/log4j-cloud.xml.in @@ -34,7 +34,7 @@ under the License. - + @@ -47,7 +47,7 @@ under the License. - + diff --git a/agent/src/com/cloud/agent/Agent.java b/agent/src/com/cloud/agent/Agent.java index f39d0e78961..994e8224894 100644 --- a/agent/src/com/cloud/agent/Agent.java +++ b/agent/src/com/cloud/agent/Agent.java @@ -37,6 +37,7 @@ import javax.naming.ConfigurationException; import org.apache.cloudstack.managed.context.ManagedContextTimerTask; import org.apache.log4j.Logger; +import org.slf4j.MDC; import com.cloud.agent.api.AgentControlAnswer; import com.cloud.agent.api.AgentControlCommand; @@ -462,6 +463,9 @@ public class Agent implements HandlerFactory, IAgentControl { final Command cmd = cmds[i]; Answer answer; try { + if (cmd.getContextParam("logid") != null) { + MDC.put("logcontextid", cmd.getContextParam("logid")); + } if (s_logger.isDebugEnabled()) { if (!requestLogged) // ensures request is logged only once per method call { @@ -615,6 +619,9 @@ public class Agent implements HandlerFactory, IAgentControl { } else if (obj instanceof Request) { final Request req = (Request)obj; final Command command = req.getCommand(); + if (command.getContextParam("logid") != null) { + MDC.put("logcontextid", command.getContextParam("logid")); + } Answer answer = null; _inProgress.incrementAndGet(); try { diff --git a/api/src/org/apache/cloudstack/context/LogContext.java b/api/src/org/apache/cloudstack/context/LogContext.java new file mode 100644 index 00000000000..9bc9ed738ec --- /dev/null +++ b/api/src/org/apache/cloudstack/context/LogContext.java @@ -0,0 +1,302 @@ +// Licensed to the Apache Software Foundation (ASF) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The ASF licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. +package org.apache.cloudstack.context; + +import java.util.HashMap; +import java.util.Map; +import java.util.UUID; + +import org.apache.log4j.Logger; +import org.slf4j.MDC; + +import org.apache.cloudstack.managed.threadlocal.ManagedThreadLocal; + +import com.cloud.exception.CloudAuthenticationException; +import com.cloud.user.Account; +import com.cloud.user.User; +import com.cloud.utils.UuidUtils; +import com.cloud.utils.db.EntityManager; +import com.cloud.utils.exception.CloudRuntimeException; + +/** + * LogContext records information about the environment the API call is made. This + * class must be always be available in all CloudStack code. + */ +public class LogContext { + private static final Logger s_logger = Logger.getLogger(LogContext.class); + private static ManagedThreadLocal s_currentContext = new ManagedThreadLocal(); + + private String logContextId; + private Account account; + private long accountId; + private long startEventId = 0; + private String eventDescription; + private String eventDetails; + private String eventType; + private boolean isEventDisplayEnabled = true; // default to true unless specifically set + private User user; + private long userId; + private final Map context = new HashMap(); + + static EntityManager s_entityMgr; + + public static void init(EntityManager entityMgr) { + s_entityMgr = entityMgr; + } + + protected LogContext() { + } + + protected LogContext(long userId, long accountId, String logContextId) { + this.userId = userId; + this.accountId = accountId; + this.logContextId = logContextId; + } + + protected LogContext(User user, Account account, String logContextId) { + this.user = user; + userId = user.getId(); + this.account = account; + accountId = account.getId(); + this.logContextId = logContextId; + } + + public void putContextParameter(String key, String value) { + context.put(key, value); + } + + public String getContextParameter(String key) { + return context.get(key); + } + + public long getCallingUserId() { + return userId; + } + + public User getCallingUser() { + if (user == null) { + user = s_entityMgr.findById(User.class, userId); + } + return user; + } + + public String getLogContextId() { + return logContextId; + } + + public Account getCallingAccount() { + if (account == null) { + account = s_entityMgr.findById(Account.class, accountId); + } + return account; + } + + public static LogContext current() { + LogContext context = s_currentContext.get(); + if (context == null) { + context = registerSystemLogContextOnceOnly(); + } + return context; + } + + /** + * This method should only be called if you can propagate the context id + * from another LogContext. + * + * @param callingUser calling user + * @param callingAccount calling account + * @param contextId context id propagated from another call context + * @return LogContext + */ + public static LogContext register(User callingUser, Account callingAccount, String contextId) { + return register(callingUser, callingAccount, null, null, contextId); + } + + protected static LogContext register(User callingUser, Account callingAccount, Long userId, Long accountId, String contextId) { + LogContext callingContext = null; + if (userId == null || accountId == null) { + callingContext = new LogContext(callingUser, callingAccount, contextId); + } else { + callingContext = new LogContext(userId, accountId, contextId); + } + s_currentContext.set(callingContext); + MDC.put("logcontextid", UuidUtils.first(contextId)); + if (s_logger.isTraceEnabled()) { + s_logger.trace("Registered for log: " + callingContext); + } + return callingContext; + } + + public static LogContext registerPlaceHolderContext() { + LogContext context = new LogContext(0, 0, UUID.randomUUID().toString()); + s_currentContext.set(context); + return context; + } + + public static LogContext register(User callingUser, Account callingAccount) { + return register(callingUser, callingAccount, UUID.randomUUID().toString()); + } + + public static LogContext registerSystemLogContextOnceOnly() { + try { + LogContext context = s_currentContext.get(); + if (context == null) { + return register(null, null, User.UID_SYSTEM, Account.ACCOUNT_ID_SYSTEM, UUID.randomUUID().toString()); + } + assert context.getCallingUserId() == User.UID_SYSTEM : "You are calling a very specific method that registers a one time system context. This method is meant for background threads that does processing."; + return context; + } catch (Exception e) { + s_logger.error("Failed to register the system log context.", e); + throw new CloudRuntimeException("Failed to register system log context", e); + } + } + + public static LogContext register(String callingUserUuid, String callingAccountUuid) { + Account account = s_entityMgr.findByUuid(Account.class, callingAccountUuid); + if (account == null) { + throw new CloudAuthenticationException("The account is no longer current.").add(Account.class, callingAccountUuid); + } + + User user = s_entityMgr.findByUuid(User.class, callingUserUuid); + if (user == null) { + throw new CloudAuthenticationException("The user is no longer current.").add(User.class, callingUserUuid); + } + return register(user, account); + } + + public static LogContext register(long callingUserId, long callingAccountId) throws CloudAuthenticationException { + Account account = s_entityMgr.findById(Account.class, callingAccountId); + if (account == null) { + throw new CloudAuthenticationException("The account is no longer current.").add(Account.class, Long.toString(callingAccountId)); + } + User user = s_entityMgr.findById(User.class, callingUserId); + if (user == null) { + throw new CloudAuthenticationException("The user is no longer current.").add(User.class, Long.toString(callingUserId)); + } + return register(user, account); + } + + public static LogContext register(long callingUserId, long callingAccountId, String contextId) throws CloudAuthenticationException { + Account account = s_entityMgr.findById(Account.class, callingAccountId); + if (account == null) { + throw new CloudAuthenticationException("The account is no longer current.").add(Account.class, Long.toString(callingAccountId)); + } + User user = s_entityMgr.findById(User.class, callingUserId); + if (user == null) { + throw new CloudAuthenticationException("The user is no longer current.").add(User.class, Long.toString(callingUserId)); + } + return register(user, account, contextId); + } + + public static void unregister() { + LogContext context = s_currentContext.get(); + if (context != null) { + s_currentContext.remove(); + if (s_logger.isTraceEnabled()) { + s_logger.trace("Unregistered: " + context); + } + } + MDC.clear(); + } + + public void setStartEventId(long startEventId) { + this.startEventId = startEventId; + } + + public long getStartEventId() { + return startEventId; + } + + public long getCallingAccountId() { + return accountId; + } + + public String getCallingAccountUuid() { + return getCallingAccount().getUuid(); + } + + public String getCallingUserUuid() { + return getCallingUser().getUuid(); + } + + public void setEventDetails(String eventDetails) { + this.eventDetails = eventDetails; + } + + public String getEventDetails() { + return eventDetails; + } + + public String getEventType() { + return eventType; + } + + public void setEventType(String eventType) { + this.eventType = eventType; + } + + public String getEventDescription() { + return eventDescription; + } + + public void setEventDescription(String eventDescription) { + this.eventDescription = eventDescription; + } + + /** + * Whether to display the event to the end user. + * @return true - if the event is to be displayed to the end user, false otherwise. + */ + public boolean isEventDisplayEnabled() { + return isEventDisplayEnabled; + } + + public void setEventDisplayEnabled(boolean eventDisplayEnabled) { + isEventDisplayEnabled = eventDisplayEnabled; + } + + public Map getContextParameters() { + return context; + } + + public void putContextParameters(Map details) { + if (details == null) + return; + for (Map.Entry entry : details.entrySet()) { + putContextParameter(entry.getKey(), entry.getValue()); + } + } + + public static void setActionEventInfo(String eventType, String description) { + LogContext context = LogContext.current(); + if (context != null) { + context.setEventType(eventType); + context.setEventDescription(description); + } + } + + @Override + public String toString() { + return new StringBuilder("LogCtxt[acct=").append(getCallingAccountId()) + .append("; user=") + .append(getCallingUserId()) + .append("; id=") + .append(logContextId) + .append("]") + .toString(); + } +} \ No newline at end of file diff --git a/api/src/org/apache/cloudstack/context/LogContextListener.java b/api/src/org/apache/cloudstack/context/LogContextListener.java new file mode 100644 index 00000000000..6fc1beb0b87 --- /dev/null +++ b/api/src/org/apache/cloudstack/context/LogContextListener.java @@ -0,0 +1,50 @@ +// Licensed to the Apache Software Foundation (ASF) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The ASF licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. +package org.apache.cloudstack.context; + +import javax.annotation.PostConstruct; +import javax.inject.Inject; + +import org.apache.cloudstack.managed.context.ManagedContextListener; + +import com.cloud.utils.db.EntityManager; + +public class LogContextListener implements ManagedContextListener { + + @Inject + EntityManager entityMgr; + + @Override + public Object onEnterContext(boolean reentry) { + if (!reentry && LogContext.current() == null) { + LogContext.registerSystemLogContextOnceOnly(); + } + return null; + } + + @Override + public void onLeaveContext(Object unused, boolean reentry) { + if (!reentry) { + LogContext.unregister(); + } + } + + @PostConstruct + public void init() { + LogContext.init(entityMgr); + } +} diff --git a/client/tomcatconf/log4j-cloud.xml.in b/client/tomcatconf/log4j-cloud.xml.in index 0a12e7d06e4..125b00204ab 100755 --- a/client/tomcatconf/log4j-cloud.xml.in +++ b/client/tomcatconf/log4j-cloud.xml.in @@ -35,7 +35,7 @@ under the License. - + @@ -47,7 +47,7 @@ under the License. - + @@ -60,7 +60,7 @@ under the License. - + @@ -73,7 +73,7 @@ under the License. - + @@ -100,7 +100,7 @@ under the License. - + diff --git a/core/resources/META-INF/cloudstack/system/spring-core-system-context.xml b/core/resources/META-INF/cloudstack/system/spring-core-system-context.xml index a1950f6ab8e..96b627e9e25 100644 --- a/core/resources/META-INF/cloudstack/system/spring-core-system-context.xml +++ b/core/resources/META-INF/cloudstack/system/spring-core-system-context.xml @@ -39,6 +39,7 @@ If you put it after the TransactionContextListener, the thread will hold open a DB connection for the life of the thread --> + diff --git a/engine/orchestration/src/com/cloud/agent/manager/AgentManagerImpl.java b/engine/orchestration/src/com/cloud/agent/manager/AgentManagerImpl.java index 93409323146..78ce7a9ba99 100644 --- a/engine/orchestration/src/com/cloud/agent/manager/AgentManagerImpl.java +++ b/engine/orchestration/src/com/cloud/agent/manager/AgentManagerImpl.java @@ -45,6 +45,7 @@ import org.apache.cloudstack.framework.jobs.AsyncJobExecutionContext; import org.apache.cloudstack.managed.context.ManagedContextRunnable; import org.apache.cloudstack.utils.identity.ManagementServerNode; import org.apache.log4j.Logger; +import org.slf4j.MDC; import com.cloud.agent.AgentManager; import com.cloud.agent.Listener; @@ -389,6 +390,9 @@ public class AgentManagerImpl extends ManagerBase implements AgentManager, Handl cmd.setContextParam("job", "job-" + job.getId()); } } + if (MDC.get("logcontextid") != null && !MDC.get("logcontextid").isEmpty()) { + cmd.setContextParam("logid", MDC.get("logcontextid")); + } } /** diff --git a/engine/orchestration/src/com/cloud/agent/manager/DirectAgentAttache.java b/engine/orchestration/src/com/cloud/agent/manager/DirectAgentAttache.java index 52dfa9fdafd..be4d029a000 100644 --- a/engine/orchestration/src/com/cloud/agent/manager/DirectAgentAttache.java +++ b/engine/orchestration/src/com/cloud/agent/manager/DirectAgentAttache.java @@ -26,6 +26,7 @@ import java.util.concurrent.atomic.AtomicInteger; import org.apache.log4j.Logger; import org.apache.cloudstack.framework.config.ConfigKey; import org.apache.cloudstack.managed.context.ManagedContextRunnable; +import org.slf4j.MDC; import com.cloud.agent.api.Answer; import com.cloud.agent.api.Command; @@ -175,6 +176,10 @@ public class DirectAgentAttache extends AgentAttache { s_logger.warn("Unable to get current status on " + _id + "(" + _name + ")"); return; } + + if (cmd.getContextParam("logid") != null) { + MDC.put("logcontextid", cmd.getContextParam("logid")); + } if (s_logger.isDebugEnabled()) { s_logger.debug("Ping from " + _id + "(" + _name + ")"); } @@ -239,6 +244,10 @@ public class DirectAgentAttache extends AgentAttache { ArrayList answers = new ArrayList(cmds.length); for (int i = 0; i < cmds.length; i++) { Answer answer = null; + Command currentCmd = cmds[i]; + if (currentCmd.getContextParam("logid") != null) { + MDC.put("logcontextid", currentCmd.getContextParam("logid")); + } try { if (resource != null) { answer = resource.executeRequest(cmds[i]); @@ -297,6 +306,10 @@ public class DirectAgentAttache extends AgentAttache { ArrayList answers = new ArrayList(cmds.length); for (int i = 0; i < cmds.length; i++) { Answer answer = null; + Command currentCmd = cmds[i]; + if (currentCmd.getContextParam("logid") != null) { + MDC.put("logcontextid", currentCmd.getContextParam("logid")); + } try { if (resource != null) { answer = resource.executeRequest(cmds[i]); diff --git a/framework/jobs/src/org/apache/cloudstack/framework/jobs/dao/AsyncJobDaoImpl.java b/framework/jobs/src/org/apache/cloudstack/framework/jobs/dao/AsyncJobDaoImpl.java index 26288d53b23..0ccd4add19a 100644 --- a/framework/jobs/src/org/apache/cloudstack/framework/jobs/dao/AsyncJobDaoImpl.java +++ b/framework/jobs/src/org/apache/cloudstack/framework/jobs/dao/AsyncJobDaoImpl.java @@ -209,7 +209,7 @@ public class AsyncJobDaoImpl extends GenericDaoBase implements SearchCriteria initMsQuery = createSearchCriteria(); initMsQuery.addAnd("executingMsid", SearchCriteria.Op.NULL); initMsQuery.addAnd("initMsid", SearchCriteria.Op.EQ, msid); - msQuery.addOr("initMsId", SearchCriteria.Op.SC, initMsQuery); + msQuery.addOr("initMsid", SearchCriteria.Op.SC, initMsQuery); sc.addAnd("executingMsid", SearchCriteria.Op.SC, msQuery); diff --git a/framework/jobs/src/org/apache/cloudstack/framework/jobs/impl/AsyncJobManagerImpl.java b/framework/jobs/src/org/apache/cloudstack/framework/jobs/impl/AsyncJobManagerImpl.java index 1ea3c781016..3e1ed9c017a 100644 --- a/framework/jobs/src/org/apache/cloudstack/framework/jobs/impl/AsyncJobManagerImpl.java +++ b/framework/jobs/src/org/apache/cloudstack/framework/jobs/impl/AsyncJobManagerImpl.java @@ -35,7 +35,6 @@ import javax.naming.ConfigurationException; import org.apache.log4j.Logger; import org.apache.log4j.NDC; - import org.apache.cloudstack.api.ApiErrorCode; import org.apache.cloudstack.context.CallContext; import org.apache.cloudstack.framework.config.ConfigKey; @@ -55,6 +54,7 @@ import org.apache.cloudstack.jobs.JobInfo; import org.apache.cloudstack.jobs.JobInfo.Status; import org.apache.cloudstack.managed.context.ManagedContextRunnable; import org.apache.cloudstack.utils.identity.ManagementServerNode; +import org.slf4j.MDC; import com.cloud.cluster.ClusterManagerListener; import com.cloud.cluster.ManagementServerHost; @@ -486,10 +486,18 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager, if (CallContext.current() == null) CallContext.registerPlaceHolderContext(); - if (job.getRelated() != null && !job.getRelated().isEmpty()) - NDC.push("job-" + job.getRelated() + "/" + "job-" + job.getId()); - else + String related = job.getRelated(); + String logContext = job.getShortUuid(); + if (related != null && !related.isEmpty()) { + NDC.push("job-" + related + "/" + "job-" + job.getId()); + AsyncJob relatedJob = _jobDao.findByIdIncludingRemoved(Long.parseLong(related)); + if (relatedJob != null) { + logContext = relatedJob.getShortUuid(); + } + } else { NDC.push("job-" + job.getId()); + } + MDC.put("logcontextid", logContext); try { super.run(); } finally { @@ -516,6 +524,15 @@ public class AsyncJobManagerImpl extends ManagerBase implements AsyncJobManager, _jobMonitor.registerActiveTask(runNumber, job.getId()); AsyncJobExecutionContext.setCurrentExecutionContext(new AsyncJobExecutionContext(job)); + String related = job.getRelated(); + String logContext = job.getShortUuid(); + if (related != null && !related.isEmpty()) { + AsyncJob relatedJob = _jobDao.findByIdIncludingRemoved(Long.parseLong(related)); + if (relatedJob != null) { + logContext = relatedJob.getShortUuid(); + } + } + MDC.put("logcontextid", logContext); // execute the job if (s_logger.isDebugEnabled()) { diff --git a/systemvm/conf.dom0/log4j-cloud.xml.in b/systemvm/conf.dom0/log4j-cloud.xml.in index bc9f35e1286..0d78a950df9 100644 --- a/systemvm/conf.dom0/log4j-cloud.xml.in +++ b/systemvm/conf.dom0/log4j-cloud.xml.in @@ -34,7 +34,7 @@ under the License. - + diff --git a/usage/conf/log4j-cloud_usage.xml.in b/usage/conf/log4j-cloud_usage.xml.in index 2b639ecbbd6..1f5c7877f0d 100644 --- a/usage/conf/log4j-cloud_usage.xml.in +++ b/usage/conf/log4j-cloud_usage.xml.in @@ -48,7 +48,7 @@ under the License. - +