
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}