Skip to content

Commit 48cb3b2

Browse files
k8s-ci-robotk8s-ci-robot
authored
Merge pull request kubernetes#94850 from SataQiu/structed-log-20200917
Using structured logging in scheduler framework runtime
2 parents 2d9a0b6 + 47c58c3 commit 48cb3b2

File tree

4 files changed

+65
-67
lines changed

4 files changed

+65
-67
lines changed

‎pkg/scheduler/core/generic_scheduler_test.go‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ package core
1818

1919
import (
2020
"context"
21+
"errors"
2122
"fmt"
2223
"math"
2324
"strconv"
@@ -512,7 +513,7 @@ func TestGenericScheduler(t *testing.T) {
512513
nodes: []string{"2", "1"},
513514
pod: &v1.Pod{ObjectMeta: metav1.ObjectMeta{Name: "2"}},
514515
name: "test error with priority map",
515-
wErr: fmt.Errorf("error while running score plugin for pod \"2\": %+v", errPrioritize),
516+
wErr: fmt.Errorf("running Score plugins: %w", fmt.Errorf(`plugin "FalseMap" failed with: %w`, errPrioritize)),
516517
},
517518
{
518519
name: "test podtopologyspread plugin - 2 nodes with maxskew=1",
@@ -721,7 +722,7 @@ func TestGenericScheduler(t *testing.T) {
721722
nodes: []string{"1", "2"},
722723
pod: &v1.Pod{ObjectMeta: metav1.ObjectMeta{Name: "test-prefilter", UID: types.UID("test-prefilter")}},
723724
expectedHosts: nil,
724-
wErr: fmt.Errorf(`prefilter plugin "FakePreFilter" failed for pod "test-prefilter": injected error status`),
725+
wErr: fmt.Errorf(`running PreFilter plugin "FakePreFilter": %w`, errors.New("injected error status")),
725726
},
726727
}
727728
for _, test := range tests {

‎pkg/scheduler/framework/runtime/framework.go‎

Lines changed: 38 additions & 42 deletions
Original file line numberDiff line numberDiff line change
@@ -273,7 +273,7 @@ func NewFramework(r Registry, plugins *config.Plugins, args []config.PluginConfi
273273
}
274274
p, err := factory(args, f)
275275
if err != nil {
276-
return nil, fmt.Errorf("error initializing plugin %q: %v", name, err)
276+
return nil, fmt.Errorf("initializing plugin %q: %w", name, err)
277277
}
278278
pluginsMap[name] = p
279279

@@ -397,9 +397,9 @@ func (f *frameworkImpl) RunPreFilterPlugins(ctx context.Context, state *framewor
397397
if status.IsUnschedulable() {
398398
return status
399399
}
400-
msg := fmt.Sprintf("prefilter plugin %q failed for pod %q: %v", pl.Name(), pod.Name, status.Message())
401-
klog.Error(msg)
402-
return framework.NewStatus(framework.Error, msg)
400+
err := status.AsError()
401+
klog.ErrorS(err, "Failed running PreFilter plugin", "plugin", pl.Name(), "pod", klog.KObj(pod))
402+
return framework.AsStatus(fmt.Errorf("running PreFilter plugin %q: %w", pl.Name(), err))
403403
}
404404
}
405405

@@ -432,10 +432,9 @@ func (f *frameworkImpl) RunPreFilterExtensionAddPod(
432432
}
433433
status = f.runPreFilterExtensionAddPod(ctx, pl, state, podToSchedule, podToAdd, nodeInfo)
434434
if !status.IsSuccess() {
435-
msg := fmt.Sprintf("error while running AddPod for plugin %q while scheduling pod %q: %v",
436-
pl.Name(), podToSchedule.Name, status.Message())
437-
klog.Error(msg)
438-
return framework.NewStatus(framework.Error, msg)
435+
err := status.AsError()
436+
klog.ErrorS(err, "Failed running AddPod on PreFilter plugin", "plugin", pl.Name(), "pod", klog.KObj(podToSchedule))
437+
return framework.AsStatus(fmt.Errorf("running AddPod on PreFilter plugin %q: %w", pl.Name(), err))
439438
}
440439
}
441440

