apps: record cause of rollout and deployer pods timestamps back to rc #16347

mfojtik · 2017-09-14T12:38:26Z

This helps provide better metrics for deployment configs where we can report how much time the rollout took so in theory we can record times for last failed rollouts.

@Kargakis @tnozicka relatively simple change.

mfojtik · 2017-09-14T12:39:17Z

not sure if time.Now() is the best format or we want just report UNIX timestamps (actually I might be more happy with UNIX timestamps as you can do math with them without conversion)

smarterclayton · 2017-09-14T13:18:15Z

Generally we should be encoding times as RFC3339 whenever they go into apis On Sep 14, 2017, at 8:39 AM, Michal Fojtik <notifications@github.com> wrote: not sure if time.Now() is the best format or we want just report UNIX timestamps (actually I might be more happy with UNIX timestamps as you can do math with them without conversion) — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub <#16347 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABG_p3f2tIp7xgrO-4hh05GXx8b2SWgUks5siR54gaJpZM4PXg9Z> .

smarterclayton · 2017-09-14T13:20:11Z

pkg/apps/apis/apps/types.go

+	DeployerPodCreatedAtAnnotation = "openshift.io/deployer-pod.createdAt"
+	// DeployerPodFinishedAnnotation is an annotation on deployment that records
+	// the time of when the deploymer pod finished.
+	DeployerPodCompletedAtAnnotation = "openshift.io/deployer-pod.completedAt"


completed-at maybe. We're kind of inconsistent but no reason not to use dash

mfojtik · 2017-09-14T13:21:01Z

@smarterclayton if we encode RFC3339 to string, we need to decode, why we hate ourself?

mfojtik · 2017-09-14T13:26:07Z

@smarterclayton fixed. ptal

tnozicka · 2017-09-15T08:38:49Z

pkg/apps/apis/apps/types.go

+	// records the time of when the deployer pod for this particular
+	// deployment was created.
+	DeployerPodCreatedAtAnnotation = "openshift.io/deployer-pod.created-at"
+	// DeployerPodFinishedAnnotation is an annotation on deployment that records


s/DeployerPodFinishedAnnotation/DeployerPodCompletedAtAnnotation

tnozicka · 2017-09-15T08:39:04Z

pkg/apps/apis/apps/types.go

