Source code

001package ca.uhn.fhir.jpa.subscription.util;
002
003/*-
004 * #%L
005 * HAPI FHIR Subscription Server
006 * %%
007 * Copyright (C) 2014 - 2021 Smile CDR, Inc.
008 * %%
009 * Licensed under the Apache License, Version 2.0 (the "License");
010 * you may not use this file except in compliance with the License.
011 * You may obtain a copy of the License at
012 *
013 *      http://www.apache.org/licenses/LICENSE-2.0
014 *
015 * Unless required by applicable law or agreed to in writing, software
016 * distributed under the License is distributed on an "AS IS" BASIS,
017 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
018 * See the License for the specific language governing permissions and
019 * limitations under the License.
020 * #L%
021 */
022
023import ca.uhn.fhir.interceptor.api.Hook;
024import ca.uhn.fhir.interceptor.api.Interceptor;
025import ca.uhn.fhir.interceptor.api.Pointcut;
026import ca.uhn.fhir.jpa.searchparam.matcher.InMemoryMatchResult;
027import ca.uhn.fhir.jpa.subscription.model.CanonicalSubscriptionChannelType;
028import ca.uhn.fhir.jpa.subscription.model.ResourceDeliveryMessage;
029import ca.uhn.fhir.jpa.subscription.model.ResourceModifiedMessage;
030import ca.uhn.fhir.util.StopWatch;
031import org.slf4j.Logger;
032import org.slf4j.LoggerFactory;
033import org.slf4j.event.Level;
034
035import java.util.Date;
036import java.util.EnumMap;
037import java.util.function.Function;
038
039/**
040 * This interceptor can be used for troubleshooting subscription processing. It provides very
041 * detailed logging about the subscription processing pipeline.
042 * <p>
043 * This interceptor loges each step in the processing pipeline with a
044 * different event code, using the event codes itemized in
045 * {@link EventCodeEnum}. By default these are each placed in a logger with
046 * a different name (e.g. <code>ca.uhn.fhir.jpa.subscription.util.SubscriptionDebugLogInterceptor.SUBS20</code>
047 * in order to facilitate fine-grained logging controls where some codes are omitted and
048 * some are not.
049 * </p>
050 * <p>
051 * A custom log factory can also be passed in, in which case the logging
052 * creation may use another strategy.
053 * </p>
054 *
055 * @see EventCodeEnum
056 * @since 3.7.0
057 */
058@Interceptor
059public class SubscriptionDebugLogInterceptor {
060
061        private static final String SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK = "SubscriptionDebugLogInterceptor_precheck";
062        private final Level myLevel;
063        private final EnumMap<EventCodeEnum, Logger> myLoggers;
064
065        /**
066         * Constructor that logs at INFO level to the logger <code>ca.uhn.fhir.jpa.subscription.util.SubscriptionDebugLogInterceptor</code>
067         */
068        public SubscriptionDebugLogInterceptor() {
069                this(defaultLogFactory(), Level.INFO);
070        }
071
072        /**
073         * Constructor using a specific logger
074         */
075        public SubscriptionDebugLogInterceptor(Function<EventCodeEnum, Logger> theLogFactory, Level theLevel) {
076                myLevel = theLevel;
077                myLoggers = new EnumMap<>(EventCodeEnum.class);
078                for (EventCodeEnum next : EventCodeEnum.values()) {
079                        myLoggers.put(next, theLogFactory.apply(next));
080                }
081        }
082
083        @Hook(Pointcut.SUBSCRIPTION_RESOURCE_MODIFIED)
084        public void step10_resourceModified(ResourceModifiedMessage theMessage) {
085                String value = Long.toString(System.currentTimeMillis());
086                theMessage.setAttribute(SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK, value);
087                String resourceId = theMessage.getPayloadId();
088                if (resourceId == null) {
089                        // Delete operations have no payload
090                        resourceId = theMessage.getId();
091                }
092                log(EventCodeEnum.SUBS1, "Resource {} was submitted to the processing pipeline (op={})", resourceId, theMessage.getOperationType());
093        }
094
095        /*
096         * These methods are numbered in the order that an individual
097         * resource would go through them, for clarity and ease of
098         * tracing when debugging and poring over logs.
099         *
100         * I don't know if this numbering scheme makes sense.. I'm incrementing
101         * by 10 for each step in the normal delivery pipeline, leaving lots of
102         * gaps to add things if we ever need them.
103         */
104
105        @Hook(Pointcut.SUBSCRIPTION_BEFORE_PERSISTED_RESOURCE_CHECKED)
106        public void step20_beforeChecked(ResourceModifiedMessage theMessage) {
107                log(EventCodeEnum.SUBS2, "Checking resource {} (op={}) for matching subscriptions", theMessage.getPayloadId(), theMessage.getOperationType());
108        }
109
110        @Hook(Pointcut.SUBSCRIPTION_RESOURCE_MATCHED)
111        public void step30_subscriptionMatched(ResourceDeliveryMessage theMessage, InMemoryMatchResult theResult) {
112                log(EventCodeEnum.SUBS3, "Resource {} matched by subscription {} (memory match={})", theMessage.getPayloadId(), theMessage.getSubscription().getIdElementString(), theResult.isInMemory());
113        }
114
115        @Hook(Pointcut.SUBSCRIPTION_RESOURCE_DID_NOT_MATCH_ANY_SUBSCRIPTIONS)
116        public void step35_subscriptionNotMatched(ResourceModifiedMessage theMessage) {
117                log(EventCodeEnum.SUBS4, "Resource {} did not match any subscriptions", theMessage.getPayloadId());
118        }
119
120        @Hook(Pointcut.SUBSCRIPTION_BEFORE_DELIVERY)
121        public void step40_beforeDelivery(ResourceDeliveryMessage theMessage) {
122                log(EventCodeEnum.SUBS5, "Delivering resource {} for subscription {} to channel of type {} to endpoint {}", theMessage.getPayloadId(), theMessage.getSubscription().getIdElementString(), theMessage.getSubscription().getChannelType(), theMessage.getSubscription().getEndpointUrl());
123        }
124
125        @Hook(Pointcut.SUBSCRIPTION_AFTER_DELIVERY_FAILED)
126        public void step45_deliveryFailed(ResourceDeliveryMessage theMessage, Exception theFailure) {
127                String payloadId = null;
128                String subscriptionId = null;
129                CanonicalSubscriptionChannelType channelType = null;
130                String failureString = null;
131                if (theMessage != null) {
132                        payloadId = theMessage.getPayloadId();
133                        if (theMessage.getSubscription() != null) {
134                                subscriptionId = theMessage.getSubscription().getIdElementString();
135                                channelType = theMessage.getSubscription().getChannelType();
136                        }
137                }
138                if (theFailure != null) {
139                        failureString = theFailure.toString();
140                }
141                log(EventCodeEnum.SUBS6, "Delivery of resource {} for subscription {} to channel of type {} - Failure: {}", payloadId, subscriptionId, channelType, failureString);
142        }
143
144        @Hook(Pointcut.SUBSCRIPTION_AFTER_DELIVERY)
145        public void step50_afterDelivery(ResourceDeliveryMessage theMessage) {
146                String processingTime = theMessage
147                        .getAttribute(SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK)
148                        .map(Long::parseLong)
149                        .map(Date::new)
150                        .map(start -> new StopWatch(start).toString())
151                        .orElse("(unknown)");
152
153                log(EventCodeEnum.SUBS7, "Finished delivery of resource {} for subscription {} to channel of type {} - Total processing time: {}", theMessage.getPayloadId(), theMessage.getSubscription().getIdElementString(), theMessage.getSubscription().getChannelType(), processingTime);
154        }
155
156        protected void log(EventCodeEnum theEventCode, String theMessage, Object... theArguments) {
157                Logger logger = myLoggers.get(theEventCode);
158                if (logger != null) {
159                        switch (myLevel) {
160                                case ERROR:
161                                        logger.error(theMessage, theArguments);
162                                        break;
163                                case WARN:
164                                        logger.warn(theMessage, theArguments);
165                                        break;
166                                case INFO:
167                                        logger.info(theMessage, theArguments);
168                                        break;
169                                case DEBUG:
170                                        logger.debug(theMessage, theArguments);
171                                        break;
172                                case TRACE:
173                                        logger.trace(theMessage, theArguments);
174                                        break;
175                        }
176                }
177        }
178
179        public enum EventCodeEnum {
180                /**
181                 * A new/updated resource has been submitted to the processing pipeline and is about
182                 * to be placed on the matchign queue.
183                 */
184                SUBS1,
185                /**
186                 * A resources has been dequeued from the matching queue and is about to be checked
187                 * for any matching subscriptions.
188                 */
189                SUBS2,
190                /**
191                 * The resource has matched a subscription (logged once for each matching subscription)
192                 * and is about to be queued for delivery.
193                 */
194                SUBS3,
195                /**
196                 * The resource did not match any subscriptions and processing is complete.
197                 */
198                SUBS4,
199                /**
200                 * The resource has been dequeued from the delivery queue and is about to be
201                 * delivered.
202                 */
203                SUBS5,
204                /**
205                 * Delivery failed
206                 */
207                SUBS6,
208                /**
209                 * Delivery is now complete and processing is finished.
210                 */
211                SUBS7
212        }
213
214
215        private static Function<EventCodeEnum, Logger> defaultLogFactory() {
216                return code -> LoggerFactory.getLogger(SubscriptionDebugLogInterceptor.class.getName() + "." + code.name());
217        }
218
219}