@@ -468,10 +467,9 @@ func (f *frameworkImpl) RunPreFilterExtensionRemovePod(
468467
}
469468
status = f.runPreFilterExtensionRemovePod(ctx, pl, state, podToSchedule, podToRemove, nodeInfo)
470469
if !status.IsSuccess() {
471-
msg := fmt.Sprintf("error while running RemovePod for plugin %q while scheduling pod %q: %v",
472-
pl.Name(), podToSchedule.Name, status.Message())
473-
klog.Error(msg)
474-
return framework.NewStatus(framework.Error, msg)
470+
err := status.AsError()
471+
klog.ErrorS(err, "Failed running RemovePod on PreFilter plugin", "plugin", pl.Name(), "pod", klog.KObj(podToSchedule))
472+
return framework.AsStatus(fmt.Errorf("running RemovePod on PreFilter plugin %q: %w", pl.Name(), err))
475473
}
476474
}
477475

@@ -577,9 +575,9 @@ func (f *frameworkImpl) RunPreScorePlugins(
577575
for _, pl := range f.preScorePlugins {
578576
status = f.runPreScorePlugin(ctx, pl, state, pod, nodes)
579577
if !status.IsSuccess() {
580-
msg := fmt.Sprintf("error while running %q prescore plugin for pod %q: %v", pl.Name(), pod.Name, status.Message())
581-
klog.Error(msg)
582-
return framework.NewStatus(framework.Error, msg)
578+
err := status.AsError()
579+
klog.ErrorS(err, "Failed running PreScore plugin", "plugin", pl.Name(), "pod", klog.KObj(pod))
580+
return framework.AsStatus(fmt.Errorf("running PreScore plugin %q: %w", pl.Name(), err))
583581
}
584582
}
585583

@@ -618,7 +616,8 @@ func (f *frameworkImpl) RunScorePlugins(ctx context.Context, state *framework.Cy
618616
nodeName := nodes[index].Name
619617
s, status := f.runScorePlugin(ctx, pl, state, pod, nodeName)
620618
if !status.IsSuccess() {
621-
errCh.SendErrorWithCancel(fmt.Errorf(status.Message()), cancel)
619+
err := fmt.Errorf("plugin %q failed with: %w", pl.Name(), status.AsError())
620+
errCh.SendErrorWithCancel(err, cancel)
622621
return
623622
}
624623
pluginToNodeScores[pl.Name()][index] = framework.NodeScore{
@@ -628,9 +627,8 @@ func (f *frameworkImpl) RunScorePlugins(ctx context.Context, state *framework.Cy
628627
}
629628
})
630629
if err := errCh.ReceiveError(); err != nil {
631-
msg := fmt.Sprintf("error while running score plugin for pod %q: %v", pod.Name, err)
632-
klog.Error(msg)
633-
return nil, framework.NewStatus(framework.Error, msg)
630+
klog.ErrorS(err, "Failed running Score plugins", "pod", klog.KObj(pod))
631+
return nil, framework.AsStatus(fmt.Errorf("running Score plugins: %w", err))
634632
}
635633

636634
// Run NormalizeScore method for each ScorePlugin in parallel.
@@ -642,15 +640,14 @@ func (f *frameworkImpl) RunScorePlugins(ctx context.Context, state *framework.Cy
642640
}
643641
status := f.runScoreExtension(ctx, pl, state, pod, nodeScoreList)
644642
if !status.IsSuccess() {
645-
err := fmt.Errorf("normalize score plugin %q failed with error %v", pl.Name(), status.Message())
643+
err := fmt.Errorf("plugin %q failed with: %w", pl.Name(), status.AsError())
646644
errCh.SendErrorWithCancel(err, cancel)
647645
return
648646
}
649647
})
650648
if err := errCh.ReceiveError(); err != nil {
651-
msg := fmt.Sprintf("error while running normalize score plugin for pod %q: %v", pod.Name, err)
652-
klog.Error(msg)
653-
return nil, framework.NewStatus(framework.Error, msg)
649+
klog.ErrorS(err, "Failed running Normalize on Score plugins", "pod", klog.KObj(pod))
650+
return nil, framework.AsStatus(fmt.Errorf("running Normalize on Score plugins: %w", err))
654651
}
655652