@@ -37,6 +37,13 @@ const (
 	// annotation value is the name of the deployer Pod which will act upon the ReplicationController
 	// to implement the deployment behavior.
 	DeploymentPodAnnotation = "openshift.io/deployer-pod.name"
+	// DeployerPodCreatedAnnotation is an annotation on a deployment that


s/DeployerPodCreatedAnnotation/DeployerPodCreatedAtAnnotation

tnozicka · 2017-09-15T08:40:54Z

pkg/apps/apis/apps/types.go

@@ -37,6 +37,13 @@ const (
 	// annotation value is the name of the deployer Pod which will act upon the ReplicationController
 	// to implement the deployment behavior.
 	DeploymentPodAnnotation = "openshift.io/deployer-pod.name"
+	// DeployerPodCreatedAnnotation is an annotation on a deployment that
+	// records the time of when the deployer pod for this particular


should we mention the time format here or is RFC3339 implied in our API in general?

tnozicka · 2017-09-15T08:46:57Z

pkg/apps/controller/deployer/deployer_controller.go

@@ -149,6 +150,7 @@ func (c *DeploymentController) handle(deployment *v1.ReplicationController, will
 				return actionableError(fmt.Sprintf("couldn't create deployer pod for %q: %v", deployutil.LabelForDeploymentV1(deployment), err))
 			}
 			updatedAnnotations[deployapi.DeploymentPodAnnotation] = deploymentPod.Name
+			updatedAnnotations[deployapi.DeployerPodCreatedAtAnnotation] = time.Now().Format(time.RFC3339)


This will get thrown away in case the update at the end fails on 409

not lost, on next reconcile we set this back

not if the deployer pod is missing (e.g. deleted manually) I think - you set it back when the pod is present only on L182

tnozicka · 2017-09-15T08:52:01Z

pkg/apps/controller/deployer/deployer_controller.go

@@ -294,10 +297,12 @@ func (c *DeploymentController) nextStatus(pod *v1.Pod, deployment *v1.Replicatio
 		// Sync the internal replica annotation with the target so that we can
 		// distinguish deployer updates from other scaling events.
 		updatedAnnotations[deployapi.DeploymentReplicasAnnotation] = updatedAnnotations[deployapi.DesiredReplicasAnnotation]
+		updatedAnnotations[deployapi.DeployerPodCompletedAtAnnotation] = time.Now().Format(time.RFC3339)


thrown away at 409, and since the pod will be deleted it won't get reconciled

it will be reconciled until we succeed updating the RC status, so eventually this will be set... there might be time skew if the reconciliation takes a long time, but the over deployment status won't be updated as well, so from the user PoC the deployment will seems like still progressing...

tnozicka

this is all edge driven and won't get reconciled. there will be states when one or both of those annotations are missing causing metrics weirdness and bugs to be filled

tnozicka · 2017-09-15T09:41:56Z

so the created state will be partially reconciled but overwritten at the same time at L181. (But I don't think this will reconcile a state when someone deletes the pod manually.)

The deletion won't be reconciled I think.

But the bigger issue arising seems to be the time that due to reconciliation might be off because you are using time.Now(). In the reconciliation cycle that might be even added after rate-limiting that might be significantly off.

One thing is that we might choose to not to write that time rather than be off and providing misleading data. The second is that we could use the real times in the informer we use to feed the deployer controller with pod events and use real times from pod filled in by kubelet. Yes, on a relist the informer might loose probably the delete event and we don't get the deleting timestamp but we could reconcile it in deployer controller and set value for it as it should be fairly rare and this way it won't create false positives in metrics.

tnozicka · 2017-09-15T10:24:49Z

I guess we should have 3 values to fully reason about it:

creationTimestamp (API object)
startedAt (pod)
finishedAt (pod)

mfojtik · 2017-09-15T11:57:02Z

/retest

mfojtik · 2017-09-15T12:01:03Z

@tnozicka having three timestamps seems unreasonable to me as we basically just want to measure how long the rollout takes, which is easy with 2 timestamps ;-) I don't think the time between the pod was created and container started matters that much.

tnozicka · 2017-09-15T12:02:51Z

@mfojtik in that case you need to use startedAt, not creation timestamp

mfojtik · 2017-09-15T12:03:12Z

i switched this to use creationtimestamp of the pod as created-at annotation and finishedTimestamp of the container that runs the deployer as completed-at.

So there is no time.Now() anymore. I really hate to have special routine in deployer controller that will be updating RC in parallel with the main routine that handle the rollout. That is basically asking for troubles.

mfojtik · 2017-09-15T12:04:23Z

@tnozicka the deployment process will fail when the container cannot be created right? in that case that RC will basically end up with no timestamps.

smarterclayton · 2017-09-15T14:28:28Z

Mfojtik you know that metav1.Time automatically handles RFC3339 for you right? And that's how we serialize all json times?

mfojtik · 2017-09-15T19:38:27Z

@smarterclayton yeah, i'm using it already ;-)

mfojtik · 2017-09-15T19:38:39Z

/retest

mfojtik · 2017-09-17T19:51:11Z

@tnozicka we are green, but I think i'm going to add some tests for this tomorrow

mfojtik · 2017-09-20T07:47:30Z

@smarterclayton @tnozicka is out this week, can you take a second look?

tnozicka · 2017-09-26T11:03:54Z

pkg/apps/apis/apps/types.go

+	// deployment was started.
+	DeployerPodStartedAtAnnotation = "openshift.io/deployer-pod.started-at"
+	// DeployerPodCompletedAtAnnotation is an annotation on deployment that records
+	// the time in RFC3339 format of when the deploymer pod finished.


s/deploymer/deployer/

tnozicka · 2017-09-26T11:07:59Z

pkg/apps/controller/deployer/deployer_controller.go

@@ -149,6 +149,10 @@ func (c *DeploymentController) handle(deployment *v1.ReplicationController, will
 				return actionableError(fmt.Sprintf("couldn't create deployer pod for %q: %v", deployutil.LabelForDeploymentV1(deployment), err))
 			}
 			updatedAnnotations[deployapi.DeploymentPodAnnotation] = deploymentPod.Name
+			updatedAnnotations[deployapi.DeployerPodCreatedAtAnnotation] = deploymentPod.CreationTimestamp.String()
+			if deploymentPod.Status.StartTime != nil {
+				updatedAnnotations[deployapi.DeployerPodCreatedAtAnnotation] = deploymentPod.Status.StartTime.String()


the annotation should be DeployerPodStartedAtAnnotation not DeployerPodCreatedAtAnnotation

tnozicka · 2017-09-26T11:11:05Z

pkg/apps/controller/deployer/deployer_controller.go

@@ -176,6 +180,10 @@ func (c *DeploymentController) handle(deployment *v1.ReplicationController, will
 			} else {
 				// Update to pending or to the appropriate status relative to the existing validated deployer pod.
 				updatedAnnotations[deployapi.DeploymentPodAnnotation] = deployer.Name
+				updatedAnnotations[deployapi.DeployerPodCreatedAtAnnotation] = deployer.CreationTimestamp.String()
+				if deployer.Status.StartTime != nil {
+					updatedAnnotations[deployapi.DeployerPodCreatedAtAnnotation] = deployer.Status.StartTime.String()


tnozicka

some comments, lgtm after they are addressed

tnozicka · 2017-09-26T11:22:31Z

Also let's state that those annotations are filled at best (or at least reasonable) effort and might not be present (or be incomplete) at rare cases which should not be considered bugs.

mfojtik · 2017-10-02T12:00:46Z

@tnozicka comments addressed, thanks!

tnozicka · 2017-10-02T12:30:57Z

pkg/apps/controller/deployer/deployer_controller.go

@@ -149,6 +149,10 @@ func (c *DeploymentController) handle(deployment *v1.ReplicationController, will
 				return actionableError(fmt.Sprintf("couldn't create deployer pod for %q: %v", deployutil.LabelForDeploymentV1(deployment), err))
 			}
 			updatedAnnotations[deployapi.DeploymentPodAnnotation] = deploymentPod.Name
+			updatedAnnotations[deployapi.DeployerPodStartedAtAnnotation] = deploymentPod.CreationTimestamp.String()


this one should be DeployerPodCreatedAtAnnotation, it was ok before

tnozicka · 2017-10-02T12:33:49Z

pkg/apps/controller/deployer/deployer_controller.go

@@ -176,6 +180,10 @@ func (c *DeploymentController) handle(deployment *v1.ReplicationController, will
 			} else {
 				// Update to pending or to the appropriate status relative to the existing validated deployer pod.
 				updatedAnnotations[deployapi.DeploymentPodAnnotation] = deployer.Name
+				updatedAnnotations[deployapi.DeployerPodStartedAtAnnotation] = deployer.CreationTimestamp.String()


this one should be DeployerPodCreatedAtAnnotation, it was ok before

brain fart, sorry. fixed.

tnozicka · 2017-10-02T13:41:46Z

/lgtm

openshift-merge-robot · 2017-10-02T13:41:57Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: mfojtik, tnozicka

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these OWNERS Files:

~~pkg/apps/OWNERS~~ [mfojtik]

You can indicate your approval by writing /approve in a comment
You can cancel your approval by writing /approve cancel in a comment

tnozicka · 2017-10-02T13:42:20Z

/retest

mfojtik · 2017-10-03T13:57:11Z

/kind bug

not having this in 3.7 means we can't build up better metrics in 3.8

openshift-merge-robot · 2017-10-03T13:57:17Z

/test all [submit-queue is verifying that this PR is safe to merge]

openshift-ci-robot · 2017-10-03T14:00:20Z

@mfojtik: The following test failed, say /retest to rerun them all:

Test name	Commit	Details	Rerun command
ci/openshift-jenkins/extended_conformance_install_update	`fb1679e`	link	`/test extended_conformance_install_update`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

openshift-merge-robot · 2017-10-03T15:41:37Z

Automatic merge from submit-queue (batch tested with PRs 16347, 16652).

openshift-ci-robot added the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Sep 14, 2017

openshift-merge-robot assigned smarterclayton and 0xmichalis Sep 14, 2017

openshift-merge-robot added approved Indicates a PR has been approved by an approver from all required OWNERS files. needs-api-review labels Sep 14, 2017

smarterclayton reviewed Sep 14, 2017

View reviewed changes

mfojtik force-pushed the record-dc-cause-to-rc branch from 6f46efa to 0268ee6 Compare September 14, 2017 13:25

mfojtik mentioned this pull request Sep 14, 2017

apps: add prometheus metrics for rollout #14796

Merged

tnozicka reviewed Sep 15, 2017

View reviewed changes

tnozicka self-requested a review September 15, 2017 08:45

tnozicka reviewed Sep 15, 2017

View reviewed changes

mfojtik force-pushed the record-dc-cause-to-rc branch from 0268ee6 to 43a2ba3 Compare September 15, 2017 09:38

mfojtik force-pushed the record-dc-cause-to-rc branch from 43a2ba3 to e56fd0a Compare September 15, 2017 10:10

mfojtik force-pushed the record-dc-cause-to-rc branch from e56fd0a to ac494ed Compare September 15, 2017 12:22

openshift-ci-robot removed the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Sep 15, 2017

tnozicka reviewed Sep 26, 2017

View reviewed changes

openshift-merge-robot added approved Indicates a PR has been approved by an approver from all required OWNERS files. and removed approved Indicates a PR has been approved by an approver from all required OWNERS files. labels Sep 28, 2017

mfojtik force-pushed the record-dc-cause-to-rc branch from ac494ed to 31c51ab Compare October 2, 2017 12:00

tnozicka reviewed Oct 2, 2017

View reviewed changes

apps: record cause of rollout and deployer pods timestamps back to rc

fb1679e

mfojtik force-pushed the record-dc-cause-to-rc branch from 31c51ab to fb1679e Compare October 2, 2017 12:57

openshift-ci-robot assigned tnozicka Oct 2, 2017

openshift-ci-robot added the lgtm Indicates that a PR is ready to be merged. label Oct 2, 2017

openshift-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Oct 3, 2017

openshift-merge-robot merged commit 813f39e into openshift:master Oct 3, 2017

mfojtik deleted the record-dc-cause-to-rc branch September 5, 2018 21:07

apps: record cause of rollout and deployer pods timestamps back to rc #16347

apps: record cause of rollout and deployer pods timestamps back to rc #16347

Conversation

mfojtik commented Sep 14, 2017

mfojtik commented Sep 14, 2017

smarterclayton commented Sep 14, 2017 via email

Choose a reason for hiding this comment

mfojtik commented Sep 14, 2017

mfojtik commented Sep 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tnozicka Sep 15, 2017 • edited Loading

Choose a reason for hiding this comment

tnozicka Sep 15, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tnozicka left a comment • edited Loading

Choose a reason for hiding this comment

tnozicka commented Sep 15, 2017

tnozicka commented Sep 15, 2017

mfojtik commented Sep 15, 2017

mfojtik commented Sep 15, 2017

tnozicka commented Sep 15, 2017

mfojtik commented Sep 15, 2017

mfojtik commented Sep 15, 2017

smarterclayton commented Sep 15, 2017 via email

mfojtik commented Sep 15, 2017

mfojtik commented Sep 15, 2017

mfojtik commented Sep 17, 2017

mfojtik commented Sep 20, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tnozicka left a comment

Choose a reason for hiding this comment

tnozicka commented Sep 26, 2017

mfojtik commented Oct 2, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tnozicka commented Oct 2, 2017

openshift-merge-robot commented Oct 2, 2017

tnozicka commented Oct 2, 2017

mfojtik commented Oct 3, 2017

openshift-merge-robot commented Oct 3, 2017

openshift-ci-robot commented Oct 3, 2017 • edited Loading

openshift-merge-robot commented Oct 3, 2017

tnozicka Sep 15, 2017 •

edited

Loading

tnozicka Sep 15, 2017 •

edited

Loading

tnozicka left a comment •

edited

Loading

openshift-ci-robot commented Oct 3, 2017 •

edited

Loading