Hadoop Common
  1. Hadoop Common
  2. HADOOP-6107

Have some log messages designed for machine parsing, either real-time or post-mortem

    Details

    • Type: Improvement Improvement
    • Status: Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: 0.21.0
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      Many programs take the log output of bits of Hadoop, and try and parse it. Some may also put their own back end behind commons-logging, to capture the input without going via Log4J, so as to keep the output more machine-readable.

      These programs need log messages that

      1. are easy to parse by a regexp or other simple string parse (consider quoting values, etc)
      2. push out the full exception chain rather than stringify() bits of it
      3. stay stable across versions
      4. log the things the tools need to analyse: events, data volumes, errors

      For these logging tools, ease of parsing, retention of data and stability over time take the edge over readability. In HADOOP-5073, Jiaqi Tan proposed marking some of the existing log events as evolving towards stability. As someone who regulary patches log messages to improve diagnostics, this creates a conflict of interest. For me, good logs are ones that help people debug their problems without anyone else helping, and if that means improving the text, so be it. Tools like Chukwa have a different need.

      What to do? Some options

      1. Have some messages that are designed purely for other programs to handle
      2. Have some logs specifically for machines, to which we log alongside the human-centric messages
      3. Fix many of the common messages, then leave them alone.
      4. Mark log messages to be left alone (somehow)

        Issue Links

          Activity

          Gavin made changes -
          Link This issue is depended upon by HADOOP-7466 [ HADOOP-7466 ]
          Gavin made changes -
          Link This issue blocks HADOOP-7466 [ HADOOP-7466 ]
          Steve Loughran made changes -
          Status In Progress [ 3 ] Open [ 1 ]
          Steve Loughran made changes -
          Link This issue blocks HADOOP-7466 [ HADOOP-7466 ]
          Steve Loughran made changes -
          Status Open [ 1 ] In Progress [ 3 ]
          Steve Loughran made changes -
          Assignee Steve Loughran [ stevel@apache.org ]
          Gavin made changes -
          Field Original Value New Value
          Reporter Steve Loughran [ steve_l ] Steve Loughran [ stevel@apache.org ]
          Hide
          steve_l added a comment -

          On this topic, here's a nice paper, "Detecting Large-Scale System Problems by Mining Console Logs", where they went through the HDFS logs by parsing the text. With more machine parseable logs, there's less need for this

          http://www.sigops.org/sosp/sosp09/papers/xu-sosp09.pdf

          Show
          steve_l added a comment - On this topic, here's a nice paper, "Detecting Large-Scale System Problems by Mining Console Logs", where they went through the HDFS logs by parsing the text. With more machine parseable logs, there's less need for this http://www.sigops.org/sosp/sosp09/papers/xu-sosp09.pdf
          Hide
          Todd Lipcon added a comment -

          It's not so much a thrift back-end for log4j - the issue is that the log messages themselves are unstructured. If you're logging Strings, you're faced with a parsing challenge. If you're logging some kind of Event objects, you can choose to output strings or structured data.

          Show
          Todd Lipcon added a comment - It's not so much a thrift back-end for log4j - the issue is that the log messages themselves are unstructured. If you're logging Strings, you're faced with a parsing challenge. If you're logging some kind of Event objects, you can choose to output strings or structured data.
          Hide
          steve_l added a comment -

          sounds like you need a way of having different plug-ins for monitoring, or a thrift back-end to log4j

          Show
          steve_l added a comment - sounds like you need a way of having different plug-ins for monitoring, or a thrift back-end to log4j
          Hide
          Todd Lipcon added a comment -

          In other systems, I've done this by using Thrift to serialize the logs on disk. This allows for backward compatible evolution of the contents of the log messages, and is a much more compact format even without compression. We could consider Avro for this down the road.

          The obvious disadvantage is that text logs are way more useful than binary ones. Having binary logs absolutely requires that there is a very good tool for converting them to a readable form, as well as grepping through them.

          Show
          Todd Lipcon added a comment - In other systems, I've done this by using Thrift to serialize the logs on disk. This allows for backward compatible evolution of the contents of the log messages, and is a much more compact format even without compression. We could consider Avro for this down the road. The obvious disadvantage is that text logs are way more useful than binary ones. Having binary logs absolutely requires that there is a very good tool for converting them to a readable form, as well as grepping through them.
          Hide
          steve_l added a comment -

          and server side, similar issues

          09/06/25 13:54:26 INFO datanode.DataNode: BlockReport of 8 blocks got processed in 1 msecs
          09/06/25 13:54:26 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000001_1 0.0% reduce > copy > 
          09/06/25 13:54:29 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000001_1 0.0% reduce > copy > 
          09/06/25 13:54:29 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000000_1 0.0% reduce > copy > 
          09/06/25 13:54:32 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000000_1 0.0% reduce > copy > 
          09/06/25 13:54:35 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000001_1 0.0% reduce > copy > 
          09/06/25 13:54:36 INFO datanode.DataNode: BlockReport of 8 blocks got processed in 2 msecs
          09/06/25 13:54:38 INFO mapred.JobInProgress: Failed fetch notification #3 for task attempt_200906251314_0002_m_000000_1
          09/06/25 13:54:38 INFO mapred.JobInProgress: Too many fetch-failures for output of task: attempt_200906251314_0002_m_000000_1 ... killing it
          09/06/25 13:54:38 INFO mapred.TaskInProgress: Error from attempt_200906251314_0002_m_000000_1: Too many fetch-failures
          

          The task tracker lists attempt IDs, but nothing includes any datanode or tasktracker identity information. If you are aggregating the logs you need that, which means you need to stick extra data on every log event that comes in, and you have to track all their values. Aggregation is simpler if the machine-level events include more sender info.

          Show
          steve_l added a comment - and server side, similar issues 09/06/25 13:54:26 INFO datanode.DataNode: BlockReport of 8 blocks got processed in 1 msecs 09/06/25 13:54:26 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000001_1 0.0% reduce > copy > 09/06/25 13:54:29 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000001_1 0.0% reduce > copy > 09/06/25 13:54:29 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000000_1 0.0% reduce > copy > 09/06/25 13:54:32 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000000_1 0.0% reduce > copy > 09/06/25 13:54:35 INFO mapred.TaskTracker: attempt_200906251314_0002_r_000001_1 0.0% reduce > copy > 09/06/25 13:54:36 INFO datanode.DataNode: BlockReport of 8 blocks got processed in 2 msecs 09/06/25 13:54:38 INFO mapred.JobInProgress: Failed fetch notification #3 for task attempt_200906251314_0002_m_000000_1 09/06/25 13:54:38 INFO mapred.JobInProgress: Too many fetch-failures for output of task: attempt_200906251314_0002_m_000000_1 ... killing it 09/06/25 13:54:38 INFO mapred.TaskInProgress: Error from attempt_200906251314_0002_m_000000_1: Too many fetch-failures The task tracker lists attempt IDs, but nothing includes any datanode or tasktracker identity information. If you are aggregating the logs you need that, which means you need to stick extra data on every log event that comes in, and you have to track all their values. Aggregation is simpler if the machine-level events include more sender info.
          Hide
          steve_l added a comment - - edited

          as examples of the problem, some client side logs

            [java] 09/06/25 13:41:07 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:41:07 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:41:10 INFO mapred.JobClient: Task Id : attempt_200906251314_0002_r_000001_0, Status : FAILED
               [java] Shuffle Error: Exceeded MAX_FAILED_UNIQUE_FETCHES; bailing-out.
               [java] 09/06/25 13:41:10 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:41:10 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:44:07 INFO mapred.JobClient: Task Id : attempt_200906251314_0002_m_000004_0, Status : FAILED
               [java] Too many fetch-failures
               [java] 09/06/25 13:44:07 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:44:07 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:44:11 INFO mapred.JobClient:  map 83% reduce 0%
               [java] 09/06/25 13:44:14 INFO mapred.JobClient:  map 100% reduce 0%
               [java] 09/06/25 13:49:23 INFO mapred.JobClient: Task Id : attempt_200906251314_0002_m_000005_0, Status : FAILED
               [java] Too many fetch-failures
               [java] 09/06/25 13:49:23 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:49:23 WARN mapred.JobClient: Error reading task outputConnection refused
               [java] 09/06/25 13:49:27 INFO mapred.JobClient:  map 83% reduce 0%
          
          1. bad spacing in the " Error reading task outputConnection refused" message.
          2. not enough context as to why the connection was being refused: need to include the (hostname, port) details -which would change the message and break chukwa
          3. no stack trace in the connection refused message
          4. not enough context in the JobClient messages; if >1 job is running simultaneously, you cant determine what the map and reduce is referring to
          5. The shuffle error doesn't actually say what the MAX_FAILED_UNIQUE_FETCHES value is.
          Show
          steve_l added a comment - - edited as examples of the problem, some client side logs [java] 09/06/25 13:41:07 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:41:07 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:41:10 INFO mapred.JobClient: Task Id : attempt_200906251314_0002_r_000001_0, Status : FAILED [java] Shuffle Error: Exceeded MAX_FAILED_UNIQUE_FETCHES; bailing-out. [java] 09/06/25 13:41:10 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:41:10 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:44:07 INFO mapred.JobClient: Task Id : attempt_200906251314_0002_m_000004_0, Status : FAILED [java] Too many fetch-failures [java] 09/06/25 13:44:07 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:44:07 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:44:11 INFO mapred.JobClient: map 83% reduce 0% [java] 09/06/25 13:44:14 INFO mapred.JobClient: map 100% reduce 0% [java] 09/06/25 13:49:23 INFO mapred.JobClient: Task Id : attempt_200906251314_0002_m_000005_0, Status : FAILED [java] Too many fetch-failures [java] 09/06/25 13:49:23 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:49:23 WARN mapred.JobClient: Error reading task outputConnection refused [java] 09/06/25 13:49:27 INFO mapred.JobClient: map 83% reduce 0% bad spacing in the " Error reading task outputConnection refused" message. not enough context as to why the connection was being refused: need to include the (hostname, port) details -which would change the message and break chukwa no stack trace in the connection refused message not enough context in the JobClient messages; if >1 job is running simultaneously, you cant determine what the map and reduce is referring to The shuffle error doesn't actually say what the MAX_FAILED_UNIQUE_FETCHES value is.
          steve_l created issue -

            People

            • Assignee:
              Steve Loughran
              Reporter:
              Steve Loughran
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:

                Development