656653
// Apply score defaultWeights for each ScorePlugin in parallel.
@@ -663,17 +660,16 @@ func (f *frameworkImpl) RunScorePlugins(ctx context.Context, state *framework.Cy
663660
for i, nodeScore := range nodeScoreList {
664661
// return error if score plugin returns invalid score.
665662
if nodeScore.Score > framework.MaxNodeScore || nodeScore.Score < framework.MinNodeScore {
666-
err := fmt.Errorf("score plugin %q returns an invalid score %v, it should in the range of [%v, %v] after normalizing", pl.Name(), nodeScore.Score, framework.MinNodeScore, framework.MaxNodeScore)
663+
err := fmt.Errorf("plugin %q returns an invalid score %v, it should in the range of [%v, %v] after normalizing", pl.Name(), nodeScore.Score, framework.MinNodeScore, framework.MaxNodeScore)
667664
errCh.SendErrorWithCancel(err, cancel)
668665
return
669666
}
670667
nodeScoreList[i].Score = nodeScore.Score * int64(weight)
671668
}
672669
})
673670
if err := errCh.ReceiveError(); err != nil {
674-
msg := fmt.Sprintf("error while applying score defaultWeights for pod %q: %v", pod.Name, err)
675-
klog.Error(msg)
676-
return nil, framework.NewStatus(framework.Error, msg)
671+
klog.ErrorS(err, "Failed applying score defaultWeights on Score plugins", "pod", klog.KObj(pod))
672+
return nil, framework.AsStatus(fmt.Errorf("applying score defaultWeights on Score plugins: %w", err))
677673
}
678674

