Skip to content
This repository has been archived by the owner on Sep 5, 2019. It is now read-only.

Add pod start time #322

Merged
merged 9 commits into from
Sep 4, 2018
Merged

Add pod start time #322

Show file tree
Hide file tree
Changes from 8 commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
15e19d1
Rename startTime -> creationTime
Aug 29, 2018
d1755fe
add build actual start time to status
Aug 29, 2018
51ce7a1
Add comments and fix tests
Aug 29, 2018
abee971
Refactor start time function
Aug 29, 2018
7acaead
Fix error msgs
Aug 29, 2018
6958950
Update test setup
Aug 29, 2018
4be4746
Remove unnecessary test setup for timeout
Aug 29, 2018
8faf9d1
Add example with bad node selector
Aug 29, 2018
23eab08
Address comments
Sep 4, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
186 changes: 21 additions & 165 deletions Gopkg.lock
View file
Open in desktop

Large diffs are not rendered by default.

6 changes: 4 additions & 2 deletions pkg/apis/build/v1alpha1/build_types.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -189,7 +189,9 @@ type BuildStatus struct {
// Google provides additional information if the builder is Google.
Google *GoogleSpec `json:"google,omitempty"`

// StartTime is the time the build started.
// Creation is the time the build is created.
CreationTime metav1.Time `json:"creationTime,omitEmpty"`
// StartTime is the time the build is actually started.
StartTime metav1.Time `json:"startTime,omitEmpty"`
// CompletionTime is the time the build completed.
CompletionTime metav1.Time `json:"completionTime,omitEmpty"`
Expand All @@ -198,7 +200,7 @@ type BuildStatus struct {
StepStates []corev1.ContainerState `json:"stepStates,omitEmpty"`
// Conditions describes the set of conditions of this build.
Conditions []BuildCondition `json:"conditions,omitempty"`

// StepsCompleted lists the name of build steps completed.
StepsCompleted []string `json:"stepsCompleted"`
}

Expand Down
1 change: 1 addition & 0 deletions pkg/apis/build/v1alpha1/zz_generated.deepcopy.go
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

36 changes: 25 additions & 11 deletions pkg/builder/cluster/builder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,16 +21,16 @@ import (
"fmt"
"sync"

v1alpha1 "github.com/knative/build/pkg/apis/build/v1alpha1"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we separate these first-party imports (anything from knative/build) from the vendored imports from other packages?

buildercommon "github.com/knative/build/pkg/builder"
"github.com/knative/build/pkg/builder/cluster/convert"
"go.uber.org/zap"
corev1 "k8s.io/api/core/v1"
"k8s.io/apimachinery/pkg/api/errors"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
kubeinformers "k8s.io/client-go/informers"
"k8s.io/client-go/kubernetes"
"k8s.io/client-go/tools/cache"

v1alpha1 "github.com/knative/build/pkg/apis/build/v1alpha1"
buildercommon "github.com/knative/build/pkg/builder"
"github.com/knative/build/pkg/builder/cluster/convert"
)

type operation struct {
Expand All @@ -52,7 +52,8 @@ func (op *operation) Checkpoint(status *v1alpha1.BuildStatus) error {
}
status.Cluster.Namespace = op.namespace
status.Cluster.PodName = op.Name()
status.StartTime = op.startTime
status.CreationTime = op.startTime
status.StartTime = op.builder.podCreationTime
status.StepStates = nil
status.StepsCompleted = nil
for _, s := range op.statuses {
Expand All @@ -70,7 +71,17 @@ func (op *operation) Checkpoint(status *v1alpha1.BuildStatus) error {
}

func (op *operation) Terminate() error {
return op.builder.kubeclient.CoreV1().Pods(op.namespace).Delete(op.name, &metav1.DeleteOptions{})
if err := op.builder.kubeclient.CoreV1().Pods(op.namespace).Delete(op.name, &metav1.DeleteOptions{}); err != nil && !errors.IsNotFound(err) {
return err
}
return nil
}

func getStartTime(m *metav1.Time) metav1.Time {
if m == nil {
return metav1.Time{}
}
return *m
}

func (op *operation) Wait() (*v1alpha1.BuildStatus, error) {
Expand Down Expand Up @@ -101,7 +112,8 @@ func (op *operation) Wait() (*v1alpha1.BuildStatus, error) {
Namespace: op.namespace,
PodName: op.Name(),
},
StartTime: op.startTime,
CreationTime: op.startTime,
StartTime: op.builder.podCreationTime,
CompletionTime: metav1.Now(),
StepStates: states,
StepsCompleted: stepsCompleted,
Expand Down Expand Up @@ -177,8 +189,9 @@ type builder struct {
// send a completion notification when we see that Pod complete.
// On success, an empty string is sent.
// On failure, the Message of the failure PodCondition is sent.
callbacks map[string]chan *corev1.Pod
logger *zap.SugaredLogger
callbacks map[string]chan *corev1.Pod
logger *zap.SugaredLogger
podCreationTime metav1.Time
}

func (b *builder) Builder() v1alpha1.BuildProvider {
Expand Down Expand Up @@ -212,12 +225,12 @@ func (b *builder) OperationFromStatus(status *v1alpha1.BuildStatus) (buildercomm
for _, state := range status.StepStates {
statuses = append(statuses, corev1.ContainerStatus{State: state})
}

b.podCreationTime = status.CreationTime
return &operation{
builder: b,
namespace: status.Cluster.Namespace,
name: status.Cluster.PodName,
startTime: status.StartTime,
startTime: status.CreationTime,
statuses: statuses,
}, nil
}
Expand Down Expand Up @@ -253,6 +266,7 @@ func (b *builder) addPodEvent(obj interface{}) {
b.mux.Lock()
defer b.mux.Unlock()
key := getKey(pod.Namespace, pod.Name)
b.podCreationTime = getStartTime(pod.Status.StartTime)

if ch, ok := b.callbacks[key]; ok {
// Send the person listening the message.
Expand Down
64 changes: 49 additions & 15 deletions pkg/builder/cluster/builder_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,12 +67,15 @@ func TestBasicFlow(t *testing.T) {
if buildercommon.IsDone(&bs) {
t.Errorf("IsDone(%v); wanted not done, got done.", bs)
}
if bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
if bs.CreationTime.IsZero() {
t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
}
if !bs.CompletionTime.IsZero() {
t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
}
if !bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
}
op, err = builder.OperationFromStatus(&bs)
if err != nil {
t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
Expand Down Expand Up @@ -101,11 +104,14 @@ func TestBasicFlow(t *testing.T) {
if msg, failed := buildercommon.ErrorMessage(status); failed {
t.Errorf("ErrorMessage(%v); wanted not failed, got %q", status, msg)
}
if status.CompletionTime.IsZero() {
t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
}
if status.StartTime.IsZero() {
t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
}
if status.CompletionTime.IsZero() {
t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
if status.CreationTime.IsZero() {
t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
}
}()
// Wait until the test thread is ready for us to update things.
Expand All @@ -117,6 +123,8 @@ func TestBasicFlow(t *testing.T) {
if err != nil {
t.Fatalf("Unexpected error fetching Pod: %v", err)
}
pod.Status.StartTime = &metav1.Time{Time: time.Now()}

// Now modify it to look done.
pod.Status.Phase = corev1.PodSucceeded
pod, err = podsclient.Update(pod)
Expand Down Expand Up @@ -162,12 +170,15 @@ func TestNonFinalUpdateFlow(t *testing.T) {
if buildercommon.IsDone(&bs) {
t.Errorf("IsDone(%v); wanted not done, got done.", bs)
}
if bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
if bs.CreationTime.IsZero() {
t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
}
if !bs.CompletionTime.IsZero() {
t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
}
if !bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
}
op, err = builder.OperationFromStatus(&bs)
if err != nil {
t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
Expand All @@ -185,8 +196,8 @@ func TestNonFinalUpdateFlow(t *testing.T) {
if err != nil {
t.Fatalf("Unexpected error waiting for builder.Operation: %v", err)
}
if status.StartTime.IsZero() {
t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
if status.CreationTime.IsZero() {
t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
}
if status.CompletionTime.IsZero() {
t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
Expand All @@ -203,6 +214,8 @@ func TestNonFinalUpdateFlow(t *testing.T) {
}
// Make a non-terminal modification
pod.Status.Phase = corev1.PodRunning
pod.Status.StartTime = &metav1.Time{Time: time.Now()}

pod, err = podsclient.Update(pod)
if err != nil {
t.Fatalf("Unexpected error updating Pod: %v", err)
Expand Down Expand Up @@ -254,12 +267,15 @@ func TestFailureFlow(t *testing.T) {
if buildercommon.IsDone(&bs) {
t.Errorf("IsDone(%v); wanted not done, got done.", bs)
}
if bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
if bs.CreationTime.IsZero() {
t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
}
if !bs.CompletionTime.IsZero() {
t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
}
if !bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
}
op, err = builder.OperationFromStatus(&bs)
if err != nil {
t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
Expand Down Expand Up @@ -288,12 +304,15 @@ func TestFailureFlow(t *testing.T) {
if msg, failed := buildercommon.ErrorMessage(status); !failed || msg != expectedErrorMessage {
t.Errorf("ErrorMessage(%v); wanted %q, got %q", status, expectedErrorMessage, msg)
}
if status.StartTime.IsZero() {
t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
if status.CreationTime.IsZero() {
t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
}
if status.CompletionTime.IsZero() {
t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
}
if status.StartTime.IsZero() {
t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
}
if len(status.StepStates) != 1 {
t.Errorf("StepStates contained %d states, want 1: %+v", len(status.StepStates), status.StepStates)
} else if status.StepStates[0].Terminated.Reason != expectedErrorReason {
Expand All @@ -319,6 +338,7 @@ func TestFailureFlow(t *testing.T) {
},
},
}}
pod.Status.StartTime = &metav1.Time{Time: time.Now()}
pod, err = podsclient.Update(pod)
if err != nil {
t.Fatalf("Unexpected error updating Pod: %v", err)
Expand Down Expand Up @@ -352,12 +372,15 @@ func TestPodPendingFlow(t *testing.T) {
if buildercommon.IsDone(&bs) {
t.Errorf("IsDone(%v); wanted not done, got done.", bs)
}
if bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
if bs.CreationTime.IsZero() {
t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
}
if !bs.CompletionTime.IsZero() {
t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
}
if !bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
}
op, err = builder.OperationFromStatus(&bs)
if err != nil {
t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
Expand Down Expand Up @@ -386,6 +409,9 @@ func TestPodPendingFlow(t *testing.T) {
if msg := statusMessage(status); msg != expectedPendingMsg {
t.Errorf("ErrorMessage(%v); wanted %q, got %q", status, expectedPendingMsg, msg)
}
if status.CreationTime.IsZero() {
t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
}
if status.StartTime.IsZero() {
t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
}
Expand Down Expand Up @@ -418,6 +444,7 @@ func TestPodPendingFlow(t *testing.T) {
},
},
}}
pod.Status.StartTime = &metav1.Time{Time: time.Now()}
pod, err = podsclient.Update(pod)
if err != nil {
t.Fatalf("Unexpected error updating Pod: %v", err)
Expand Down Expand Up @@ -459,7 +486,10 @@ func TestStepFailureFlow(t *testing.T) {
if buildercommon.IsDone(&bs) {
t.Errorf("IsDone(%v); wanted not done, got done.", bs)
}
if bs.StartTime.IsZero() {
if bs.CreationTime.IsZero() {
t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
}
if !bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
}
if !bs.CompletionTime.IsZero() {
Expand Down Expand Up @@ -495,6 +525,9 @@ func TestStepFailureFlow(t *testing.T) {
!strings.Contains(msg, `"step-name"`) || !strings.Contains(msg, "128") {
t.Errorf("ErrorMessage(%v); got %q, want %q", status, msg, expectedErrorMessage)
}
if status.CreationTime.IsZero() {
t.Errorf("status.CreationTime; got %v, want non-zero", status.CreationTime)
}
if status.StartTime.IsZero() {
t.Errorf("status.StartTime; got %v, want non-zero", status.StartTime)
}
Expand Down Expand Up @@ -523,6 +556,7 @@ func TestStepFailureFlow(t *testing.T) {
ImageID: "docker-pullable://ubuntu@sha256:deadbeef",
}}
pod.Status.Message = "don't expect this!"
pod.Status.StartTime = &metav1.Time{Time: time.Now()}

pod, err = podsclient.Update(pod)
if err != nil {
Expand Down
3 changes: 1 addition & 2 deletions pkg/builder/interface.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -92,8 +92,7 @@ func IsTimeout(status *v1alpha1.BuildStatus, buildTimeout string) bool {
return false
}
}

return time.Since(status.StartTime.Time).Seconds() > timeout.Seconds()
return time.Since(status.CreationTime.Time).Seconds() > timeout.Seconds()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Time spent scheduling the pod shouldn't count toward the build's timeout, should this consider status.StartTime instead of status.CreationTime ?

Unless we were thinking this would be a useful way to kill a build that was unschedulable, in which case we might need to introduce two separate timeouts.

In GCB we only enforce timeouts once the build starts, since it's not the user's fault if it takes us a long time to start their build. We've considered enforcing a timeout on queued time, but I don't think any user has asked for it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we don't enforce timeout for allocating resources then build will remain in pending state forever. I was planning to follow up with a PR to introduce another timeout for allocating resources(queue timeout). Probably default this timeout to 10min and user doesn't need to worry about using this.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, if that's on your radar for future changes that sounds good to me.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Created: #325 to follow up with changes discussed in this PR.

}

// ErrorMessage returns the error message from the status.
Expand Down
2 changes: 2 additions & 0 deletions pkg/builder/nop/builder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,7 @@ func (nb *operation) Checkpoint(status *v1alpha1.BuildStatus) error {
status.Google = &v1alpha1.GoogleSpec{}
}
status.Google.Operation = nb.Name()
status.CreationTime = startTime
status.StartTime = startTime
status.SetCondition(&v1alpha1.BuildCondition{
Type: v1alpha1.BuildSucceeded,
Expand All @@ -67,6 +68,7 @@ func (nb *operation) Wait() (*v1alpha1.BuildStatus, error) {
Google: &v1alpha1.GoogleSpec{
Operation: nb.Name(),
},
CreationTime: startTime,
StartTime: startTime,
CompletionTime: completionTime,
}
Expand Down
6 changes: 6 additions & 0 deletions pkg/builder/nop/builder_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -45,6 +45,9 @@ func TestBasicFlow(t *testing.T) {
if err != nil {
t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
}
if bs.CreationTime.IsZero() {
t.Errorf("bs.CreationTime; want non-zero, got %v", bs.CreationTime)
}
if bs.StartTime.IsZero() {
t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
}
Expand All @@ -67,6 +70,9 @@ func TestBasicFlow(t *testing.T) {
if msg, failed := buildercommon.ErrorMessage(status); failed {
t.Errorf("ErrorMessage(%v); wanted not failed, got %q", status, msg)
}
if status.CreationTime.IsZero() {
t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
}
if status.StartTime.IsZero() {
t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
}
Expand Down
12 changes: 5 additions & 7 deletions pkg/controller/build/controller_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,7 @@ func TestBasicFlows(t *testing.T) {
t.Errorf("error fetching build: %v", err)
}
// Update status to current time
first.Status.StartTime = metav1.Now()
first.Status.CreationTime = metav1.Now()

if builder.IsDone(&first.Status) {
t.Errorf("First IsDone(%d); wanted not done, got done.", idx)
Expand Down Expand Up @@ -232,12 +232,11 @@ func TestTimeoutFlows(t *testing.T) {
bldr := &nop.Builder{}

build := newBuild("test")
addBuffer, err := time.ParseDuration("10m")
buffer, err := time.ParseDuration("10m")
if err != nil {
t.Errorf("Error parsing duration")
}

build.Status.StartTime.Time = metav1.Now().Time.Add(-addBuffer)
build.Spec.Timeout = "1s"

f := &fixture{
Expand Down Expand Up @@ -268,10 +267,9 @@ func TestTimeoutFlows(t *testing.T) {
if err != nil {
t.Errorf("error fetching build: %v", err)
}
// Update status to current time
// first.Status.StartTime = metav1.Now()
first.Status.StartTime.Time = metav1.Now().Time.Add(-addBuffer)
first.Spec.Timeout = "1s"

// Update status to past time by substracting buffer time
first.Status.CreationTime.Time = metav1.Now().Time.Add(-buffer)

if builder.IsDone(&first.Status) {
t.Error("First IsDone; wanted not done, got done.")
Expand Down
Loading