search

jenkinsci / build-time-blame-plugin

A Jenkins plugin for analyzing the historical console output of a Job with the goal of determining which steps are taking the most time.
https://plugins.jenkins.io/build-time-blame/
MIT License
29 stars 9 forks source link

"Error finding timestamps" despite Timestamps are enabled #7

Closed tkleiber closed 7 years ago

tkleiber commented 8 years ago

We have jobs here which works fine and another wich does not work. Both has Timestamps enabled. Timestamps could be seen, when showing the log.

LTegtmeier commented 8 years ago

I had to modify the parsing of logs/timestamps to work around some issues caused by the way Maven logs to the console. This might be something similar.

I'll need the builds directory for one of the jobs that is failing or at least the log file and timestamper folder for one of the error builds.

LTegtmeier commented 8 years ago

Closing as unreproducible. I'll need logs or a way to generate logs that have this error in order to diagnose and fix it.

If you're trying to look into it, the LogParser does the processing of logs by merging each line with the next timestamp. It uses CustomFileReader to break the file on \n characters. This is because Maven often logs \r characters. The timestamper plugin does not consider these as new lines. Your issue might be something related to this.

tkleiber commented 8 years ago

Sorry for the delay, attached are the logs and 2 screenshots. You see the timestamps and the error for build 358 as an example.

builds.zip timestamps_build_358 error_build_time_blame_report_build_358

LTegtmeier commented 8 years ago

Ok, I'll look into it, thanks.

LTegtmeier commented 8 years ago

Does this job happen to run on the same slave as the jobs that work? Or does it run on a slave with a different Operating System?

tkleiber commented 8 years ago

Same slave, same operating system.

LTegtmeier commented 8 years ago

I found the problem. But, I'm not sure what caused it or what the plugin should do about it. It appears the Timestamper plugin did not create a timestamp for the final Finished: SUCCESS line.

00:12:48.712 Triggering a new build of ADF 12c Systemtest - Test nach Deploy FF 44.0 WIN SERVER 2008 (CITRIX)
00:12:48.714 Triggering a new build of ADF 12c Systemtest - Test nach Deploy IE 11.0 WIN 7 (Virtuell)
00:12:48.714 Triggering a new build of ADF 12c Systemtest - Test nach Deploy IE 11.0 WIN SERVER 2008 (CITRIX)
Finished: SUCCESS

I could not recreate this issue with Timestamper plugin version 1.8.7 (which appears to be the version you are using) and Jenkins version 2.9. The LogParser throws an exception whenever it finds a line that doesn't match a timestamp because it has no logic to determine that the timestamps are only slightly different in this case. Since it's the last line, LogParser could fall back to the timestamp from the previous line. But, it would be tricky to ensure that doesn't cause other problems. My first impulse is that this is a bug in the timestamper plugin. But, I'm not sure what conditions cause it.