679675
return pluginToNodeScores, nil
@@ -710,9 +706,9 @@ func (f *frameworkImpl) RunPreBindPlugins(ctx context.Context, state *framework.
710706
for _, pl := range f.preBindPlugins {
711707
status = f.runPreBindPlugin(ctx, pl, state, pod, nodeName)
712708
if !status.IsSuccess() {
713-
err := fmt.Errorf("error while running %q prebind plugin for pod %q: %w", pl.Name(), pod.Name, status.AsError())
714-
klog.Error(err)
715-
return framework.AsStatus(err)
709+
err := status.AsError()
710+
klog.ErrorS(err, "Failed running PreBind plugin", "plugin", pl.Name(), "pod", klog.KObj(pod))
711+
return framework.AsStatus(fmt.Errorf("running PreBind plugin %q: %w", pl.Name(), err))
716712
}
717713
}
718714
return nil
@@ -743,9 +739,9 @@ func (f *frameworkImpl) RunBindPlugins(ctx context.Context, state *framework.Cyc
743739
continue
744740
}
745741
if !status.IsSuccess() {
746-
err := fmt.Errorf("plugin %q failed to bind pod \"%v/%v\": %w", bp.Name(), pod.Namespace, pod.Name, status.AsError())
747-
klog.Error(err)
748-
return framework.AsStatus(err)
742+
err := status.AsError()
743+
klog.ErrorS(err, "Failed running Bind plugin", "plugin", bp.Name(), "pod", klog.KObj(pod))
744+
return framework.AsStatus(fmt.Errorf("running Bind plugin %q: %w", bp.Name(), err))
749745
}
750746
return status
751747
}
@@ -796,9 +792,9 @@ func (f *frameworkImpl) RunReservePluginsReserve(ctx context.Context, state *fra
796792
for _, pl := range f.reservePlugins {
797793
status = f.runReservePluginReserve(ctx, pl, state, pod, nodeName)
798794
if !status.IsSuccess() {
799-
msg := fmt.Sprintf("error while running Reserve in %q reserve plugin for pod %q: %v", pl.Name(), pod.Name, status.Message())
800-
klog.Error(msg)
801-
return framework.NewStatus(framework.Error, msg)
795+
err := status.AsError()
796+
klog.ErrorS(err, "Failed running Reserve plugin", "plugin", pl.Name(), "pod", klog.KObj(pod))
797+
return framework.AsStatus(fmt.Errorf("running Reserve plugin %q: %w", pl.Name(), err))
802798
}
803799
}
804800
return nil
@@ -867,9 +863,9 @@ func (f *frameworkImpl) RunPermitPlugins(ctx context.Context, state *framework.C
867863
pluginsWaitTime[pl.Name()] = timeout
868864
statusCode = framework.Wait
869865
} else {
870-
msg := fmt.Sprintf("error while running %q permit plugin for pod %q: %v", pl.Name(), pod.Name, status.Message())
871-
klog.Error(msg)
872-
return framework.NewStatus(framework.Error, msg)
866+
err := status.AsError()
867+
klog.ErrorS(err, "Failed running Permit plugin", "plugin", pl.Name(), "pod", klog.KObj(pod))
868+
return framework.AsStatus(fmt.Errorf("running Permit plugin %q: %w", pl.Name(), err))
873869
}
874870
}
875871
}
@@ -912,9 +908,9 @@ func (f *frameworkImpl) WaitOnPermit(ctx context.Context, pod *v1.Pod) (status *
912908
klog.V(4).Infof(msg)
913909
return framework.NewStatus(s.Code(), msg)
914910
}
915-
msg := fmt.Sprintf("error received while waiting on permit for pod %q: %v", pod.Name, s.Message())
916-
klog.Error(msg)
917-
return framework.NewStatus(framework.Error, msg)
911+
err := s.AsError()
912+
klog.ErrorS(err, "Failed waiting on permit for pod", "pod", klog.KObj(pod))
913+
return framework.AsStatus(fmt.Errorf("waiting on permit for pod: %w", err))
918914
}
919915
return nil
920916
}

‎pkg/scheduler/framework/runtime/framework_test.go‎

Lines changed: 18 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -346,6 +346,8 @@ var nodes = []*v1.Node{
346346
{ObjectMeta: metav1.ObjectMeta{Name: "node2"}},
347347
}
348348

