Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-46420

Raw log with timestamps is cut short

    Details

    • Type: Bug
    • Status: Resolved (View Workflow)
    • Priority: Major
    • Resolution: Fixed
    • Component/s: timestamper-plugin
    • Labels:
      None
    • Environment:
      Timestamper 1.8.8
      Jenkins 1.651.3
    • Similar Issues:

      Description

      Viewing the consoleText log with timestamps works, but viewing the plaintext log with time stamps does not work properly. The log is cut short, and the time stamps ends too early.

      Console text has proper time stamps:

      00:40:41.937 Finished: SUCCESS
      

      Plain text (.../timestamps?appendLog) does not:

      00:40:41.937  make[3]: Entering directory '/buildroot/otp-OTP-19.2/erts/lib_src'
        make[3]: Nothing to be done for 'all'.
      

      The number of timestamps is about 16k, but there are 26k lines in the log. I can see that some parts of the log, e.g. what looks like empty lines, is handled differently in the consoleText part compared to the plaintext part:

      consoleText skips empty lines:

      00:00:16.744 Sending build context to Docker daemon 19.46 kB
      
      
      00:00:16.834 Step 1 : FROM openjdk:8u131-jre-alpine
      

      /timestamps does not:

      00:00:16.744  Sending build context to Docker daemon 19.46 kB
      00:00:16.834  
      00:00:16.834  
      00:00:16.835  Step 1 : FROM openjdk:8u131-jre-alpine
      

      Here the time stamp becomes skewed.

      It looks like the code which presents the plaintext output does not match the code for the consoleText in some cases which skews the times. This makes the plain text timestamp output essentially useless for most logs.

        Attachments

          Activity

          Hide
          dbailey Darragh Bailey added a comment -

          Looks like in the console it is possible for log messages to contain a new line while being written out as a single entry, but the timestamper reader is assuming each new line delimits a new log entry. Consequently, appear to run out of timestamps.

          Looking in a raw log file on disk, it looks like '^M' character is written out to a console log in to indicate a newline within a log line, without indicating a new log line. But the BufferedReader assumes any newline, carriage return or linefeed.

          Perhaps simply switching from BufferedReader to Scanner in LogFileReader would be sufficient to solve? Allows use of a delimiter as the end of line token as described at https://stackoverflow.com/a/16712231

          Show
          dbailey Darragh Bailey added a comment - Looks like in the console it is possible for log messages to contain a new line while being written out as a single entry, but the timestamper reader is assuming each new line delimits a new log entry. Consequently, appear to run out of timestamps. Looking in a raw log file on disk, it looks like '^M' character is written out to a console log in to indicate a newline within a log line, without indicating a new log line. But the BufferedReader assumes any newline, carriage return or linefeed. Perhaps simply switching from BufferedReader to Scanner in LogFileReader would be sufficient to solve? Allows use of a delimiter as the end of line token as described at https://stackoverflow.com/a/16712231
          Hide
          dbailey Darragh Bailey added a comment -

          Tested the following fix and it appears to work as expected for me: https://github.com/jenkinsci/timestamper-plugin/pull/21

          You can check locally by using a simple echo statement in code that uses '\r' instead of '\n' for newlines.

          Raw output and console matched.

          Show
          dbailey Darragh Bailey added a comment - Tested the following fix and it appears to work as expected for me: https://github.com/jenkinsci/timestamper-plugin/pull/21 You can check locally by using a simple echo statement in code that uses '\r' instead of '\n' for newlines. Raw output and console matched.
          Hide
          scm_issue_link SCM/JIRA link daemon added a comment -

          Code changed in jenkins
          User: Darragh Bailey
          Path:
          src/main/java/hudson/plugins/timestamper/io/LogFileReader.java
          http://jenkins-ci.org/commit/timestamper-plugin/996c35a1e49f3ed914b32e105b16e57b66cbff15
          Log:
          JENKINS-46420 Match console end of line delimiter

          Console output defaults to a limited set of end of line delimiters,
          such as '\n'. Change to using the Scanner class which allows for
          control of the delimiter character to ensure the LogFileReader class
          matches between lines and recorded timestamps even when output contains
          other newline characters.

          Show
          scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Darragh Bailey Path: src/main/java/hudson/plugins/timestamper/io/LogFileReader.java http://jenkins-ci.org/commit/timestamper-plugin/996c35a1e49f3ed914b32e105b16e57b66cbff15 Log: JENKINS-46420 Match console end of line delimiter Console output defaults to a limited set of end of line delimiters, such as '\n'. Change to using the Scanner class which allows for control of the delimiter character to ensure the LogFileReader class matches between lines and recorded timestamps even when output contains other newline characters.
          Hide
          scm_issue_link SCM/JIRA link daemon added a comment -

          Code changed in jenkins
          User: StevenGBrown
          Path:
          src/main/java/hudson/plugins/timestamper/io/LogFileReader.java
          http://jenkins-ci.org/commit/timestamper-plugin/43c84084e01fae21c3e825a5d0e23722bec8f556
          Log:
          Merge pull request #21 from electrofelix/limit-newline-characters

          JENKINS-46420 Match console end of line delimiter

          Compare: https://github.com/jenkinsci/timestamper-plugin/compare/2fed9af88ade...43c84084e01f

          Show
          scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: StevenGBrown Path: src/main/java/hudson/plugins/timestamper/io/LogFileReader.java http://jenkins-ci.org/commit/timestamper-plugin/43c84084e01fae21c3e825a5d0e23722bec8f556 Log: Merge pull request #21 from electrofelix/limit-newline-characters JENKINS-46420 Match console end of line delimiter Compare: https://github.com/jenkinsci/timestamper-plugin/compare/2fed9af88ade...43c84084e01f
          Hide
          stevengbrown Steven G Brown added a comment -

          Thanks. I've released your fix with Timestamper 1.8.9.

          Show
          stevengbrown Steven G Brown added a comment - Thanks. I've released your fix with Timestamper 1.8.9.

            People

            • Assignee:
              stevengbrown Steven G Brown
              Reporter:
              gunnar Gunnar Strand
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: