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

@@ -34,7 +34,7 @@ under the License.
         <param name="ActiveFileName" value="@AGENTLOG@"/>
       </rollingPolicy>
       <layout class="org.apache.log4j.EnhancedPatternLayout">
-         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{3}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{3}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
    
@@ -47,7 +47,7 @@ under the License.
       <param name="Threshold" value="INFO"/>
 
       <layout class="org.apache.log4j.PatternLayout">
-         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
 

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 {

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<LogContext> s_currentContext = new ManagedThreadLocal<LogContext>();
+
+    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<String, String> context = new HashMap<String, String>();
+
+    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<String, String> getContextParameters() {
+        return context;
+    }
+
+    public void putContextParameters(Map<String, String> details) {
+        if (details == null)
+            return;
+        for (Map.Entry<String, String> 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();
+    }
+}

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<Object> {
+
+    @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);
+    }
+}

client/tomcatconf/log4j-cloud.xml.in

@@ -35,7 +35,7 @@ under the License.
         <param name="ActiveFileName" value="@MSLOG@"/>
       </rollingPolicy>
       <layout class="org.apache.log4j.EnhancedPatternLayout">
-         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{1.}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{1.}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
    
@@ -47,7 +47,7 @@ under the License.
         <param name="ActiveFileName" value="@APISERVERLOG@"/>
       </rollingPolicy>
       <layout class="org.apache.log4j.EnhancedPatternLayout">
-         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{1.}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{1.}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
 
@@ -60,7 +60,7 @@ under the License.
       <param name="SyslogHost" value="localhost"/>
       <param name="Facility" value="LOCAL6"/>
       <layout class="org.apache.log4j.PatternLayout">
-         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
 
@@ -73,7 +73,7 @@ under the License.
       <param name="SyslogHosts" value=""/>
       <param name="Facility" value="LOCAL6"/>
       <layout class="org.apache.log4j.PatternLayout">
-         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
 
@@ -100,7 +100,7 @@ under the License.
       <param name="Target" value="System.out"/>
       <param name="Threshold" value="INFO"/>
       <layout class="org.apache.log4j.EnhancedPatternLayout">
-         <param name="ConversionPattern" value="%-5p [%c{1.}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%-5p [%c{1.}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
 

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 -->
             <bean class="org.apache.cloudstack.context.CallContextListener" />
+            <bean class="org.apache.cloudstack.context.LogContextListener" />
             <bean class="com.cloud.utils.db.TransactionContextListener" />
         </list>
     </property>

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"));
+        }
     }
 
     /**

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<Answer> answers = new ArrayList<Answer>(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<Answer> answers = new ArrayList<Answer>(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]);

framework/jobs/src/org/apache/cloudstack/framework/jobs/dao/AsyncJobDaoImpl.java

@@ -209,7 +209,7 @@ public class AsyncJobDaoImpl extends GenericDaoBase<AsyncJobVO, Long> implements
         SearchCriteria<AsyncJobVO> 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);
 

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()) {

systemvm/conf.dom0/log4j-cloud.xml.in

@@ -34,7 +34,7 @@ under the License.
         <param name="ActiveFileName" value="@CPLOG@"/>
       </rollingPolicy>
       <layout class="org.apache.log4j.EnhancedPatternLayout">
-         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{3}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c{3}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>
    

usage/conf/log4j-cloud_usage.xml.in

@@ -48,7 +48,7 @@ under the License.
       </rollingPolicy>
 
       <layout class="org.apache.log4j.EnhancedPatternLayout">
-         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) %m%n"/>
+         <param name="ConversionPattern" value="%-5p [%c{3}] (%t:%x) (logid:%X{logcontextid}) %m%n"/>
       </layout>
    </appender>