349+
var errInjectedStatus = errors.New("injected status")
350+
349351
func newFrameworkWithQueueSortAndBind(r Registry, pl *config.Plugins, plc []config.PluginConfig, opts ...Option) (v1alpha1.Framework, error) {
350352
if _, ok := r[queueSortPlugin]; !ok {
351353
r[queueSortPlugin] = newQueueSortPlugin
@@ -1139,7 +1141,6 @@ func TestPostFilterPlugins(t *testing.T) {
11391141
}
11401142

11411143
func TestPreBindPlugins(t *testing.T) {
1142-
injectedStatusErr := errors.New("injected status")
11431144
tests := []struct {
11441145
name string
11451146
plugins []*TestPlugin
@@ -1168,7 +1169,7 @@ func TestPreBindPlugins(t *testing.T) {
11681169
inj: injectedResult{PreBindStatus: int(v1alpha1.Unschedulable)},
11691170
},
11701171
},
1171-
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`error while running "TestPlugin" prebind plugin for pod "": %w`, injectedStatusErr)),
1172+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running PreBind plugin "TestPlugin": %w`, errInjectedStatus)),
11721173
},
11731174
{
11741175
name: "ErrorPreBindPlugin",
@@ -1178,7 +1179,7 @@ func TestPreBindPlugins(t *testing.T) {
11781179
inj: injectedResult{PreBindStatus: int(v1alpha1.Error)},
11791180
},
11801181
},
1181-
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`error while running "TestPlugin" prebind plugin for pod "": %w`, injectedStatusErr)),
1182+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running PreBind plugin "TestPlugin": %w`, errInjectedStatus)),
11821183
},
11831184
{
11841185
name: "UnschedulablePreBindPlugin",
@@ -1188,7 +1189,7 @@ func TestPreBindPlugins(t *testing.T) {
11881189
inj: injectedResult{PreBindStatus: int(v1alpha1.UnschedulableAndUnresolvable)},
11891190
},
11901191
},
1191-
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`error while running "TestPlugin" prebind plugin for pod "": %w`, injectedStatusErr)),
1192+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running PreBind plugin "TestPlugin": %w`, errInjectedStatus)),
11921193
},
11931194
{
11941195
name: "SuccessErrorPreBindPlugins",
@@ -1202,7 +1203,7 @@ func TestPreBindPlugins(t *testing.T) {
12021203
inj: injectedResult{PreBindStatus: int(v1alpha1.Error)},
12031204
},
12041205
},
1205-
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`error while running "TestPlugin 1" prebind plugin for pod "": %w`, injectedStatusErr)),
1206+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running PreBind plugin "TestPlugin 1": %w`, errInjectedStatus)),
12061207
},
12071208
{
12081209
name: "ErrorSuccessPreBindPlugin",
@@ -1216,7 +1217,7 @@ func TestPreBindPlugins(t *testing.T) {
12161217
inj: injectedResult{PreBindStatus: int(v1alpha1.Success)},
12171218
},
12181219
},
1219-
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`error while running "TestPlugin" prebind plugin for pod "": %w`, injectedStatusErr)),
1220+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running PreBind plugin "TestPlugin": %w`, errInjectedStatus)),
12201221
},
12211222
{
12221223
name: "SuccessSuccessPreBindPlugin",
@@ -1244,7 +1245,7 @@ func TestPreBindPlugins(t *testing.T) {
12441245
inj: injectedResult{PreBindStatus: int(v1alpha1.Error)},
12451246
},
12461247
},
1247-
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`error while running "TestPlugin" prebind plugin for pod "": %w`, injectedStatusErr)),
1248+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running PreBind plugin "TestPlugin": %w`, errInjectedStatus)),
12481249
},
12491250
{
12501251
name: "UnschedulableAndSuccessPreBindPlugin",
@@ -1258,7 +1259,7 @@ func TestPreBindPlugins(t *testing.T) {
12581259
inj: injectedResult{PreBindStatus: int(v1alpha1.Success)},
12591260
},
12601261
},
1261-
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`error while running "TestPlugin" prebind plugin for pod "": %w`, injectedStatusErr)),
1262+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running PreBind plugin "TestPlugin": %w`, errInjectedStatus)),
12621263
},
12631264
}
12641265

@@ -1324,7 +1325,7 @@ func TestReservePlugins(t *testing.T) {
13241325
inj: injectedResult{ReserveStatus: int(v1alpha1.Unschedulable)},
13251326
},
13261327
},
1327-
wantStatus: v1alpha1.NewStatus(v1alpha1.Error, `error while running Reserve in "TestPlugin" reserve plugin for pod "": injected status`),
1328+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running Reserve plugin "TestPlugin": %w`, errInjectedStatus)),
13281329
},
13291330
{
13301331
name: "ErrorReservePlugin",
@@ -1334,7 +1335,7 @@ func TestReservePlugins(t *testing.T) {
13341335
inj: injectedResult{ReserveStatus: int(v1alpha1.Error)},
13351336
},
13361337
},
1337-
wantStatus: v1alpha1.NewStatus(v1alpha1.Error, `error while running Reserve in "TestPlugin" reserve plugin for pod "": injected status`),
1338+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running Reserve plugin "TestPlugin": %w`, errInjectedStatus)),
13381339
},
13391340
{
13401341
name: "UnschedulableReservePlugin",
@@ -1344,7 +1345,7 @@ func TestReservePlugins(t *testing.T) {
13441345
inj: injectedResult{ReserveStatus: int(v1alpha1.UnschedulableAndUnresolvable)},
13451346
},
13461347
},
1347-
wantStatus: v1alpha1.NewStatus(v1alpha1.Error, `error while running Reserve in "TestPlugin" reserve plugin for pod "": injected status`),
1348+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running Reserve plugin "TestPlugin": %w`, errInjectedStatus)),
13481349
},
13491350
{
13501351
name: "SuccessSuccessReservePlugins",
@@ -1372,7 +1373,7 @@ func TestReservePlugins(t *testing.T) {
13721373
inj: injectedResult{ReserveStatus: int(v1alpha1.Error)},
13731374
},
13741375
},
1375-
wantStatus: v1alpha1.NewStatus(v1alpha1.Error, `error while running Reserve in "TestPlugin" reserve plugin for pod "": injected status`),
1376+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running Reserve plugin "TestPlugin": %w`, errInjectedStatus)),
13761377
},
13771378
{
13781379
name: "SuccessErrorReservePlugins",
@@ -1386,7 +1387,7 @@ func TestReservePlugins(t *testing.T) {
13861387
inj: injectedResult{ReserveStatus: int(v1alpha1.Error)},
13871388
},
13881389
},
1389-
wantStatus: v1alpha1.NewStatus(v1alpha1.Error, `error while running Reserve in "TestPlugin 1" reserve plugin for pod "": injected status`),
1390+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running Reserve plugin "TestPlugin 1": %w`, errInjectedStatus)),
13901391
},
13911392
{
13921393
name: "ErrorSuccessReservePlugin",
@@ -1400,7 +1401,7 @@ func TestReservePlugins(t *testing.T) {
14001401
inj: injectedResult{ReserveStatus: int(v1alpha1.Success)},
14011402
},
14021403
},
1403-
wantStatus: v1alpha1.NewStatus(v1alpha1.Error, `error while running Reserve in "TestPlugin" reserve plugin for pod "": injected status`),
1404+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running Reserve plugin "TestPlugin": %w`, errInjectedStatus)),
14041405
},
14051406
{
14061407
name: "UnschedulableAndSuccessReservePlugin",
@@ -1414,7 +1415,7 @@ func TestReservePlugins(t *testing.T) {
14141415
inj: injectedResult{ReserveStatus: int(v1alpha1.Success)},
14151416
},
14161417
},
1417-
wantStatus: v1alpha1.NewStatus(v1alpha1.Error, `error while running Reserve in "TestPlugin" reserve plugin for pod "": injected status`),
1418+
wantStatus: v1alpha1.AsStatus(fmt.Errorf(`running Reserve plugin "TestPlugin": %w`, errInjectedStatus)),
14181419
},
14191420
}
14201421

@@ -1490,7 +1491,7 @@ func TestPermitPlugins(t *testing.T) {
14901491
inj: injectedResult{PermitStatus: int(v1alpha1.Error)},
14911492
},
14921493
},
1493-
want: v1alpha1.NewStatus(v1alpha1.Error, `error while running "TestPlugin" permit plugin for pod "": injected status`),
1494+
want: v1alpha1.AsStatus(fmt.Errorf(`running Permit plugin "TestPlugin": %w`, errInjectedStatus)),
14941495
},
14951496
{
14961497
name: "UnschedulableAndUnresolvablePermitPlugin",
@@ -1538,7 +1539,7 @@ func TestPermitPlugins(t *testing.T) {
15381539
inj: injectedResult{PermitStatus: int(v1alpha1.Error)},
15391540
},
15401541
},
1541-
want: v1alpha1.NewStatus(v1alpha1.Error, `error while running "TestPlugin" permit plugin for pod "": injected status`),
1542+
want: v1alpha1.AsStatus(fmt.Errorf(`running Permit plugin "TestPlugin": %w`, errInjectedStatus)),
15421543
},
15431544
}
15441545

0 commit comments

Comments
 (0)