Add option to Jobs to automatically Timestamp build logs with elapsed time or UTC | Feature Requests

Add option to Jobs to automatically Timestamp build logs with elapsed time or UTC

Jeff Minard

While CCI allows you to separate builds into steps, it's very common to find that a singular step is multi-phased itself. It would be extremely helpful if, within a build step, the output was timestamped. 
This is the Jenkins equivalent: https://wiki.jenkins.io/display/JENKINS/Timestamper
I'd be most interested in the duration feature, more so that having the timestamps and needing to work out duration of steps myself.
CCI-I-360

April 9, 2018

Kevin Tse

Thanks for your patience on this request! After careful consideration, we've decided to keep the current log format, and here's why:

We want to preserve your control: The log output reflects your build configuration, and we're committed to not altering it without your explicit direction.
We want to protect existing workflows: Many teams download logs and parse them programmatically. Adding timestamps would break those existing integrations.
You have options: If you need timestamp instrumentation for your builds, this article (https://support.circleci.com/hc/en-us/articles/31116144542107-Adding-Timestamps-to-Commands-in-CircleCI) highlights 4 different methods which can be re-used across commands.

If that doesn't work for you, let us know what specific problem you are trying to solve that the article doesn't address. If there's something we've missed in our reasoning, we're open to hearing it.

Matthew Bush

Kevin Tse I'm disappointed to see you declining this feature request. All three of your stated justifications ring hollow. 
> We want to preserve your control:
So make it an opt-in parameter to the configuration yaml that defaults to false. 
> We want to protect existing workflows:
Yes, this is important. That's why it should be opt-in with a default that preserves existing behavior. That's not a justification to skip the feature entirely.
> You have options:
Those methods all amount to "You can make your CI job do anything you want as long as you write the code to do so". They're all workarounds with some combination of disadvantages like
* You have to remember to include them each time
* They make the CI config harder to read and understand
* They don't work when running orbs
I'd phrase the specific problem as:
> As a platform engineer responsible for maintaining complex CI job configurations across multiple repositories and demonstrating replicatable best practices to my colleagues, I want a simple
 way to enable timestamps on every log line, in some sort of configurable format with a sensible default, so that I can use the logs to optimize the job configuration, or debug problems. 
The timestamps could either be inline with the logs, or as some sort of metadata associated with each log line, although I suspect the latter option would be quite difficult to implement.

Peter Darton

I think you've misunderstood the request entirely.
Nobody is asking for less control over log output; quite the opposite.
We're not asking CircleCI to _modify_ the plain-text logs and insert timestamps into that data in a manner than renders it inseperable, we're asking for extra metadata to be recorded so we know _when_ each line in those logs arrived.
e.g. the Jenkins timestamper doesn't remove control; the timestamps are metadata known for each line of text in the log. These timestamps can optionally
 be rendered in the UI to annotate the log, or omitted, 100% under the control of the user _viewing_ the logs.
i.e. the timestamps aren't _in_ the logs, they're metadata.
So the plain-text logs remain plain-text logs, but there's timestamp metadata that the UI can use when rendering that plain-text log to (optionally) show _when_ each line of the plain-text log arrived.
i.e. There need not be _any_ impact on existing workflows.
If you really want to "protect existing workflows" then telling people they need to re-write them as per "option" isn't the way to do that.
As far as "options" go, they're hideous.
I have burned days
 on this; it is far from as simple as the support article implies when juggling stdout, stderr and whereever "set -x" debug logging is going. Worse, one platform-agnostic implementation I used (just pure bash) resulted in crippling performance implications on Windows. Even worse, we then need an implementation for every scripting language used (we have a mix of bash and Powershell), making it highly platform-dependent.
So, yes, we're 100% "in control" ... but we resent having to take full manual control for something that would be so much more elegant if it were implemented on the CircleCI side of things; Jenkins (and every other CI system I've used) does this _so_ much better and easier.
As a build engineer, I just want to say what I want to be run; I expect my CI platform to run it and tell me _everything_ about what it did without me having to invent my own infrastructure to capture all these details.
TL;DR: It's _hard_ to do well within build code; it would be much better done on the CirlcleCI side of things, and there's no compelling reason why it would have to be a breaking change to do so.

Mark M. Spencer

This is a great suggestion, Jeff. Having automatic timestamping, especially with elapsed time, would significantly improve build log readability and debugging efficiency. How would this feature best integrate with existing CCI logging functionalities, without overly cluttering the output for simpler builds? It reminds me of the Dinosaur Game.

Jack

CircleCI, please implement this simple change!

kai zhang

It is already 5 years after this crazy fundamental idea was emerged to you, why is it still not implemented? It's essential for either long-time build debugging or build time optimization, when it turns to enterprise use case, it's very common that a big project runs on CircleCi, then timestamp is very basic information facilitating deep dive! And it's even generally implemented by your competitors!

Peter Darton

Having come from Jenkins, where I'd enabled Timerstamper globally, moving to CircleCI where no timestamps were shown anywhere felt like a massive downgrade.
I've lost count of the number of times that I've previously had to track down log entries across multiple systems (especially for security stuff), and having accurate timestamps is absolutely key to being able to do that.
CircleCI is just an information black hole by comparison to everything else.
IMO any automated system ought to make it obvious exactly when every step
 happened, and ideally when every line output from every step happened, otherwise you don't know which part of a job took much longer than normal.
TL;DR: This is a crazy functionality omission.

Alex Anderson

I'm really surprised this isn't built-in already - it's really helpful for optimising builds.

Ian Bone

@Nathan this would be a big help. Our workflow uses rebasing so the Git commit history reflects the merge time into our lower stages leaving us with no good way to precisely timestamp prod releases.

Tom H

Would love to have this. As a workaround, I'm currently piping build scripts through "ts" (part of "moreutils"):/path/to/my/script | ts

Jeff Minard

@Nathan: +1

Nathan Dintenfass

I'm adjusting the name of this to reflect how we would likely implement this if and when it makes the backlog.

→