Repository: camel Updated Branches: refs/heads/master ff6c512da -> aecd383d7
CAMEL-10462: Improve MDC Logging in DefaultCamelContext and RouteService Project: http://git-wip-us.apache.org/repos/asf/camel/repo Commit: http://git-wip-us.apache.org/repos/asf/camel/commit/aecd383d Tree: http://git-wip-us.apache.org/repos/asf/camel/tree/aecd383d Diff: http://git-wip-us.apache.org/repos/asf/camel/diff/aecd383d Branch: refs/heads/master Commit: aecd383d727ea5067d74ee56a1148c3eda15d62b Parents: ff6c512 Author: Quinn Stevenson <qu...@pronoia-solutions.com> Authored: Thu Nov 10 09:01:31 2016 -0700 Committer: Claus Ibsen <davscl...@apache.org> Committed: Fri Nov 11 15:14:02 2016 +0100 ---------------------------------------------------------------------- .../apache/camel/impl/DefaultCamelContext.java | 141 +++++++++---- .../org/apache/camel/impl/RouteService.java | 196 +++++++++++-------- 2 files changed, 219 insertions(+), 118 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/camel/blob/aecd383d/camel-core/src/main/java/org/apache/camel/impl/DefaultCamelContext.java ---------------------------------------------------------------------- diff --git a/camel-core/src/main/java/org/apache/camel/impl/DefaultCamelContext.java b/camel-core/src/main/java/org/apache/camel/impl/DefaultCamelContext.java index 3e023df..12295bf 100644 --- a/camel-core/src/main/java/org/apache/camel/impl/DefaultCamelContext.java +++ b/camel-core/src/main/java/org/apache/camel/impl/DefaultCamelContext.java @@ -172,6 +172,9 @@ import org.apache.camel.util.TimeUtils; import org.apache.camel.util.URISupport; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +import static org.apache.camel.impl.MDCUnitOfWork.MDC_CAMEL_CONTEXT_ID; /** * Represents the context used to configure routes and the policies to use. @@ -2896,56 +2899,87 @@ public class DefaultCamelContext extends ServiceSupport implements ModelCamelCon } } + @Override public void start() throws Exception { - vetoStated.set(false); - startDate = new Date(); - stopWatch.restart(); - log.info("Apache Camel " + getVersion() + " (CamelContext: " + getName() + ") is starting"); + try (MDCHelper mdcHelper = new MDCHelper()) { + vetoStated.set(false); + startDate = new Date(); + stopWatch.restart(); + log.info("Apache Camel " + getVersion() + " (CamelContext: " + getName() + ") is starting"); + + // Note: This is done on context start as we want to avoid doing it during object construction + // where we could be dealing with CDI proxied camel contexts which may never be started (CAMEL-9657) + // [TODO] Remove in 3.0 + Container.Instance.manage(this); + + doNotStartRoutesOnFirstStart = !firstStartDone && !isAutoStartup(); + + // if the context was configured with auto startup = false, and we are already started, + // then we may need to start the routes on the 2nd start call + if (firstStartDone && !isAutoStartup() && isStarted()) { + // invoke this logic to warm up the routes and if possible also start the routes + doStartOrResumeRoutes(routeServices, true, true, false, true); + } - // Note: This is done on context start as we want to avoid doing it during object construction - // where we could be dealing with CDI proxied camel contexts which may never be started (CAMEL-9657) - // [TODO] Remove in 3.0 - Container.Instance.manage(this); + // super will invoke doStart which will prepare internal services and start routes etc. + try { + firstStartDone = true; + super.start(); + } catch (VetoCamelContextStartException e) { + // mark we veto against starting Camel + vetoStated.set(true); + if (e.isRethrowException()) { + throw e; + } else { + log.info("CamelContext ({}) vetoed to not start due {}", getName(), e.getMessage()); + // swallow exception and change state of this camel context to stopped + stop(); + return; + } + } - doNotStartRoutesOnFirstStart = !firstStartDone && !isAutoStartup(); + stopWatch.stop(); + if (log.isInfoEnabled()) { + // count how many routes are actually started + int started = 0; + for (Route route : getRoutes()) { + if (getRouteStatus(route.getId()).isStarted()) { + started++; + } + } + log.info("Total " + getRoutes().size() + " routes, of which " + started + " are started."); + log.info("Apache Camel " + getVersion() + " (CamelContext: " + getName() + ") started in " + TimeUtils.printDuration(stopWatch.taken())); + } + EventHelper.notifyCamelContextStarted(this); + } + } - // if the context was configured with auto startup = false, and we are already started, - // then we may need to start the routes on the 2nd start call - if (firstStartDone && !isAutoStartup() && isStarted()) { - // invoke this logic to warm up the routes and if possible also start the routes - doStartOrResumeRoutes(routeServices, true, true, false, true); + @Override + public void stop() throws Exception { + try (MDCHelper mdcHelper = new MDCHelper()) { + super.stop(); } + } - // super will invoke doStart which will prepare internal services and start routes etc. - try { - firstStartDone = true; - super.start(); - } catch (VetoCamelContextStartException e) { - // mark we veto against starting Camel - vetoStated.set(true); - if (e.isRethrowException()) { - throw e; - } else { - log.info("CamelContext ({}) vetoed to not start due {}", getName(), e.getMessage()); - // swallow exception and change state of this camel context to stopped - stop(); - return; - } + @Override + public void suspend() throws Exception { + try (MDCHelper mdcHelper = new MDCHelper()) { + super.suspend(); } + } - stopWatch.stop(); - if (log.isInfoEnabled()) { - // count how many routes are actually started - int started = 0; - for (Route route : getRoutes()) { - if (getRouteStatus(route.getId()).isStarted()) { - started++; - } - } - log.info("Total " + getRoutes().size() + " routes, of which " + started + " are started."); - log.info("Apache Camel " + getVersion() + " (CamelContext: " + getName() + ") started in " + TimeUtils.printDuration(stopWatch.taken())); + @Override + public void resume() throws Exception { + try (MDCHelper mdcHelper = new MDCHelper()) { + super.resume(); + } + } + + @Override + public void shutdown() throws Exception { + try (MDCHelper mdcHelper = new MDCHelper()) { + super.shutdown(); } - EventHelper.notifyCamelContextStarted(this); } // Implementation methods @@ -4266,4 +4300,29 @@ public class DefaultCamelContext extends ServiceSupport implements ModelCamelCon public String toString() { return "CamelContext(" + getName() + ")"; } + + class MDCHelper implements AutoCloseable { + final Map<String, String> originalContextMap; + + MDCHelper() { + if (isUseMDCLogging()) { + originalContextMap = MDC.getCopyOfContextMap(); + MDC.put(MDC_CAMEL_CONTEXT_ID, getName()); + } else { + originalContextMap = null; + } + } + + @Override + public void close() { + if (isUseMDCLogging()) { + if (originalContextMap != null) { + MDC.setContextMap(originalContextMap); + } else { + MDC.clear(); + } + } + } + + } } http://git-wip-us.apache.org/repos/asf/camel/blob/aecd383d/camel-core/src/main/java/org/apache/camel/impl/RouteService.java ---------------------------------------------------------------------- diff --git a/camel-core/src/main/java/org/apache/camel/impl/RouteService.java b/camel-core/src/main/java/org/apache/camel/impl/RouteService.java index d0ff6d0..a39ffd8 100644 --- a/camel-core/src/main/java/org/apache/camel/impl/RouteService.java +++ b/camel-core/src/main/java/org/apache/camel/impl/RouteService.java @@ -48,6 +48,10 @@ import org.apache.camel.util.EventHelper; import org.apache.camel.util.ServiceHelper; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +import static org.apache.camel.impl.MDCUnitOfWork.MDC_CAMEL_CONTEXT_ID; +import static org.apache.camel.impl.MDCUnitOfWork.MDC_ROUTE_ID; /** * Represents the runtime objects for a given {@link RouteDefinition} so that it can be stopped independently @@ -157,41 +161,43 @@ public class RouteService extends ChildServiceSupport { if (warmUpDone.compareAndSet(false, true)) { for (Route route : routes) { - // warm up the route first - route.warmUp(); - - LOG.debug("Starting services on route: {}", route.getId()); - List<Service> services = route.getServices(); + try (MDCHelper mdcHelper = new MDCHelper(route.getId())) { + // warm up the route first + route.warmUp(); - // callback that we are staring these services - route.onStartingServices(services); + LOG.debug("Starting services on route: {}", route.getId()); + List<Service> services = route.getServices(); - // gather list of services to start as we need to start child services as well - Set<Service> list = new LinkedHashSet<Service>(); - for (Service service : services) { - list.addAll(ServiceHelper.getChildServices(service)); - } + // callback that we are staring these services + route.onStartingServices(services); - // split into consumers and child services as we need to start the consumers - // afterwards to avoid them being active while the others start - List<Service> childServices = new ArrayList<Service>(); - for (Service service : list) { - - // inject the route - if (service instanceof RouteAware) { - ((RouteAware) service).setRoute(route); + // gather list of services to start as we need to start child services as well + Set<Service> list = new LinkedHashSet<Service>(); + for (Service service : services) { + list.addAll(ServiceHelper.getChildServices(service)); } - if (service instanceof Consumer) { - inputs.put(route, (Consumer) service); - } else { - childServices.add(service); + // split into consumers and child services as we need to start the consumers + // afterwards to avoid them being active while the others start + List<Service> childServices = new ArrayList<Service>(); + for (Service service : list) { + + // inject the route + if (service instanceof RouteAware) { + ((RouteAware) service).setRoute(route); + } + + if (service instanceof Consumer) { + inputs.put(route, (Consumer) service); + } else { + childServices.add(service); + } } - } - startChildService(route, childServices); + startChildService(route, childServices); - // fire event - EventHelper.notifyRouteAdded(camelContext, route); + // fire event + EventHelper.notifyRouteAdded(camelContext, route); + } } // ensure lifecycle strategy is invoked which among others enlist the route in JMX @@ -208,18 +214,20 @@ public class RouteService extends ChildServiceSupport { warmUp(); for (Route route : routes) { - // start the route itself - ServiceHelper.startService(route); - - // invoke callbacks on route policy - if (route.getRouteContext().getRoutePolicyList() != null) { - for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { - routePolicy.onStart(route); + try (MDCHelper mdcHelper = new MDCHelper(route.getId())) { + // start the route itself + ServiceHelper.startService(route); + + // invoke callbacks on route policy + if (route.getRouteContext().getRoutePolicyList() != null) { + for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { + routePolicy.onStart(route); + } } - } - // fire event - EventHelper.notifyRouteStarted(camelContext, route); + // fire event + EventHelper.notifyRouteStarted(camelContext, route); + } } } @@ -236,29 +244,31 @@ public class RouteService extends ChildServiceSupport { } for (Route route : routes) { - LOG.debug("Stopping services on route: {}", route.getId()); + try (MDCHelper mdcHelper = new MDCHelper(route.getId())) { + LOG.debug("Stopping services on route: {}", route.getId()); - // gather list of services to stop as we need to start child services as well - Set<Service> services = gatherChildServices(route, true); + // gather list of services to stop as we need to start child services as well + Set<Service> services = gatherChildServices(route, true); - // stop services - stopChildService(route, services, isShutdownCamelContext); + // stop services + stopChildService(route, services, isShutdownCamelContext); - // stop the route itself - if (isShutdownCamelContext) { - ServiceHelper.stopAndShutdownServices(route); - } else { - ServiceHelper.stopServices(route); - } + // stop the route itself + if (isShutdownCamelContext) { + ServiceHelper.stopAndShutdownServices(route); + } else { + ServiceHelper.stopServices(route); + } - // invoke callbacks on route policy - if (route.getRouteContext().getRoutePolicyList() != null) { - for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { - routePolicy.onStop(route); + // invoke callbacks on route policy + if (route.getRouteContext().getRoutePolicyList() != null) { + for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { + routePolicy.onStop(route); + } } + // fire event + EventHelper.notifyRouteStopped(camelContext, route); } - // fire event - EventHelper.notifyRouteStopped(camelContext, route); } if (isRemovingRoutes()) { camelContext.removeRouteCollection(routes); @@ -270,28 +280,30 @@ public class RouteService extends ChildServiceSupport { @Override protected void doShutdown() throws Exception { for (Route route : routes) { - LOG.debug("Shutting down services on route: {}", route.getId()); + try (MDCHelper mdcHelper = new MDCHelper(route.getId())) { + LOG.debug("Shutting down services on route: {}", route.getId()); - // gather list of services to stop as we need to start child services as well - Set<Service> services = gatherChildServices(route, true); + // gather list of services to stop as we need to start child services as well + Set<Service> services = gatherChildServices(route, true); - // shutdown services - stopChildService(route, services, true); + // shutdown services + stopChildService(route, services, true); - // shutdown the route itself - ServiceHelper.stopAndShutdownServices(route); + // shutdown the route itself + ServiceHelper.stopAndShutdownServices(route); - // endpoints should only be stopped when Camel is shutting down - // see more details in the warmUp method - ServiceHelper.stopAndShutdownServices(route.getEndpoint()); - // invoke callbacks on route policy - if (route.getRouteContext().getRoutePolicyList() != null) { - for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { - routePolicy.onRemove(route); + // endpoints should only be stopped when Camel is shutting down + // see more details in the warmUp method + ServiceHelper.stopAndShutdownServices(route.getEndpoint()); + // invoke callbacks on route policy + if (route.getRouteContext().getRoutePolicyList() != null) { + for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { + routePolicy.onRemove(route); + } } + // fire event + EventHelper.notifyRouteRemoved(camelContext, route); } - // fire event - EventHelper.notifyRouteRemoved(camelContext, route); } // need to call onRoutesRemove when the CamelContext is shutting down or Route is shutdown @@ -318,9 +330,11 @@ public class RouteService extends ChildServiceSupport { // suspend and resume logic is provided by DefaultCamelContext which leverages ShutdownStrategy // to safely suspend and resume for (Route route : routes) { - if (route.getRouteContext().getRoutePolicyList() != null) { - for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { - routePolicy.onSuspend(route); + try (MDCHelper mdcHelper = new MDCHelper(route.getId())) { + if (route.getRouteContext().getRoutePolicyList() != null) { + for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { + routePolicy.onSuspend(route); + } } } } @@ -331,9 +345,11 @@ public class RouteService extends ChildServiceSupport { // suspend and resume logic is provided by DefaultCamelContext which leverages ShutdownStrategy // to safely suspend and resume for (Route route : routes) { - if (route.getRouteContext().getRoutePolicyList() != null) { - for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { - routePolicy.onResume(route); + try (MDCHelper mdcHelper = new MDCHelper(route.getId())) { + if (route.getRouteContext().getRoutePolicyList() != null) { + for (RoutePolicy routePolicy : route.getRouteContext().getRoutePolicyList()) { + routePolicy.onResume(route); + } } } } @@ -441,4 +457,30 @@ public class RouteService extends ChildServiceSupport { } } + class MDCHelper implements AutoCloseable { + final Map<String, String> originalContextMap; + + MDCHelper(String routeId) { + if (getCamelContext().isUseMDCLogging()) { + originalContextMap = MDC.getCopyOfContextMap(); + MDC.put(MDC_CAMEL_CONTEXT_ID, getCamelContext().getName()); + MDC.put(MDC_ROUTE_ID, routeId); + } else { + originalContextMap = null; + } + } + + @Override + public void close() { + if (getCamelContext().isUseMDCLogging()) { + if (originalContextMap != null) { + MDC.setContextMap(originalContextMap); + } else { + MDC.clear(); + } + } + } + + } + }
