Skip to content

Commit 24fc00c

Browse files
gyuhogyuho
committed
eks/conformance: improve logging
Signed-off-by: Gyuho Lee <leegyuho@amazon.com>
1 parent b0adb31 commit 24fc00c

File tree

4 files changed

+102
-27
lines changed

4 files changed

+102
-27
lines changed

‎CHANGELOG/CHANGELOG-1.2.md‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,12 @@
77

88
See [code changes](https://github.com/aws/aws-k8s-tester/compare/v1.2.4...v1.2.5).
99

10-
TODO
10+
### `eks`
11+
12+
- Cut [`eks/conformance` tail output to max 30-line](https://github.com/aws/aws-k8s-tester/commit/).
13+
- Set [`eks/conformance` `sonobuoy run --timeout`](https://github.com/aws/aws-k8s-tester/commit/).
14+
- Improve [`eks/conformance` log outputs](https://github.com/aws/aws-k8s-tester/commit/).
15+
- Update [`sonobuoy` version to `v0.18.2`](https://github.com/vmware-tanzu/sonobuoy/releases/tag/v0.18.2).
1116

1217
### Go
1318

‎eks/conformance/conformance.go‎

Lines changed: 82 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,8 @@ import (
2020
"github.com/dustin/go-humanize"
2121
"github.com/mholt/archiver/v3"
2222
"go.uber.org/zap"
23+
v1 "k8s.io/api/core/v1"
24+
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
2325
"k8s.io/utils/exec"
2426
)
2527

@@ -215,6 +217,7 @@ func (ts *tester) deleteSonobuoy() (err error) {
215217
}
216218

217219
func (ts *tester) runSonobuoy() (err error) {
220+
timeoutSeconds := int64(ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunTimeout.Seconds())
218221
args := []string{
219222
ts.cfg.EKSConfig.AddOnConformance.SonobuoyPath,
220223
"--logtostderr",
@@ -226,10 +229,16 @@ func (ts *tester) runSonobuoy() (err error) {
226229
"--mode=" + ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunMode,
227230
"--kube-conformance-image=" + ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunKubeConformanceImage,
228231
"--show-default-podspec=true",
232+
fmt.Sprintf("--timeout=%d", timeoutSeconds), // default "10800", 3-hour
229233
}
230234
cmd := strings.Join(args, " ")
231235

232-
ts.cfg.Logger.Info("running sonobuoy", zap.String("command", cmd))
236+
ts.cfg.Logger.Info("running sonobuoy",
237+
zap.Duration("timeout", ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunTimeout),
238+
zap.Int64("timeout-seconds", timeoutSeconds),
239+
zap.String("mode", ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunMode),
240+
zap.String("command", cmd),
241+
)
233242

234243
var output []byte
235244
ctx, cancel := context.WithTimeout(context.Background(), time.Minute) // do not wait, so just set timeout for launching tests
@@ -242,12 +251,55 @@ func (ts *tester) runSonobuoy() (err error) {
242251
}
243252
fmt.Printf("\n'%s' output:\n\n%s\n\n", cmd, out)
244253

245-
ts.cfg.Logger.Info("ran sonobuoy", zap.String("command", cmd))
254+
ts.cfg.Logger.Info("ran sonobuoy", zap.String("mode", ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunMode), zap.String("command", cmd))
246255
return nil
247256
}
248257

249258
func (ts *tester) checkSonobuoy() (err error) {
250-
argsLogs := []string{
259+
ts.cfg.Logger.Info("checking pod/sonobuoy-e2e-job")
260+
sonobuoyE2EJobPod := ""
261+
retryStart := time.Now()
262+
for time.Now().Sub(retryStart) < 10*time.Minute {
263+
select {
264+
case <-ts.cfg.Stopc:
265+
ts.cfg.Logger.Warn("sonobuoy check stopped")
266+
return nil
267+
case <-ts.cfg.Stopc:
268+
ts.cfg.Logger.Warn("sonobuoy check timeout")
269+
return fmt.Errorf("sonobuoy run took too long (exceeded %v)", ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunTimeout)
270+
case <-time.After(10 * time.Second):
271+
}
272+
273+
ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
274+
var pods *v1.PodList
275+
pods, err = ts.cfg.K8SClient.
276+
KubernetesClientSet().
277+
CoreV1().
278+
Pods(ts.cfg.EKSConfig.AddOnConformance.Namespace).
279+
List(ctx, metav1.ListOptions{})
280+
cancel()
281+
if err != nil {
282+
ts.cfg.Logger.Warn("failed to list pods", zap.Error(err))
283+
continue
284+
}
285+
286+
for _, pv := range pods.Items {
287+
ts.cfg.Logger.Info("found pod", zap.String("name", pv.GetName()))
288+
if strings.HasPrefix(pv.GetName(), "sonobuoy-e2e-job-") {
289+
sonobuoyE2EJobPod = pv.GetName()
290+
break
291+
}
292+
}
293+
if sonobuoyE2EJobPod != "" {
294+
break
295+
}
296+
}
297+
if sonobuoyE2EJobPod == "" {
298+
return fmt.Errorf("failed to find pod/sonobuoy-e2e-job in %q", ts.cfg.EKSConfig.AddOnConformance.Namespace)
299+
}
300+
ts.cfg.Logger.Info("found pod/sonobuoy-e2e-job", zap.String("name", sonobuoyE2EJobPod))
301+
302+
argsLogsSonobuoy := []string{
251303
ts.cfg.EKSConfig.AddOnConformance.SonobuoyPath,
252304
"--logtostderr",
253305
"--alsologtostderr",
@@ -256,7 +308,18 @@ func (ts *tester) checkSonobuoy() (err error) {
256308
"--kubeconfig=" + ts.cfg.EKSConfig.KubeConfigPath,
257309
"--namespace=" + ts.cfg.EKSConfig.AddOnConformance.Namespace,
258310
}
259-
cmdLogs := strings.Join(argsLogs, " ")
311+
cmdLogsSonobuoy := strings.Join(argsLogsSonobuoy, " ")
312+
313+
argsLogsPod := []string{
314+
ts.cfg.EKSConfig.KubectlPath,
315+
"--kubeconfig=" + ts.cfg.EKSConfig.KubeConfigPath,
316+
"--namespace=" + ts.cfg.EKSConfig.AddOnConformance.Namespace,
317+
"logs",
318+
fmt.Sprintf("pod/%s", sonobuoyE2EJobPod),
319+
"e2e",
320+
"--tail=30",
321+
}
322+
cmdLogsPod := strings.Join(argsLogsPod, " ")
260323

261324
argsStatus := []string{
262325
ts.cfg.EKSConfig.AddOnConformance.SonobuoyPath,
@@ -271,7 +334,8 @@ func (ts *tester) checkSonobuoy() (err error) {
271334
cmdStatus := strings.Join(argsStatus, " ")
272335

273336
ts.cfg.Logger.Info("running sonobuoy",
274-
zap.String("logs-command", cmdLogs),
337+
zap.String("logs-command-sonobuoy", cmdLogsSonobuoy),
338+
zap.String("logs-command-pod", cmdLogsPod),
275339
zap.String("status-command", cmdStatus),
276340
)
277341

@@ -280,12 +344,13 @@ func (ts *tester) checkSonobuoy() (err error) {
280344
start, waitDur := time.Now(), ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunTimeout
281345

282346
interval := 15 * time.Minute
283-
347+
cnt := 0
284348
for time.Now().Sub(start) < waitDur {
349+
cnt++
285350
ts.cfg.Logger.Info(
286351
"waiting for sonobuoy run",
287352
zap.Duration("interval", interval),
288-
zap.String("time", humanize.Time(deadline)),
353+
zap.String("deadline", humanize.Time(deadline)),
289354
zap.Duration("timeout", ts.cfg.EKSConfig.AddOnConformance.SonobuoyRunTimeout),
290355
)
291356
select {
@@ -298,20 +363,24 @@ func (ts *tester) checkSonobuoy() (err error) {
298363
case <-time.After(interval):
299364
}
300365

366+
argsLogs, cmdLogs := argsLogsSonobuoy, cmdLogsSonobuoy
367+
if cnt%2 == 0 {
368+
argsLogs, cmdLogs = argsLogsPod, cmdLogsPod
369+
}
301370
ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
302371
output, err := exec.New().CommandContext(ctx, argsLogs[0], argsLogs[1:]...).CombinedOutput()
303372
cancel()
304373
out := strings.TrimSpace(string(output))
305374
if err != nil {
306-
ts.cfg.Logger.Warn("failed to run sonobuoy logs", zap.String("command", cmdLogs), zap.Error(err))
375+
ts.cfg.Logger.Warn("failed to fetch sonobuoy logs", zap.String("command", cmdLogs), zap.Error(err))
307376
}
308377
lines := strings.Split(out, "\n")
309378
linesN := len(lines)
310-
if linesN > 300 {
311-
lines = lines[:300]
379+
if linesN > 30 { // tail 30 lines
380+
lines = lines[linesN-30:]
312381
out = strings.Join(lines, "\n")
313382
}
314-
fmt.Printf("\n'%s' output (total %d lines, last 300 lines):\n\n%s\n\n", cmdLogs, linesN, out)
383+
fmt.Printf("\n'%s' output (total lines %d, last 30 lines):\n\n%s\n\n", cmdLogs, linesN, out)
315384

316385
ctx, cancel = context.WithTimeout(context.Background(), time.Minute)
317386
output, err = exec.New().CommandContext(ctx, argsStatus[0], argsStatus[1:]...).CombinedOutput()
@@ -333,8 +402,8 @@ func (ts *tester) checkSonobuoy() (err error) {
333402
}
334403

335404
interval = time.Duration(float64(interval) * 0.7)
336-
if interval < time.Minute {
337-
interval = time.Minute
405+
if interval < 2*time.Minute {
406+
interval = 2 * time.Minute
338407
}
339408
}
340409

‎eks/stresser/stresser.go‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -230,7 +230,7 @@ func startWrites(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duratio
230230
} else {
231231
writeRequestsSuccessTotal.Inc()
232232
if cnt%20 == 0 {
233-
lg.Info("wrote configmap", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", namespace))
233+
lg.Info("wrote configmap", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", namespace))
234234
}
235235
}
236236
select {
@@ -272,7 +272,7 @@ func startWrites(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duratio
272272
} else {
273273
writeRequestsSuccessTotal.Inc()
274274
if cnt%20 == 0 {
275-
lg.Info("wrote secret", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", namespace))
275+
lg.Info("wrote secret", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", namespace))
276276
}
277277
}
278278
select {
@@ -314,7 +314,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
314314
} else {
315315
readRequestsSuccessTotal.Inc()
316316
if cnt%20 == 0 {
317-
lg.Info("listed nodes", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.Int("nodes", len(rs.Items)))
317+
lg.Info("listed nodes", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.Int("nodes", len(rs.Items)))
318318
}
319319
}
320320

@@ -330,7 +330,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
330330
} else {
331331
readRequestsSuccessTotal.Inc()
332332
if cnt%20 == 0 {
333-
lg.Info("listed pods", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("pods", len(pods.Items)))
333+
lg.Info("listed pods", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("pods", len(pods.Items)))
334334
}
335335
}
336336
select {
@@ -354,7 +354,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
354354
} else {
355355
readRequestsSuccessTotal.Inc()
356356
if cnt%20 == 0 {
357-
lg.Info("listed services", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("services", len(svcs.Items)))
357+
lg.Info("listed services", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("services", len(svcs.Items)))
358358
}
359359
}
360360
select {
@@ -378,7 +378,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
378378
} else {
379379
readRequestsSuccessTotal.Inc()
380380
if cnt%20 == 0 {
381-
lg.Info("listed endpoints", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("endpoints", len(eps.Items)))
381+
lg.Info("listed endpoints", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("endpoints", len(eps.Items)))
382382
}
383383
}
384384
select {
@@ -402,7 +402,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
402402
} else {
403403
readRequestsSuccessTotal.Inc()
404404
if cnt%20 == 0 {
405-
lg.Info("listed configmaps", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("configmaps", len(cms.Items)))
405+
lg.Info("listed configmaps", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("configmaps", len(cms.Items)))
406406
}
407407
}
408408
select {
@@ -427,7 +427,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
427427
}
428428
readRequestsSuccessTotal.Inc()
429429
if cnt%20 == 0 {
430-
lg.Info("listed secrets", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("secrets", len(ss.Items)))
430+
lg.Info("listed secrets", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("secrets", len(ss.Items)))
431431
}
432432
select {
433433
case <-stopc:
@@ -450,7 +450,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
450450
} else {
451451
readRequestsSuccessTotal.Inc()
452452
if cnt%20 == 0 {
453-
lg.Info("listed jobs", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("jobs", len(jobs.Items)))
453+
lg.Info("listed jobs", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("jobs", len(jobs.Items)))
454454
}
455455
}
456456
select {
@@ -474,7 +474,7 @@ func startReads(lg *zap.Logger, cli *kubernetes.Clientset, timeout time.Duration
474474
} else {
475475
readRequestsSuccessTotal.Inc()
476476
if cnt%20 == 0 {
477-
lg.Info("listed cronjobs", zap.String("time", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("cronjobs", len(cjbs.Items)))
477+
lg.Info("listed cronjobs", zap.String("deadline", humanize.Time(deadline)), zap.Int("iteration", cnt), zap.String("namespace", nv), zap.Int("cronjobs", len(cjbs.Items)))
478478
}
479479
}
480480
select {

‎eksconfig/add-on-conformance.go‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -75,8 +75,8 @@ func (cfg *Config) IsEnabledAddOnConformance() bool {
7575
func getDefaultAddOnConformance() *AddOnConformance {
7676
addOn := &AddOnConformance{
7777
Enable: false,
78-
SonobuoyPath: "/tmp/sonobuoy-v0.18.1",
79-
SonobuoyDownloadURL: "https://github.com/vmware-tanzu/sonobuoy/releases/download/v0.18.1/sonobuoy_0.18.1_linux_amd64.tar.gz",
78+
SonobuoyPath: "/tmp/sonobuoy-v0.18.2",
79+
SonobuoyDownloadURL: "https://github.com/vmware-tanzu/sonobuoy/releases/download/v0.18.2/sonobuoy_0.18.2_linux_amd64.tar.gz",
8080
}
8181
if runtime.GOOS == "darwin" {
8282
addOn.SonobuoyDownloadURL = strings.Replace(addOn.SonobuoyDownloadURL, "linux", "darwin", -1)
@@ -101,8 +101,9 @@ func (cfg *Config) validateAddOnConformance() error {
101101
}
102102
cfg.AddOnConformance.SonobuoyDeleteTimeoutString = cfg.AddOnConformance.SonobuoyDeleteTimeout.String()
103103

104+
// "certified-conformance" takes >=3-hour
104105
if cfg.AddOnConformance.SonobuoyRunTimeout == time.Duration(0) {
105-
cfg.AddOnConformance.SonobuoyRunTimeout = 3*time.Hour + 30*time.Minute
106+
cfg.AddOnConformance.SonobuoyRunTimeout = 5 * time.Hour
106107
}
107108
cfg.AddOnConformance.SonobuoyRunTimeoutString = cfg.AddOnConformance.SonobuoyRunTimeout.String()
108109

0 commit comments

Comments
 (0)