From cdc8eb2849b09dbb7984593b422aa692dfb79af8 Mon Sep 17 00:00:00 2001 From: egernug Date: Tue, 11 Jun 2019 14:46:04 +0000 Subject: [PATCH] Logging improvements Change-Id: Ic0ad656b9bb041f65a37103680e3599c8ca1f98e Issue-ID: DMAAP-1203 Signed-off-by: egernug --- .../org/onap/dmaap/datarouter/node/Delivery.java | 8 +- .../onap/dmaap/datarouter/node/DeliveryQueue.java | 156 ++++++++++----------- datarouter-node/src/main/resources/logback.xml | 2 +- 3 files changed, 83 insertions(+), 83 deletions(-) diff --git a/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/Delivery.java b/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/Delivery.java index df73c1e9..9af8ed77 100644 --- a/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/Delivery.java +++ b/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/Delivery.java @@ -134,7 +134,7 @@ public class Delivery { cur = spoolfile.getUsableSpace(); if (cur >= stop) { logger.info("NODE0503 Free disk space at or above yellow threshold. current=" + cur + YELLOW + stop - + TOTAL + tspace); + + TOTAL + tspace); return; } logger.warn( @@ -195,7 +195,7 @@ public class Delivery { cleardirs(); while (curthreads < threads) { curthreads++; - (new Thread("Delivery Thread") { + (new Thread("del-thread-" + curthreads) { @Override public void run() { dodelivery(); @@ -249,7 +249,7 @@ public class Delivery { for (DelItem item : items) { long amount = dqs.get(item.getSpool()).cancelTask(item.getPublishId()); logger.info("NODE0502 Attempting to discard " + item.getSpool() + "/" + item.getPublishId() - + " to free up disk"); + + " to free up disk"); if (amount > 0) { cur += amount; if (cur >= stop) { @@ -302,7 +302,7 @@ public class Delivery { } DelItem delItem = (DelItem) object; return Objects.equals(pubid, delItem.pubid) - && Objects.equals(getSpool(), delItem.getSpool()); + && Objects.equals(getSpool(), delItem.getSpool()); } @Override diff --git a/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/DeliveryQueue.java b/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/DeliveryQueue.java index 8cdafd6f..0ba9ecfd 100644 --- a/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/DeliveryQueue.java +++ b/datarouter-node/src/main/java/org/onap/dmaap/datarouter/node/DeliveryQueue.java @@ -26,41 +26,47 @@ package org.onap.dmaap.datarouter.node; import com.att.eelf.configuration.EELFLogger; import com.att.eelf.configuration.EELFManager; -import java.io.File; -import java.util.Arrays; -import java.util.Hashtable; -import java.util.Vector; +import java.io.*; +import java.util.*; import org.jetbrains.annotations.Nullable; /** * Mechanism for monitoring and controlling delivery of files to a destination. - * - *

The DeliveryQueue class maintains lists of DeliveryTasks for a single destination (a subscription or another data - * router node) and assigns delivery threads to try to deliver them. It also maintains a delivery status that causes it - * to back off on delivery attempts after a failure. - * - *

If the most recent delivery result was a failure, then no more attempts will be made for a period of time. - * Initially, and on the first failure following a success, this delay will be DeliveryQueueHelper.getInitFailureTimer() - * (milliseconds). If, after this delay, additional failures occur, each failure will multiply the delay by - * DeliveryQueueHelper.getFailureBackoff() up to a maximum delay specified by DeliveryQueueHelper.getMaxFailureTimer(). - * Note that this behavior applies to the delivery queue as a whole and not to individual files in the queue. If - * multiple files are being delivered and one fails, the delay will be started. If a second delivery fails while the - * delay was active, it will not change the delay or change the duration of any subsequent delay. If, however, it - * succeeds, it will cancel the delay. - * - *

The queue maintains 3 collections of files to deliver: A to do list of files that will be attempted, a working - * set of files that are being attempted, and a retry set of files that were attempted and failed. Whenever the to do - * list is empty and needs to be refilled, a scan of the spool directory is made and the file names sorted. Any files - * in the working set are ignored. If a DeliveryTask for the file is in the retry set, then that delivery task is placed - * on the to do list. Otherwise, a new DeliveryTask for the file is created and placed on the to do list. If, when a - * DeliveryTask is about to be removed from the to do list, its age exceeds DeliveryQueueHelper.getExpirationTimer(), - * then it is instead marked as expired. - * - *

A delivery queue also maintains a skip flag. This flag is true if the failure timer is active or if no files are - * found in a directory scan. + *

+ * The DeliveryQueue class maintains lists of DeliveryTasks for a single + * destination (a subscription or another data router node) and assigns + * delivery threads to try to deliver them. It also maintains a delivery + * status that causes it to back off on delivery attempts after a failure. + *

+ * If the most recent delivery result was a failure, then no more attempts + * will be made for a period of time. Initially, and on the first failure + * following a success, this delay will be DeliveryQueueHelper.getInitFailureTimer() (milliseconds). + * If, after this delay, additional failures occur, each failure will + * multiply the delay by DeliveryQueueHelper.getFailureBackoff() up to a + * maximum delay specified by DeliveryQueueHelper.getMaxFailureTimer(). + * Note that this behavior applies to the delivery queue as a whole and not + * to individual files in the queue. If multiple files are being + * delivered and one fails, the delay will be started. If a second + * delivery fails while the delay was active, it will not change the delay + * or change the duration of any subsequent delay. + * If, however, it succeeds, it will cancel the delay. + *

+ * The queue maintains 3 collections of files to deliver: A todo list of + * files that will be attempted, a working set of files that are being + * attempted, and a retry set of files that were attempted and failed. + * Whenever the todo list is empty and needs to be refilled, a scan of the + * spool directory is made and the file names sorted. Any files in the working set are ignored. + * If a DeliveryTask for the file is in the retry set, then that delivery + * task is placed on the todo list. Otherwise, a new DeliveryTask for the + * file is created and placed on the todo list. + * If, when a DeliveryTask is about to be removed from the todo list, its + * age exceeds DeliveryQueueHelper.getExpirationTimer(), then it is instead + * marked as expired. + *

+ * A delivery queue also maintains a skip flag. This flag is true if the + * failure timer is active or if no files are found in a directory scan. */ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { - private static EELFLogger logger = EELFManager.getInstance().getLogger(DeliveryQueue.class); private DeliveryQueueHelper deliveryQueueHelper; private DestInfo destinationInfo; @@ -73,16 +79,6 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { private File dir; private Vector todo = new Vector<>(); - /** - * Create a delivery queue for a given destination info. - */ - DeliveryQueue(DeliveryQueueHelper deliveryQueueHelper, DestInfo destinationInfo) { - this.deliveryQueueHelper = deliveryQueueHelper; - this.destinationInfo = destinationInfo; - dir = new File(destinationInfo.getSpool()); - dir.mkdirs(); - } - /** * Try to cancel a delivery task. * @@ -111,8 +107,7 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { if (dt.isCleaned()) { return (0); } - StatusLog.logExp(dt.getPublishId(), dt.getFeedId(), dt.getSubId(), dt.getURL(), dt.getMethod(), dt.getCType(), - dt.getLength(), "diskFull", dt.getAttempts()); + StatusLog.logExp(dt.getPublishId(), dt.getFeedId(), dt.getSubId(), dt.getURL(), dt.getMethod(), dt.getCType(), dt.getLength(), "diskFull", dt.getAttempts()); dt.clean(); return (dt.getLength()); } @@ -122,6 +117,7 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { */ private synchronized void markSuccess(DeliveryTask task) { working.remove(task.getPublishId()); + logger.debug(task.getPublishId() + " marked as success."); task.clean(); failed = false; failduration = 0; @@ -131,6 +127,7 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { * Mark that a delivery task has expired. */ private synchronized void markExpired(DeliveryTask task) { + logger.debug(task.getPublishId() + " marked as expired."); task.clean(); } @@ -139,6 +136,7 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { */ private synchronized void markFailNoRetry(DeliveryTask task) { working.remove(task.getPublishId()); + logger.debug(task.getPublishId() + " marked as failed permanently"); task.clean(); failed = false; failduration = 0; @@ -150,7 +148,7 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { if (failduration == 0) { if (destinationInfo.isPrivilegedSubscriber()) { failduration = deliveryQueueHelper.getWaitForFileProcessFailureTimer(); - } else { + } else{ failduration = deliveryQueueHelper.getInitFailureTimer(); } } @@ -168,6 +166,7 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { */ private synchronized void markRedirect(DeliveryTask task) { working.remove(task.getPublishId()); + logger.debug(task.getPublishId() + " marked as redirected."); retry.put(task.getPublishId(), task); } @@ -176,6 +175,7 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { */ private synchronized void markFailWithRetry(DeliveryTask task) { working.remove(task.getPublishId()); + logger.debug(task.getPublishId() + " marked as temporarily failed."); retry.put(task.getPublishId(), task); fdupdate(); } @@ -219,98 +219,97 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { return dt; } return null; + } } /** - * Update the destination info for this delivery queue. + * Create a delivery queue for a given destination info + */ + DeliveryQueue(DeliveryQueueHelper deliveryQueueHelper, DestInfo destinationInfo) { + this.deliveryQueueHelper = deliveryQueueHelper; + this.destinationInfo = destinationInfo; + dir = new File(destinationInfo.getSpool()); + dir.mkdirs(); + } + + /** + * Update the destination info for this delivery queue */ public void config(DestInfo destinationInfo) { this.destinationInfo = destinationInfo; } /** - * Get the dest info. + * Get the dest info */ public DestInfo getDestinationInfo() { return (destinationInfo); } /** - * Get the config manager. + * Get the config manager */ public DeliveryQueueHelper getConfig() { return (deliveryQueueHelper); } /** - * Exceptional condition occurred during delivery. + * Exceptional condition occurred during delivery */ public void reportDeliveryExtra(DeliveryTask task, long sent) { StatusLog.logDelExtra(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getLength(), sent); } /** - * Message too old to deliver. + * Message too old to deliver */ void reportExpiry(DeliveryTask task) { - StatusLog.logExp(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), "retriesExhausted", task.getAttempts()); + StatusLog.logExp(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), "retriesExhausted", task.getAttempts()); markExpired(task); } /** - * Completed a delivery attempt. + * Completed a delivery attempt */ public void reportStatus(DeliveryTask task, int status, String xpubid, String location) { if (status < 300) { - StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, xpubid); + StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, xpubid); if (destinationInfo.isPrivilegedSubscriber()) { - task.setResumeTime( - System.currentTimeMillis() + deliveryQueueHelper.getWaitForFileProcessFailureTimer()); + task.setResumeTime(System.currentTimeMillis() + deliveryQueueHelper.getWaitForFileProcessFailureTimer()); markFailWithRetry(task); } else { markSuccess(task); } } else if (status < 400 && deliveryQueueHelper.isFollowRedirects()) { - StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, location); + StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, location); if (deliveryQueueHelper.handleRedirection(destinationInfo, location, task.getFileId())) { markRedirect(task); } else { - StatusLog - .logExp(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), "notRetryable", task.getAttempts()); + StatusLog.logExp(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), "notRetryable", task.getAttempts()); markFailNoRetry(task); } - } else if (status < 500 && status != 429) { - // Status 429 is the standard response for Too Many Requests and indicates - // that a file needs to be delivered again at a later time. - StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, location); - StatusLog.logExp(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), "notRetryable", task.getAttempts()); + } else if (status < 500 && status != 429) { // Status 429 is the standard response for Too Many Requests and indicates that a file needs to be delivered again at a later time. + StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, location); + StatusLog.logExp(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), "notRetryable", task.getAttempts()); markFailNoRetry(task); } else { - StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, location); + StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), destinationInfo.getAuthUser(), status, location); markFailWithRetry(task); } } /** - * Delivery failed by reason of an exception. + * Delivery failed by reason of an exception */ public void reportException(DeliveryTask task, Exception exception) { - StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), - task.getCType(), task.getLength(), destinationInfo.getAuthUser(), -1, exception.toString()); + StatusLog.logDel(task.getPublishId(), task.getFeedId(), task.getSubId(), task.getURL(), task.getMethod(), task.getCType(), task.getLength(), destinationInfo.getAuthUser(), -1, exception.toString()); deliveryQueueHelper.handleUnreachable(destinationInfo); markFailWithRetry(task); } /** - * Get the feed ID for a subscription. + * Get the feed ID for a subscription * * @param subid The subscription ID * @return The feed ID @@ -320,20 +319,22 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { } /** - * Get the URL to deliver a message to given the file ID. + * Get the URL to deliver a message to given the file ID */ public String getDestURL(String fileid) { return (deliveryQueueHelper.getDestURL(destinationInfo, fileid)); } /** - * Deliver files until there's a failure or there are no more files to deliver. + * Deliver files until there's a failure or there are no more + * files to deliver */ public void run() { DeliveryTask task; long endtime = System.currentTimeMillis() + deliveryQueueHelper.getFairTimeLimit(); int filestogo = deliveryQueueHelper.getFairFileLimit(); while ((task = getNext()) != null) { + logger.debug("Processing file: " + task.getPublishId()); task.run(); if (--filestogo <= 0 || System.currentTimeMillis() > endtime) { break; @@ -342,21 +343,21 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { } /** - * Is there no work to do for this queue right now. + * Is there no work to do for this queue right now? */ synchronized boolean isSkipSet() { return (peekNext() == null); } /** - * Reset the retry timer. + * Reset the retry timer */ void resetQueue() { resumetime = System.currentTimeMillis(); } /** - * Get task if in queue and mark as success. + * Get task if in queue and mark as success */ boolean markTaskSuccess(String pubId) { DeliveryTask task = working.get(pubId); @@ -374,7 +375,6 @@ public class DeliveryQueue implements Runnable, DeliveryTaskHelper { } return false; } - private void scanForNextTask(String[] files) { for (String fname : files) { String pubId = getPubId(fname); diff --git a/datarouter-node/src/main/resources/logback.xml b/datarouter-node/src/main/resources/logback.xml index 2ce2050c..cc2ff4e2 100644 --- a/datarouter-node/src/main/resources/logback.xml +++ b/datarouter-node/src/main/resources/logback.xml @@ -365,7 +365,7 @@ - + -- 2.16.6