Source code

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