[JIRA] (JENKINS-44195) Add timestamps to the log

6 views
Skip to first unread message

oliver.lockwood@cantab.net (JIRA)

unread,
Feb 20, 2018, 6:12:02 AM2/20/18
to jenkinsc...@googlegroups.com
Oliver Lockwood commented on Improvement JENKINS-44195
 
Re: Add timestamps to the log

These two are related / duplicates, surely?

Add Comment Add Comment
 
This message was sent by Atlassian JIRA (v7.3.0#73011-sha1:3c73d0e)
Atlassian logo

dragoonis@gmail.com (JIRA)

unread,
Feb 28, 2018, 5:37:02 PM2/28/18
to jenkinsc...@googlegroups.com

I'm happy to pick this ticket up, pending a few chats with other team members.

As per https://issues.jenkins-ci.org/browse/JENKINS-47833 - have we decided to use Timestamper for this solution? or a native solution without requiring an additional plugin.

 

mneale@cloudbees.com (JIRA)

unread,
Feb 28, 2018, 6:10:05 PM2/28/18
to jenkinsc...@googlegroups.com

Paul Dragoonis I think this doesn't need timestamper (looking at the duplicate ticket, the console notes seem to bloat things) and this could be done probably in a more baked in way (or at least thought about). But I don't have any specific ideas on implementation...

mneale@cloudbees.com (JIRA)

unread,
Feb 28, 2018, 6:10:07 PM2/28/18
to jenkinsc...@googlegroups.com
Michael Neale edited a comment on Improvement JENKINS-44195
[~dragoonis] I think this doesn't need timestamper (looking at the duplicate ticket, the console notes seem to bloat things) and this could be done probably in a more baked in way (or at least thought about). But I don't have any specific ideas on implementation... (maybe time stamper could be adapted to work with blue ocean? I dunno)

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 1, 2018, 9:31:05 AM3/1/18
to jenkinsc...@googlegroups.com

Timestamer already works with pipeline, the problem is that blueocean is suppressing the output.

If you open the logs in the old console view it will show you the timestamps.

I'd vote against "baking this in", I think reusing a build wrapper is much better architecture when you consider plugins like https://wiki.jenkins.io/display/JENKINS/Logstash+Plugin  I'd hate to have to have to remove those baked in timestamps with regex when sending to an external system.

 

 

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 1, 2018, 9:31:06 AM3/1/18
to jenkinsc...@googlegroups.com
Jakub Bochenski edited a comment on Improvement JENKINS-44195
Timestamer already works with pipeline, the problem is that blueocean is suppressing the output.

If you open the logs in the old console view it will show you the timestamps.

I'd vote against "baking this in", I think reusing a build wrapper is much better architecture when you consider plugins like [https://wiki.jenkins.io/display/JENKINS/Logstash+Plugin]  I'd hate to have to have to remove those baked in timestamps with regex when sending log lines to an external system.

 

 

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 1, 2018, 9:40:03 AM3/1/18
to jenkinsc...@googlegroups.com

PS. We use timestamper on all our Jenkins jobs with 150 days retention. Some of the logs are quite big (~20 MB raw text). I haven't noticed any issues related to console notes like the ones trejkaz reported

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 5:29:04 PM3/1/18
to jenkinsc...@googlegroups.com

Jakub Bochenski timestamper with its use of console note won't work with anything that isn't the classic UI, it assumes that all the rest of it is there, ie if you want to get the logs out into another system, it won't work with it (that is my understanding). 

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 5:34:03 PM3/1/18
to jenkinsc...@googlegroups.com
Michael Neale edited a comment on Improvement JENKINS-44195
[~jbochenski] timestamper with its use of console I note won't work with anything that isn't timestamper lets you fetch the classic UI, it assumes that all the rest of it is there, logs as text ( ie if you can choose what you want to get the logs out into another system see , and then it won't work with adds it (that is my understanding to text ) which implies it might be able to work

 

I think the idea of wrapping pipeline via a step to get this is very strange and a usability hassle though (wouldn't people want to see timestamps always as a base line?)

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 5:48:04 PM3/1/18
to jenkinsc...@googlegroups.com

Jakub Bochenski oh good to know re size. 

Ah - the timestamper doesn't ad to the text you get via an api. It has another API to fetch it - so it must be possible. I can see the /wfapi used by the stage view shows it, so perhaps the best approach Paul Dragoonis is to find a way to support it in the log api that blue ocean uses - then it would work the same as people use now. 

The data returned from it looks like the following, which would be messy/risky to inject into an alternate log viewer (see the html fragments - and explains why sometimes things look off in stage view): 

 

{"nodeId""18","nodeStatus""SUCCESS","length": 8602,"hasMore"false,"text""<span class=\"timestamp\"><b>00:00:14.594</b> </span>[timestamper] Running shell script\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>+ ping -c 15 www.apple.com\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>PING e6858.dsce9.akamaiedge.net (104.84.9.174): 56 data bytes\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>64 bytes from 104.84.9.174: icmp_seq=0 ttl=52 time=46.146 ms\n<span class=\"timestamp\"><b>00:00:15.772</b> </span>64 bytes from 104.84.9.174: icmp_seq=1 ttl=52 time=24.984 ms\n<span class=\"timestamp\"><b>00:00:16.692</b> </span>64 bytes from 104.84.9.174: icmp_seq=2 ttl=52 time=40.099 ms\n<span class=\"timestamp\"><b>00:00:18.045</b> </span>64 bytes from 104.84.9.174: icmp_seq=3 ttl=52 time=39.247 ms\n<span class=\"timestamp\"><b>00:00:18.960</b> </span>64 bytes from 104.84.9.174: icmp_seq=4 ttl=52 time=38.471 ms\n<span class=\"timestamp\"><b>00:00:19.876</b> </span>64 bytes from 104.84.9.174: icmp_seq=5 ttl=52 time=37.845 ms\n<span class=\"timestamp\"><b>00:00:20.793</b> </span>64 bytes from 104.84.9.174: icmp_seq=6 ttl=52 time=37.656 ms\n<span class=\"timestamp\"><b>00:00:21.713</b> </span>64 bytes from 104.84.9.174: icmp_seq=7 ttl=52 time=35.950 ms\n<span class=\"timestamp\"><b>00:00:23.062</b> </span>64 bytes from 104.84.9.174: icmp_seq=8 ttl=52 time=37.010 ms\n<span class=\"timestamp\"><b>00:00:23.979</b> </span>64 bytes from 104.84.9.174: icmp_seq=9 ttl=52 time=34.426 ms\n<span class=\"timestamp\"><b>00:00:24.898</b> </span>64 bytes from 104.84.9.174: icmp_seq=10 ttl=52 time=33.600 ms\n<span class=\"timestamp\"><b>00:00:25.818</b> </span>64 bytes from 104.84.9.174: icmp_seq=11 ttl=52 time=21.033 ms\n<span class=\"timestamp\"><b>00:00:26.740</b> </span>64 bytes from 104.84.9.174: icmp_seq=12 ttl=52 time=19.620 ms\n<span class=\"timestamp\"><b>00:00:28.093</b> </span>64 bytes from 104.84.9.174: icmp_seq=13 ttl=52 time=30.910 ms\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>64 bytes from 104.84.9.174: icmp_seq=14 ttl=52 time=57.460 ms\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>--- e6858.dsce9.akamaiedge.net ping statistics ---\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>15 packets transmitted, 15 packets received, 0.0% packet loss\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>round-trip min/avg/max/stddev = 19.620/35.630/57.460/9.128 ms\n","consoleUrl""/job/timestamper/3/execution/node/18/log"}

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 5:49:11 PM3/1/18
to jenkinsc...@googlegroups.com
Michael Neale edited a comment on Improvement JENKINS-44195
[~jbochenski] oh good to know re size. 

Ah - the timestamper doesn't ad to the text you get via an api. It has another API to fetch it - so it must be possible. I can see the /wfapi used by the stage view shows it, so perhaps the best approach [~dragoonis] is to find a way to support it in the log api that blue ocean uses - then it would work the same as people use now. 

The data returned from it looks like the following, which would be messy/risky to inject into an alternate log viewer (see the html fragments - and explains why sometimes things look off in stage view)


 

The URI
: [http://localhost:8080/job/timestamper/3/execution/node/9/wfapi/log?_=1519944444778]

 

Perhaps [~vivek] may have some ideas on how the blue api server side could use the timestamper endpoint to fetch it with the stamps added?  

 

Response: 

 
{code:java}
{"nodeId": "18","nodeStatus": "SUCCESS","length": 8602,"hasMore": false,"text": "<span class=\"timestamp\"><b>00:00:14.594</b> </span>[timestamper] Running shell script\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>+ ping -c 15 www.apple.com\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>PING e6858.dsce9.akamaiedge.net (104.84.9.174): 56 data bytes\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>64 bytes from 104.84.9.174: icmp_seq=0 ttl=52 time=46.146 ms\n<span class=\"timestamp\"><b>00:00:15.772</b> </span>64 bytes from 104.84.9.174: icmp_seq=1 ttl=52 time=24.984 ms\n<span class=\"timestamp\"><b>00:00:16.692</b> </span>64 bytes from 104.84.9.174: icmp_seq=2 ttl=52 time=40.099 ms\n<span class=\"timestamp\"><b>00:00:18.045</b> </span>64 bytes from 104.84.9.174: icmp_seq=3 ttl=52 time=39.247 ms\n<span class=\"timestamp\"><b>00:00:18.960</b> </span>64 bytes from 104.84.9.174: icmp_seq=4 ttl=52 time=38.471 ms\n<span class=\"timestamp\"><b>00:00:19.876</b> </span>64 bytes from 104.84.9.174: icmp_seq=5 ttl=52 time=37.845 ms\n<span class=\"timestamp\"><b>00:00:20.793</b> </span>64 bytes from 104.84.9.174: icmp_seq=6 ttl=52 time=37.656 ms\n<span class=\"timestamp\"><b>00:00:21.713</b> </span>64 bytes from 104.84.9.174: icmp_seq=7 ttl=52 time=35.950 ms\n<span class=\"timestamp\"><b>00:00:23.062</b> </span>64 bytes from 104.84.9.174: icmp_seq=8 ttl=52 time=37.010 ms\n<span class=\"timestamp\"><b>00:00:23.979</b> </span>64 bytes from 104.84.9.174: icmp_seq=9 ttl=52 time=34.426 ms\n<span class=\"timestamp\"><b>00:00:24.898</b> </span>64 bytes from 104.84.9.174: icmp_seq=10 ttl=52 time=33.600 ms\n<span class=\"timestamp\"><b>00:00:25.818</b> </span>64 bytes from 104.84.9.174: icmp_seq=11 ttl=52 time=21.033 ms\n<span class=\"timestamp\"><b>00:00:26.740</b> </span>64 bytes from 104.84.9.174: icmp_seq=12 ttl=52 time=19.620 ms\n<span class=\"timestamp\"><b>00:00:28.093</b> </span>64 bytes from 104.84.9.174: icmp_seq=13 ttl=52 time=30.910 ms\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>64 bytes from 104.84.9.174: icmp_seq=14 ttl=52 time=57.460 ms\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>--- e6858.dsce9.akamaiedge.net ping statistics ---\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>15 packets transmitted, 15 packets received, 0.0% packet loss\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>round-trip min/avg/max/stddev = 19.620/35.630/57.460/9.128 ms\n","consoleUrl": "/job/timestamper/3/execution/node/18/log"}{code}

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 5:50:03 PM3/1/18
to jenkinsc...@googlegroups.com
Michael Neale edited a comment on Improvement JENKINS-44195
I note that timestamper lets you fetch the logs as text (ie you can choose what you want to see, and then it adds it to text) which implies it might be able to work. 


 

I think the idea of wrapping pipeline via a step to get this is very strange and a usability hassle though (wouldn't people want to see timestamps always as a base line?)


 

One of the hard things is that the whole console note thing kind of doesn't work if you are working with logs as text, outside of the classic web UI (as everything comes back as markup with assumptions as to how it works). It would be a bit like expecting the timestamper to work with LogStash logs. 

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 5:52:04 PM3/1/18
to jenkinsc...@googlegroups.com
Michael Neale edited a comment on Improvement JENKINS-44195
[~jbochenski] oh good to know re size. 

Ah - Clarification: there is no *supressing* of the timestamps in the logs via  blue ocean, the timestamps are not added to the log itself (directly), so it wouldn't be possible to supress it, they just aren't there. 

The
timestamper doesn't ad to the text you get via an api. It has another API to fetch it  the logs with the timestamps added as span/html fragments - so it must be possible. I can see the /wfapi used by the stage view shows it, so perhaps the best approach [~dragoonis] is to find a way to support it in the log api that blue ocean uses - then it would work the same as people use now. 


The data returned from it looks like the following, which would be messy/risky to inject into an alternate log viewer (see the html fragments - and explains why sometimes things look off in stage view). 

 

The URI: [http://localhost:8080/job/timestamper/3/execution/node/9/wfapi/log?_=1519944444778]

 

Perhaps [~vivek] may have some ideas on how the blue api server side could use the timestamper endpoint to fetch it with the stamps added? 

 

Response: 

 
{code:java}
{"nodeId": "18","nodeStatus": "SUCCESS","length": 8602,"hasMore": false,"text": "<span class=\"timestamp\"><b>00:00:14.594</b> </span>[timestamper] Running shell script\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>+ ping -c 15 www.apple.com\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>PING e6858.dsce9.akamaiedge.net (104.84.9.174): 56 data bytes\n<span class=\"timestamp\"><b>00:00:14.857</b> </span>64 bytes from 104.84.9.174: icmp_seq=0 ttl=52 time=46.146 ms\n<span class=\"timestamp\"><b>00:00:15.772</b> </span>64 bytes from 104.84.9.174: icmp_seq=1 ttl=52 time=24.984 ms\n<span class=\"timestamp\"><b>00:00:16.692</b> </span>64 bytes from 104.84.9.174: icmp_seq=2 ttl=52 time=40.099 ms\n<span class=\"timestamp\"><b>00:00:18.045</b> </span>64 bytes from 104.84.9.174: icmp_seq=3 ttl=52 time=39.247 ms\n<span class=\"timestamp\"><b>00:00:18.960</b> </span>64 bytes from 104.84.9.174: icmp_seq=4 ttl=52 time=38.471 ms\n<span class=\"timestamp\"><b>00:00:19.876</b> </span>64 bytes from 104.84.9.174: icmp_seq=5 ttl=52 time=37.845 ms\n<span class=\"timestamp\"><b>00:00:20.793</b> </span>64 bytes from 104.84.9.174: icmp_seq=6 ttl=52 time=37.656 ms\n<span class=\"timestamp\"><b>00:00:21.713</b> </span>64 bytes from 104.84.9.174: icmp_seq=7 ttl=52 time=35.950 ms\n<span class=\"timestamp\"><b>00:00:23.062</b> </span>64 bytes from 104.84.9.174: icmp_seq=8 ttl=52 time=37.010 ms\n<span class=\"timestamp\"><b>00:00:23.979</b> </span>64 bytes from 104.84.9.174: icmp_seq=9 ttl=52 time=34.426 ms\n<span class=\"timestamp\"><b>00:00:24.898</b> </span>64 bytes from 104.84.9.174: icmp_seq=10 ttl=52 time=33.600 ms\n<span class=\"timestamp\"><b>00:00:25.818</b> </span>64 bytes from 104.84.9.174: icmp_seq=11 ttl=52 time=21.033 ms\n<span class=\"timestamp\"><b>00:00:26.740</b> </span>64 bytes from 104.84.9.174: icmp_seq=12 ttl=52 time=19.620 ms\n<span class=\"timestamp\"><b>00:00:28.093</b> </span>64 bytes from 104.84.9.174: icmp_seq=13 ttl=52 time=30.910 ms\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>64 bytes from 104.84.9.174: icmp_seq=14 ttl=52 time=57.460 ms\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>--- e6858.dsce9.akamaiedge.net ping statistics ---\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>15 packets transmitted, 15 packets received, 0.0% packet loss\n<span class=\"timestamp\"><b>00:00:29.012</b> </span>round-trip min/avg/max/stddev = 19.620/35.630/57.460/9.128 ms\n","consoleUrl": "/job/timestamper/3/execution/node/18/log"}{code}

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 5:56:05 PM3/1/18
to jenkinsc...@googlegroups.com

So some more thoughts: 

  • Perhaps there is a way for timestamper to add data to the log in a way that blue ocean or other systems can use (that isn't classic UI specific markup that won't work)
  • Perhaps a way to show/toggle timestamps for all logs in blue ocean would be easier (would mean not using time stamper)
  • The timestamper output has to be scraped for the actual time data out of the embedded markup returned in the json (ugh)

None are appealing really. 

trejkaz@trypticon.org (JIRA)

unread,
Mar 1, 2018, 7:40:02 PM3/1/18
to jenkinsc...@googlegroups.com
trejkaz commented on Improvement JENKINS-44195

I'm fine with anything that gets the logs into the view in a more or less accurate way...

As long as it doesn't fill our disk with inefficient ConsoleNote serialisations like the timestamper plugin does. But maybe that just means fixing how its ConsoleNote is serialised? When I looked at how much was stored in it, I wasn't able to account for the enormous size it was writing into the file. (People who claim they aren't noticing it probably aren't using it with pipeline. It turns out that if you use it for non-pipeline jobs, it stores the timestamps in a much more sensible way.)

The comment about external logging systems seems a bit odd to me too actually, surely if you're going to store a timestamp, you'd want the time that it actually occurred, not the time at which the log event eventually entered something like logstash? Does logstash not support passing existing timestamps along?

Jared@Kauppi.la (JIRA)

unread,
Mar 1, 2018, 7:45:02 PM3/1/18
to jenkinsc...@googlegroups.com

Logstash definitely supports parsing existing timestamps and is generally the value you want to use vs just utilizing the received time like you mentioned.

trejkaz@trypticon.org (JIRA)

unread,
Mar 1, 2018, 7:50:02 PM3/1/18
to jenkinsc...@googlegroups.com
trejkaz commented on Improvement JENKINS-44195

This relates to another thing we noticed, which is that timestamps were being generated from Jenkins master, which meant they didn't really reflect the times the events were occurring on the slaves. Normally you'd think this wouldn't differ by much, but because of the already-mentioned ConsoleNote thing, our Jenkins was working so hard reading from sockets and writing to logs that it was being delayed in processing data coming from slaves.

We currently pipe all our commands through an executable to add the timestamps to the raw output so that we can see the true timestamps irrespective of how long the master is taking to read and write the data. 

 

mneale@cloudbees.com (JIRA)

unread,
Mar 1, 2018, 7:51:02 PM3/1/18
to jenkinsc...@googlegroups.com

trejkaz interesting - yes they probably are large. 

Jared Kauppila log stash I don't think would see those timestamps from the timestamper plugin at all (it probably ads its own somehow...)

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 2, 2018, 7:19:03 AM3/2/18
to jenkinsc...@googlegroups.com

{quote}I think the idea of wrapping pipeline via a step to get this is very strange and a usability hassle though (wouldn't people want to see timestamps always as a base line?){quote}

Michael Neale one group of people who apparently has no use for timestamps are Jenkins plugin developers, c.f. https://ci.jenkins.io/job/Plugins/ YMMV
More seriously: there are more plugins one could consider obvious defaults, e.g: log rotate, colorize output or mask passwords.

I agree there is an usability problem, but it's a general pipeline problem. There is just no convenient way to apply common settings like the above.
I've already mentioned it before. You can define a common wrapper via shared libraries, but you need to remember to apply this (unless you want declarative pipeline).

I'd love to see this general issue addressed instead of just baking in the timestamps

 

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 2, 2018, 7:21:04 AM3/2/18
to jenkinsc...@googlegroups.com
Jakub Bochenski edited a comment on Improvement JENKINS-44195
\ {quote}I think the idea of wrapping pipeline via a step to get this is very strange and a usability hassle though (wouldn't people want to see timestamps always as a base line?)\{quote}

[~michaelneale] one group of people who apparently has no use for timestamps are Jenkins plugin developers, c.f. [https://ci.jenkins.io/job/Plugins/] YMMV

More seriously: there are more plugins one could consider obvious defaults, e.g: log rotate, colorize output or mask passwords.

I agree there is an usability problem, but it's a general pipeline problem. There is just no convenient way to apply common settings like the above.
I've already mentioned it before. You can define a common wrapper via shared libraries, but you need to remember to apply this (unless you want declarative pipeline).

I'd love to see this general issue addressed instead of just baking in the timestamps

 

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 2, 2018, 7:21:04 AM3/2/18
to jenkinsc...@googlegroups.com

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 2, 2018, 7:38:03 AM3/2/18
to jenkinsc...@googlegroups.com
Jakub Bochenski edited a comment on Improvement JENKINS-44195
{quote}As long as it doesn't fill our disk with inefficient ConsoleNote serialisations like the timestamper plugin does. But maybe that just means fixing how its ConsoleNote is serialised? When I looked at how much was stored in it, I wasn't able to account for the enormous size it was writing into the file. (People who claim they aren't noticing it probably aren't using it with pipeline. It turns out that if you use it for non-pipeline jobs, it stores the timestamps in a much more sensible way.)

The comment about external logging systems seems a bit odd to me too actually, surely if you're going to store a timestamp, you'd want the time that it actually occurred, not the time at which the log event eventually entered something like logstash? Does logstash not support passing existing timestamps along?{quote}

[~trejkaz] the logstash plugin supports two modes: sending each line individually or sending the whole log as a single document. In both modes the only time data that is being sent is {{hudson.model.Run.getTimestamp()}}. In each-line mode you have the send time as a proxy for actual line time.

This might seem odd, but that's the way it works now. Being both an active user and maintainer of the logstash plugin I'd like to make sure it stays relevant. One thing that would break an existing use case is the baked-in timestamps interfering with text search of the build log.

I second the call to fix ConsoleNote serialization. It is the current API for annotating console lines so making it work properly with Pipeline seems like a better choice.
As a bonus: it would make implementing sendiing "real" timestamps to external systems much easier if somebody wants to add that feature one day (as opposed to having to hack into Pipeline internals, not to mention having to switch for old-style and pipeline jobs).

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 2, 2018, 7:38:04 AM3/2/18
to jenkinsc...@googlegroups.com

As long as it doesn't fill our disk with inefficient ConsoleNote serialisations like the timestamper plugin does. But maybe that just means fixing how its ConsoleNote is serialised? When I looked at how much was stored in it, I wasn't able to account for the enormous size it was writing into the file. (People who claim they aren't noticing it probably aren't using it with pipeline. It turns out that if you use it for non-pipeline jobs, it stores the timestamps in a much more sensible way.)

The comment about external logging systems seems a bit odd to me too actually, surely if you're going to store a timestamp, you'd want the time that it actually occurred, not the time at which the log event eventually entered something like logstash? Does logstash not support passing existing timestamps along?

trejkaz the logstash plugin supports two modes: sending each line individually or sending the whole log as a single document. In both modes the only time data that is being sent is hudson.model.Run.getTimestamp(). In each-line mode you have the send time as a proxy for actual line time.


This might seem odd, but that's the way it works now. Being both an active user and maintainer of the logstash plugin I'd like to make sure it stays relevant. One thing that would break an existing use case is the baked-in timestamps interfering with text search of the build log.

I second the call to fix ConsoleNote serialization. It is the current API for annotating console lines so making it work properly with Pipeline seems like a better choice.
As a bonus: it would make implementing sendiing "real" timestamps to external systems much easier if somebody wants to add that feature one day (as opposed to having to hack into Pipeline internals, not to mention having to switch for old-style and pipeline jobs).

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 2, 2018, 7:39:03 AM3/2/18
to jenkinsc...@googlegroups.com
Jakub Bochenski edited a comment on Improvement JENKINS-44195
{quote}As long as it doesn't fill our disk with inefficient ConsoleNote serialisations like the timestamper plugin does. But maybe that just means fixing how its ConsoleNote is serialised? When I looked at how much was stored in it, I wasn't able to account for the enormous size it was writing into the file. (People who claim they aren't noticing it probably aren't using it with pipeline. It turns out that if you use it for non-pipeline jobs, it stores the timestamps in a much more sensible way.)

The comment about external logging systems seems a bit odd to me too actually, surely if you're going to store a timestamp, you'd want the time that it actually occurred, not the time at which the log event eventually entered something like logstash? Does logstash not support passing existing timestamps along?{quote}

[~trejkaz] the logstash plugin supports two modes: sending each line individually or sending the whole log as a single document. In both modes the only time data that is being sent is {{hudson.model.Run.getTimestamp()}}. In each-line mode you have the
send receive time as a proxy for actual line time.


This might seem odd, but that's the way it works now. Being both an active user and maintainer of the logstash plugin I'd like to make sure it stays relevant. One thing that would break an existing use case is the baked-in timestamps interfering with text search of the build log.

I second the call to fix ConsoleNote serialization. It is the current API for annotating console lines so making it work properly with Pipeline seems like a better choice.
As a bonus: it would make implementing sendiing "real" timestamps to external systems much easier if somebody wants to add that feature one day (as opposed to having to hack into Pipeline internals, not to mention having to switch for old-style and pipeline jobs).

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 2, 2018, 7:39:03 AM3/2/18
to jenkinsc...@googlegroups.com
Jakub Bochenski edited a comment on Improvement JENKINS-44195
{quote}I think the idea of wrapping pipeline via a step to get this is very strange and a usability hassle though (wouldn't people want to see timestamps always as a base line?){quote}

[~michaelneale] one group of people who apparently has no use for timestamps are Jenkins plugin developers, c.f. [https://ci.jenkins.io/job/Plugins/] YMMV
More seriously: there are more plugins one could consider obvious defaults, e.g: log rotate, colorize output or mask passwords.

I agree there is an usability problem, but it's a general pipeline problem. There is just no convenient way to apply common settings like the above.
I've already mentioned it before. You can define a common wrapper via shared libraries, but you need to remember to apply this (unless you want declarative pipeline , then your out of luck ).


I'd love to see this general issue addressed instead of just baking in the timestamps

 

vivek.pandey@gmail.com (JIRA)

unread,
Mar 5, 2018, 3:42:13 PM3/5/18
to jenkinsc...@googlegroups.com
Vivek Pandey updated an issue
 
Jenkins / Improvement JENKINS-44195
Change By: Vivek Pandey
Sprint: Blue Ocean 1.5 - beta 2

vivek.pandey@gmail.com (JIRA)

unread,
Mar 5, 2018, 3:42:13 PM3/5/18
to jenkinsc...@googlegroups.com
Vivek Pandey updated an issue
Change By: Vivek Pandey
Sprint: Blue Ocean 1.5 - beta 3

vivek.pandey@gmail.com (JIRA)

unread,
Mar 19, 2018, 5:31:02 PM3/19/18
to jenkinsc...@googlegroups.com

vivek.pandey@gmail.com (JIRA)

unread,
Mar 19, 2018, 5:31:04 PM3/19/18
to jenkinsc...@googlegroups.com
Vivek Pandey updated an issue
Change By: Vivek Pandey
Sprint: Blue Ocean - Candidates

bochenski.kuba+jenkins@gmail.com (JIRA)

unread,
Mar 20, 2018, 6:45:02 AM3/20/18
to jenkinsc...@googlegroups.com
Jakub Bochenski commented on Improvement JENKINS-44195
 
Re: Add timestamps to the log

FTR the ConsoleNote and other reasons for pipeline logs bloat are discussed in JENKINS-38381 and JENKINS-48344

batmat@batmat.net (JIRA)

unread,
Jul 3, 2018, 3:49:02 AM7/3/18
to jenkinsc...@googlegroups.com

I agree timestamping ought to be always on, at the very least by default. One might not realize it is needed, until things start to go less well. Then, when trying to understand where time is spent, you're left with either enabling the option, or possibly trickier wild guesses.

This message was sent by Atlassian JIRA (v7.10.1#710002-sha1:6efc396)

steve.lohr@deutschepost.de (JIRA)

unread,
Aug 16, 2018, 8:18:04 AM8/16/18
to jenkinsc...@googlegroups.com

would really like to see this feature, just stumpled upon it in Blue Ocean and thought there was a mistake with the missing timestamps

marko.elezovic@oradian.com (JIRA)

unread,
Sep 1, 2018, 2:15:02 PM9/1/18
to jenkinsc...@googlegroups.com

+1 - this would be awesome - we've recently migrated to Blue Ocean, and this is a regression for our debugging efforts
Is there any clue when this would be available, because otherwise we need to start manually logging to console instead?

This message was sent by Atlassian Jira (v7.11.2#711002-sha1:fdc329d)

kellyfj@gmail.com (JIRA)

unread,
Sep 18, 2018, 10:34:04 AM9/18/18
to jenkinsc...@googlegroups.com

The lack of this feature is also causing a step back in our ability to debug long running jobs. This is very needed. Thanks!

jglick@cloudbees.com (JIRA)

unread,
Feb 7, 2019, 3:31:03 PM2/7/19
to jenkinsc...@googlegroups.com

The release of JENKINS-48344 should open up a new implementation possibility for this in Blue Ocean.

tagrain@gmail.com (JIRA)

unread,
Mar 5, 2019, 9:25:07 AM3/5/19
to jenkinsc...@googlegroups.com
Thomas Grainger stopped work on Improvement JENKINS-44195
 
Change By: Thomas Grainger
Status: In Progress Open

tagrain@gmail.com (JIRA)

unread,
Mar 5, 2019, 9:25:07 AM3/5/19
to jenkinsc...@googlegroups.com
Thomas Grainger started work on Improvement JENKINS-44195
 
Change By: Thomas Grainger
Status: Open In Progress

ethorsa@inbox.lv (JIRA)

unread,
Apr 5, 2019, 4:42:04 AM4/5/19
to jenkinsc...@googlegroups.com
ethorsa commented on Improvement JENKINS-44195

Timestamper 1.9 provides support for timestamps in pipelines. It's even possible to enable them globally.

steve.lohr@deutschepost.de (JIRA)

unread,
Apr 5, 2019, 5:10:03 AM4/5/19
to jenkinsc...@googlegroups.com

ethorsa it is not about timestamps in pipelines but the display of them in Blue Ocean

steffen.wilke@wibemedia.de (JIRA)

unread,
Jul 8, 2019, 1:11:03 PM7/8/19
to jenkinsc...@googlegroups.com

Proper timestamp visualization in the Blue Ocean view would be very much appreciated! Having to switch to the old UI for this is time-consuming and inconsistent.

luckyhk.lee@samsung.com (JIRA)

unread,
Jul 9, 2019, 5:13:29 AM7/9/19
to jenkinsc...@googlegroups.com

In my case, 

I am using timestamp plugin,

In console output, timezone is OK. but log is too long.

It shows

15:26:36 blah blah

So I want to see log in blueocean for each stage, step.

but int blue ocean, timezone is UTC maybe.

It shows

[2019-07-09T06:23:02.385Z]  blah blah

 

even though I set timezone properly.

 

Reply all
Reply to author
Forward
0 new messages