From fdc27ebaaaa596371600818435b8a96d471f1d9e Mon Sep 17 00:00:00 2001 From: Jonathan Cobb Date: Wed, 22 Jul 2020 09:07:34 -0400 Subject: [PATCH] add support for debug logging for a specific fqdn --- .../resources/stream/FilterHttpResource.java | 42 +++++++++++++++++-- 1 file changed, 38 insertions(+), 4 deletions(-) diff --git a/bubble-server/src/main/java/bubble/resources/stream/FilterHttpResource.java b/bubble-server/src/main/java/bubble/resources/stream/FilterHttpResource.java index f293d309..7c21911e 100644 --- a/bubble-server/src/main/java/bubble/resources/stream/FilterHttpResource.java +++ b/bubble-server/src/main/java/bubble/resources/stream/FilterHttpResource.java @@ -27,6 +27,7 @@ import lombok.Getter; import lombok.extern.slf4j.Slf4j; import org.cobbzilla.util.collection.ExpirationMap; import org.cobbzilla.util.http.HttpContentEncodingType; +import org.cobbzilla.util.io.FileUtil; import org.cobbzilla.wizard.cache.redis.RedisService; import org.glassfish.grizzly.http.server.Request; import org.glassfish.jersey.server.ContainerRequest; @@ -75,7 +76,17 @@ public class FilterHttpResource { @Autowired private BubbleConfiguration configuration; @Autowired private SelfNodeService selfNodeService; - private static final long ACTIVE_REQUEST_TIMEOUT = HOURS.toSeconds(4); + @Getter(lazy=true) private static final String debugFqdn = initDebugFqdn(); + private static String initDebugFqdn() { + try { + return FileUtil.toString(HOME_DIR+"/debug_fqdn").trim(); + } catch (Exception e) { + log.debug("initDebugFqdn: "+shortError(e)); + return "~debug_fqdn_disabled~"; // will never match any fqdn + } + } + + private static final long ACTIVE_REQUEST_TIMEOUT = HOURS.toSeconds(12); @Getter(lazy=true) private final RedisService activeRequestCache = redis.prefixNamespace(getClass().getSimpleName()+".requests"); @@ -101,6 +112,7 @@ public class FilterHttpResource { final RedisService cache = ruleEngine.getMatchersCache(); final String requestId = filterRequest.getRequestId(); + final boolean extraLog = filterRequest.getFqdn().contains(getDebugFqdn()); final String prefix = "getMatchersResponse("+requestId+"): "; final String cacheKey = filterRequest.cacheKey(); final String matchersJson = cache.get(cacheKey); @@ -108,11 +120,13 @@ public class FilterHttpResource { final FilterMatchersResponse cached = json(matchersJson, FilterMatchersResponse.class); cache.set(requestId, json(cached, COMPACT_MAPPER), EX, MATCHERS_CACHE_TIMEOUT); if (log.isTraceEnabled()) log.trace(prefix+"found cached response for cacheKey="+cacheKey+" and set for requestId "+requestId+": "+json(cached, COMPACT_MAPPER)); + else if (extraLog) log.error(prefix+"found cached response for cacheKey="+cacheKey+" and set for requestId "+requestId+": "+json(cached, COMPACT_MAPPER)); return cached.setRequestId(requestId); } final FilterMatchersResponse response = findMatchers(filterRequest, req, request); if (log.isTraceEnabled()) log.trace(prefix+"writing cache-miss to redis under keys "+cacheKey+" and "+requestId+": "+json(response, COMPACT_MAPPER)); + else if (extraLog) log.error(prefix+"writing cache-miss to redis under keys "+cacheKey+" and "+requestId+": "+json(response, COMPACT_MAPPER)); cache.set(cacheKey, json(response, COMPACT_MAPPER), EX, MATCHERS_CACHE_TIMEOUT); cache.set(requestId, json(response, COMPACT_MAPPER), EX, MATCHERS_CACHE_TIMEOUT); return response; @@ -192,17 +206,21 @@ public class FilterHttpResource { @Context ContainerRequest request, @PathParam("requestId") String requestId, FilterMatchersRequest filterRequest) { + boolean extraLog = requestId.contains(getDebugFqdn()); if (filterRequest == null || !filterRequest.hasRequestId() || empty(requestId) || !requestId.equals(filterRequest.getRequestId())) { if (log.isDebugEnabled()) log.debug("selectMatchers: no filterRequest, missing requestId, or mismatch, returning forbidden"); + else if (extraLog) log.error("selectMatchers: no filterRequest, missing requestId, or mismatch, returning forbidden"); return forbidden(); } validateMitmCall(req); final String prefix = "selectMatchers("+filterRequest.getRequestId()+"): "; if (log.isDebugEnabled()) log.debug(prefix+"starting for filterRequest="+json(filterRequest, COMPACT_MAPPER)); + else if (extraLog) log.error(prefix+"starting for filterRequest="+json(filterRequest, COMPACT_MAPPER)); if (!filterRequest.hasRemoteAddr()) { if (log.isDebugEnabled()) log.debug(prefix+"no VPN address provided, returning no matchers"); + else if (extraLog) log.error(prefix+"no VPN address provided, returning no matchers"); return ok(NO_MATCHERS); } @@ -210,6 +228,7 @@ public class FilterHttpResource { final Device device = deviceIdService.findDeviceByIp(vpnAddr); if (device == null) { if (log.isDebugEnabled()) log.debug(prefix+"device not found for IP "+vpnAddr+", returning no matchers"); + else if (extraLog) log.error(prefix+"device not found for IP "+vpnAddr+", returning no matchers"); return ok(NO_MATCHERS); } else if (log.isTraceEnabled()) { log.trace(prefix+"found device "+device.id()+" for IP "+vpnAddr); @@ -217,22 +236,25 @@ public class FilterHttpResource { filterRequest.setDevice(device.getUuid()); final FilterMatchersResponse response = getMatchersResponse(filterRequest, req, request); if (log.isDebugEnabled()) log.debug(prefix+"returning response: "+json(response, COMPACT_MAPPER)); + else if (extraLog) log.error(prefix+"returning response: "+json(response, COMPACT_MAPPER)); return ok(response); } private FilterMatchersResponse findMatchers(FilterMatchersRequest filterRequest, Request req, ContainerRequest request) { - final String requestId = filterRequest.getRequestId(); + boolean extraLog = requestId.contains(getDebugFqdn()); final String prefix = "findMatchers("+ requestId +"): "; final Device device = findDevice(filterRequest.getDevice()); if (device == null) { if (log.isDebugEnabled()) log.debug(prefix+"findDevice("+ filterRequest.getDevice() +") returned null, returning no matchers"); + else if (extraLog) log.error(prefix+"findDevice("+ filterRequest.getDevice() +") returned null, returning no matchers"); return NO_MATCHERS; } final String accountUuid = device.getAccount(); final Account caller = findCaller(accountUuid); if (caller == null) { if (log.isDebugEnabled()) log.debug(prefix+"account "+ accountUuid +" not found for device "+device.id()+", returning no matchers"); + else if (extraLog) log.error(prefix+"account "+ accountUuid +" not found for device "+device.id()+", returning no matchers"); return NO_MATCHERS; } @@ -250,12 +272,15 @@ public class FilterHttpResource { if (matcher.hasUserAgentRegex()) { if (!matcher.matchesUserAgent(filterRequest.getUserAgent())) { if (log.isDebugEnabled()) log.debug(prefix+"matcher "+matcher.getName()+" with pattern "+matcher.getUrlRegex()+" found match for uri: '"+uri+"', but user-agent pattern "+matcher.getUserAgentRegex()+" does not match user-agent="+filterRequest.getUserAgent()); + else if (extraLog) log.error(prefix+"matcher "+matcher.getName()+" with pattern "+matcher.getUrlRegex()+" found match for uri: '"+uri+"', but user-agent pattern "+matcher.getUserAgentRegex()+" does not match user-agent="+filterRequest.getUserAgent()); continue; } else { if (log.isDebugEnabled()) log.debug(prefix + "matcher " + matcher.getName() + " with pattern " + matcher.getUrlRegex() + " found match for uri: '" + uri + "' and for user-agent pattern "+matcher.getUserAgentRegex()+" for user-agent="+filterRequest.getUserAgent()); + else if (extraLog) log.error(prefix + "matcher " + matcher.getName() + " with pattern " + matcher.getUrlRegex() + " found match for uri: '" + uri + "' and for user-agent pattern "+matcher.getUserAgentRegex()+" for user-agent="+filterRequest.getUserAgent()); } } else { if (log.isDebugEnabled()) log.debug(prefix + "matcher " + matcher.getName() + " with pattern " + matcher.getUrlRegex() + " found match for uri: '" + uri + "'"); + else if (extraLog) log.error(prefix + "matcher " + matcher.getName() + " with pattern " + matcher.getUrlRegex() + " found match for uri: '" + uri + "'"); } final FilterMatchDecision matchResponse = ruleEngine.preprocess(filterRequest, req, request, caller, device, matcher); switch (matchResponse) { @@ -267,6 +292,7 @@ public class FilterHttpResource { } } else { if (log.isDebugEnabled()) log.debug(prefix+"matcher "+matcher.getName()+" with pattern "+matcher.getUrlRegex()+" did NOT match uri: '"+uri+"'"); + else if (extraLog) log.error(prefix+"matcher "+matcher.getName()+" with pattern "+matcher.getUrlRegex()+" did NOT match uri: '"+uri+"'"); } } } @@ -277,42 +303,50 @@ public class FilterHttpResource { .setMatchers(empty(retainMatchers) ? Collections.emptyList() : new ArrayList<>(retainMatchers.values())); if (log.isDebugEnabled()) log.debug(prefix+"preprocess decision for "+filterRequest.getUrl()+": "+response+", retainMatchers="+names(retainMatchers.values())); + else if (extraLog) log.error(prefix+"preprocess decision for "+filterRequest.getUrl()+": "+response+", retainMatchers="+names(retainMatchers.values())); return response; } private List getEnabledMatchers(String requestId, String accountUuid, String fqdn) { + boolean extraLog = fqdn.contains(getDebugFqdn()); final String prefix = "getEnabledMatchers("+requestId+"): "; List matchers = matcherDAO.findByAccountAndFqdnAndEnabledAndRequestCheck(accountUuid, fqdn); if (log.isTraceEnabled()) log.trace(prefix+"checking all enabled matchers for fqdn: "+json(matchers, COMPACT_MAPPER)); + else if (extraLog) log.error(prefix+"checking all enabled matchers for fqdn: "+json(matchers, COMPACT_MAPPER)); matchers = matchers.stream() .filter(m -> appDAO.findByAccountAndId(accountUuid, m.getApp()).enabled()).collect(Collectors.toList()); if (log.isTraceEnabled()) log.trace(prefix+"after removing disabled apps, enabled matchers for fqdn: "+json(matchers, COMPACT_MAPPER)); + else if (extraLog) log.error(prefix+"after removing disabled apps, enabled matchers for fqdn: "+json(matchers, COMPACT_MAPPER)); if (matchers.isEmpty()) return matchers; matchers = matchers.stream() .filter(m -> { final AppSite site = siteDAO.findByAccountAndAppAndId(accountUuid, m.getApp(), m.getSite()); if (site == null) { - log.warn(prefix+"site "+m.getSite()+" not found for matcher "+m.getName()+"/"+m.getUuid()); + if (log.isWarnEnabled()) log.warn(prefix+"site "+m.getSite()+" not found for matcher "+m.getName()+"/"+m.getUuid()); + else if (extraLog) log.error(prefix+"site "+m.getSite()+" not found for matcher "+m.getName()+"/"+m.getUuid()); return false; } return site.enabled(); }).collect(Collectors.toList()); if (log.isTraceEnabled()) log.trace(prefix+"after removing disabled sites, enabled matchers for fqdn: "+json(matchers, COMPACT_MAPPER)); + else if (extraLog) log.error(prefix+"after removing disabled sites, enabled matchers for fqdn: "+json(matchers, COMPACT_MAPPER)); if (matchers.isEmpty()) return matchers; matchers = matchers.stream() .filter(m -> { final AppRule rule = ruleDAO.findByAccountAndAppAndId(accountUuid, m.getApp(), m.getRule()); if (rule == null) { - log.warn(prefix+"rule "+m.getRule()+" not found for matcher "+m.getName()+"/"+m.getUuid()); + if (log.isWarnEnabled()) log.warn(prefix+"rule "+m.getRule()+" not found for matcher "+m.getName()+"/"+m.getUuid()); + else if (extraLog) log.error(prefix+"rule "+m.getRule()+" not found for matcher "+m.getName()+"/"+m.getUuid()); return false; } return rule.enabled(); }).collect(Collectors.toList()); if (log.isTraceEnabled()) log.trace(prefix+"after removing disabled rules, enabled matchers for fqdn: "+json(matchers, COMPACT_MAPPER)); else if (log.isDebugEnabled()) log.debug(prefix+"found "+matchers.size()+" candidate matchers: "+names(matchers)); + else if (extraLog) log.error(prefix+"found "+matchers.size()+" candidate matchers: "+names(matchers)); return matchers; }