Uploaded image for project: 'Flume'
  1. Flume
  2. FLUME-2385

Flume spans log file with "Spooling Directory Source runner has shutdown" messages at INFO level

    Details

    • Type: Improvement
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 1.4.0
    • Fix Version/s: 1.6.0
    • Component/s: None
    • Labels:
      None

      Description

      When I start an agent with the following config, the spooling directory source emits "14/05/14 22:36:12 INFO source.SpoolDirectorySource: Spooling Directory Source runner has shutdown." messages twice a second. Pretty innocuous but it will fill up the file system needlessly and get in the way of other INFO messages.

      cis.sources = httpd
      cis.sinks = loggerSink
      cis.channels = mem2logger

      cis.sources.httpd.type = spooldir
      cis.sources.httpd.spoolDir = /var/log/httpd
      cis.sources.httpd.trackerDir = /var/lib/flume-ng/tracker/httpd
      cis.sources.httpd.channels = mem2logger

      cis.sinks.loggerSink.type = logger
      cis.sinks.loggerSink.channel = mem2logger

      cis.channels.mem2logger.type = memory
      cis.channels.mem2logger.capacity = 10000
      cis.channels.mem2logger.transactionCapacity = 1000

        Activity

        Hide
        hudson Hudson added a comment -

        UNSTABLE: Integrated in flume-trunk #692 (See https://builds.apache.org/job/flume-trunk/692/)
        FLUME-2385. Remove incorrect log message at INFO level in Spool Directory Source. (hshreedharan: http://git-wip-us.apache.org/repos/asf/flume/repo?p=flume.git&a=commit&h=2c18533253be786b9c60bf687cdf38d2384d2625)

        • flume-ng-core/src/main/java/org/apache/flume/source/SpoolDirectorySource.java
        Show
        hudson Hudson added a comment - UNSTABLE: Integrated in flume-trunk #692 (See https://builds.apache.org/job/flume-trunk/692/ ) FLUME-2385 . Remove incorrect log message at INFO level in Spool Directory Source. (hshreedharan: http://git-wip-us.apache.org/repos/asf/flume/repo?p=flume.git&a=commit&h=2c18533253be786b9c60bf687cdf38d2384d2625 ) flume-ng-core/src/main/java/org/apache/flume/source/SpoolDirectorySource.java
        Hide
        hudson Hudson added a comment -

        UNSTABLE: Integrated in Flume-trunk-hbase-98 #49 (See https://builds.apache.org/job/Flume-trunk-hbase-98/49/)
        FLUME-2385. Remove incorrect log message at INFO level in Spool Directory Source. (hshreedharan: http://git-wip-us.apache.org/repos/asf/flume/repo?p=flume.git&a=commit&h=2c18533253be786b9c60bf687cdf38d2384d2625)

        • flume-ng-core/src/main/java/org/apache/flume/source/SpoolDirectorySource.java
        Show
        hudson Hudson added a comment - UNSTABLE: Integrated in Flume-trunk-hbase-98 #49 (See https://builds.apache.org/job/Flume-trunk-hbase-98/49/ ) FLUME-2385 . Remove incorrect log message at INFO level in Spool Directory Source. (hshreedharan: http://git-wip-us.apache.org/repos/asf/flume/repo?p=flume.git&a=commit&h=2c18533253be786b9c60bf687cdf38d2384d2625 ) flume-ng-core/src/main/java/org/apache/flume/source/SpoolDirectorySource.java
        Hide
        hshreedharan Hari Shreedharan added a comment -

        Committed! Thanks Phil!

        Show
        hshreedharan Hari Shreedharan added a comment - Committed! Thanks Phil!
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit c1512241c0104daa80f58c6146ecb759ef6417da in flume's branch refs/heads/flume-1.6 from Hari Shreedharan
        [ https://git-wip-us.apache.org/repos/asf?p=flume.git;h=c151224 ]

        FLUME-2385. Remove incorrect log message at INFO level in Spool Directory Source.

        (Phil Scala via Hari Shreedharan)

        Show
        jira-bot ASF subversion and git services added a comment - Commit c1512241c0104daa80f58c6146ecb759ef6417da in flume's branch refs/heads/flume-1.6 from Hari Shreedharan [ https://git-wip-us.apache.org/repos/asf?p=flume.git;h=c151224 ] FLUME-2385 . Remove incorrect log message at INFO level in Spool Directory Source. (Phil Scala via Hari Shreedharan)
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 2c18533253be786b9c60bf687cdf38d2384d2625 in flume's branch refs/heads/trunk from Hari Shreedharan
        [ https://git-wip-us.apache.org/repos/asf?p=flume.git;h=2c18533 ]

        FLUME-2385. Remove incorrect log message at INFO level in Spool Directory Source.

        (Phil Scala via Hari Shreedharan)

        Show
        jira-bot ASF subversion and git services added a comment - Commit 2c18533253be786b9c60bf687cdf38d2384d2625 in flume's branch refs/heads/trunk from Hari Shreedharan [ https://git-wip-us.apache.org/repos/asf?p=flume.git;h=2c18533 ] FLUME-2385 . Remove incorrect log message at INFO level in Spool Directory Source. (Phil Scala via Hari Shreedharan)
        Hide
        hshreedharan Hari Shreedharan added a comment -

        +1. Running tests and committing.

        Show
        hshreedharan Hari Shreedharan added a comment - +1. Running tests and committing.
        Hide
        advancedxy Xianjin YE added a comment -

        hi, Phil Scala, I think (according to my colleague) the more reasonable change is to set the log level to debug.

        Show
        advancedxy Xianjin YE added a comment - hi, Phil Scala , I think (according to my colleague) the more reasonable change is to set the log level to debug.
        Hide
        scaph01 Phil Scala added a comment -

        Patch to stop the logging of the "Spooling Directory Source runner has shutdown" over and over.

        Show
        scaph01 Phil Scala added a comment - Patch to stop the logging of the "Spooling Directory Source runner has shutdown" over and over.
        Hide
        scaph01 Phil Scala added a comment -

        Ed / Justin,
        Looking at the code, there seems to be a code change that introduced this behavior in the spool dir source,

        Commit:

        SHA-1: a345f611ba814c3689420edf4c2cc9b69ba3ac70
        
        * FLUME-2283: Spool Dir source must check interrupt flag before writing to channel
        
        (Hari Shreedharan via Jarek Jarcec Cecho)
        

        introduced this info logging statement and its logged all of the time, irrespective if there is an error (you don't know how long I looked around for an error today when I saw this being logged). The code in question is:

        while (!Thread.interrupted()) {
                  List<Event> events = reader.readEvents(batchSize);
                  if (events.isEmpty()) {
                    break;
                  }
                  sourceCounter.addToEventReceivedCount(events.size());
                  sourceCounter.incrementAppendBatchReceivedCount();
        
                  try {
                    getChannelProcessor().processEventBatch(events);
                    reader.commit();
                  } catch (ChannelException ex) {
                    ...
                    }
                    continue;
                  }
                  backoffInterval = 250;
                  sourceCounter.addToEventAcceptedCount(events.size());
                  sourceCounter.incrementAppendBatchAcceptedCount();
                }
                logger.info("Spooling Directory Source runner has shutdown.");
        ....
        
        

        the issue is events.isEmpty() returns true when there is nothing new in the spool dir, this calls the break and so the statement is logged. Since this is called on a schedule, 500ms later the same thing happens over and over. I believe the logging statement is not accurate because the source has not shutdown, its just done checking for files for this iteration.

        the fix to this issue is simply to remove this logging statement, which I will submit a patch for.

        Show
        scaph01 Phil Scala added a comment - Ed / Justin, Looking at the code, there seems to be a code change that introduced this behavior in the spool dir source, Commit: SHA-1: a345f611ba814c3689420edf4c2cc9b69ba3ac70 * FLUME-2283: Spool Dir source must check interrupt flag before writing to channel (Hari Shreedharan via Jarek Jarcec Cecho) introduced this info logging statement and its logged all of the time, irrespective if there is an error (you don't know how long I looked around for an error today when I saw this being logged). The code in question is: while (! Thread .interrupted()) { List<Event> events = reader.readEvents(batchSize); if (events.isEmpty()) { break ; } sourceCounter.addToEventReceivedCount(events.size()); sourceCounter.incrementAppendBatchReceivedCount(); try { getChannelProcessor().processEventBatch(events); reader.commit(); } catch (ChannelException ex) { ... } continue ; } backoffInterval = 250; sourceCounter.addToEventAcceptedCount(events.size()); sourceCounter.incrementAppendBatchAcceptedCount(); } logger.info( "Spooling Directory Source runner has shutdown." ); .... the issue is events.isEmpty() returns true when there is nothing new in the spool dir, this calls the break and so the statement is logged. Since this is called on a schedule, 500ms later the same thing happens over and over. I believe the logging statement is not accurate because the source has not shutdown, its just done checking for files for this iteration. the fix to this issue is simply to remove this logging statement, which I will submit a patch for.
        Hide
        ejsarge Edward Sargisson added a comment -

        I agree that this is highly annoying - especially so that you have to know to look back to just when the spamming started to determine what the failure actually was.

        However, I also think it's important that administrators know that the source has stopped. I would probably support simply logging a message saying, "Spooling Directory Source <name> has stopped. Refer to the start of these messages to determine why."

        We could consider logging this only every 5s or similar but that's a bit more interesting to implement.

        Show
        ejsarge Edward Sargisson added a comment - I agree that this is highly annoying - especially so that you have to know to look back to just when the spamming started to determine what the failure actually was. However, I also think it's important that administrators know that the source has stopped. I would probably support simply logging a message saying, "Spooling Directory Source <name> has stopped. Refer to the start of these messages to determine why." We could consider logging this only every 5s or similar but that's a bit more interesting to implement.

          People

          • Assignee:
            scaph01 Phil Scala
            Reporter:
            justinhayes Justin Hayes
          • Votes:
            3 Vote for this issue
            Watchers:
            12 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development