Skip to content

Commit 06ed18f

Browse files
karlkfikarlkfi
committed
Switch logging to Logrus
- Switch to json log formating - Add log timestamps - Add container_name to all log messsages - Add support for Stackdriver severity field - Pass the logger (with "global" fields) through the context
1 parent 410339a commit 06ed18f

File tree

7 files changed

+187
-96
lines changed

7 files changed

+187
-96
lines changed

‎cmd/kubexit/main.go

Lines changed: 62 additions & 64 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,6 @@ package main
33
import (
44
"context"
55
"fmt"
6-
"log"
76
"os"
87
"os/exec"
98
"os/signal"
@@ -14,6 +13,7 @@ import (
1413

1514
"github.com/fsnotify/fsnotify"
1615
"github.com/karlkfi/kubexit/pkg/kubernetes"
16+
"github.com/karlkfi/kubexit/pkg/log"
1717
"github.com/karlkfi/kubexit/pkg/supervisor"
1818
"github.com/karlkfi/kubexit/pkg/tombstone"
1919

@@ -24,21 +24,23 @@ import (
2424
func main() {
2525
var err error
2626

27-
// remove log timestamp
28-
log.SetFlags(log.Flags() &^ (log.Ldate | log.Ltime))
27+
ctx := log.WithLogger(context.Background(), log.L)
2928

3029
args := os.Args[1:]
3130
if len(args) == 0 {
32-
log.Println("Error: no arguments found")
31+
log.G(ctx).Error("no arguments found")
3332
os.Exit(2)
3433
}
3534

3635
name := os.Getenv("KUBEXIT_NAME")
3736
if name == "" {
38-
log.Println("Error: missing env var: KUBEXIT_NAME")
37+
log.G(ctx).Error("missing env var: KUBEXIT_NAME")
3938
os.Exit(2)
4039
}
41-
log.Printf("Name: %s\n", name)
40+
41+
// add field to the context logger to differentiate when pod container logs are intermingled
42+
ctx = log.WithLogger(ctx, log.G(ctx).WithField("container_name", name))
43+
log.G(ctx).Info("KUBEXIT_NAME parsed")
4244

4345
graveyard := os.Getenv("KUBEXIT_GRAVEYARD")
4446
if graveyard == "" {
@@ -47,85 +49,78 @@ func main() {
4749
graveyard = strings.TrimRight(graveyard, "/")
4850
graveyard = filepath.Clean(graveyard)
4951
}
50-
log.Printf("Graveyard: %s\n", graveyard)
51-
5252
ts := &tombstone.Tombstone{
5353
Graveyard: graveyard,
5454
Name: name,
5555
}
56-
log.Printf("Tombstone: %s\n", ts.Path())
56+
log.G(ctx).
57+
WithField("graveyard", graveyard).
58+
WithField("tombstone", ts.Path()).
59+
Info("KUBEXIT_GRAVEYARD parsed")
5760

5861
birthDepsStr := os.Getenv("KUBEXIT_BIRTH_DEPS")
5962
var birthDeps []string
60-
if birthDepsStr == "" {
61-
log.Println("Birth Deps: N/A")
62-
} else {
63+
if birthDepsStr != "" {
6364
birthDeps = strings.Split(birthDepsStr, ",")
64-
log.Printf("Birth Deps: %s\n", strings.Join(birthDeps, ","))
6565
}
66+
log.G(ctx).WithField("birth_deps", birthDeps).Info("KUBEXIT_BIRTH_DEPS parsed")
6667

6768
deathDepsStr := os.Getenv("KUBEXIT_DEATH_DEPS")
6869
var deathDeps []string
69-
if deathDepsStr == "" {
70-
log.Println("Death Deps: N/A")
71-
} else {
70+
if deathDepsStr != "" {
7271
deathDeps = strings.Split(deathDepsStr, ",")
73-
log.Printf("Death Deps: %s\n", strings.Join(deathDeps, ","))
7472
}
73+
log.G(ctx).WithField("death_deps", deathDeps).Info("KUBEXIT_DEATH_DEPS parsed")
7574

7675
birthTimeout := 30 * time.Second
7776
birthTimeoutStr := os.Getenv("KUBEXIT_BIRTH_TIMEOUT")
7877
if birthTimeoutStr != "" {
7978
birthTimeout, err = time.ParseDuration(birthTimeoutStr)
8079
if err != nil {
81-
log.Printf("Error: failed to parse birth timeout: %v\n", err)
80+
log.G(ctx).Errorf("failed to parse birth timeout: %v\n", err)
8281
os.Exit(2)
8382
}
8483
}
85-
log.Printf("Birth Timeout: %s\n", birthTimeout)
84+
log.G(ctx).WithField("birth_timeout", birthTimeout).Info("KUBEXIT_BIRTH_TIMEOUT parsed")
8685

8786
gracePeriod := 30 * time.Second
8887
gracePeriodStr := os.Getenv("KUBEXIT_GRACE_PERIOD")
8988
if gracePeriodStr != "" {
9089
gracePeriod, err = time.ParseDuration(gracePeriodStr)
9190
if err != nil {
92-
log.Printf("Error: failed to parse grace period: %v\n", err)
91+
log.G(ctx).Printf("Error: failed to parse grace period: %v\n", err)
9392
os.Exit(2)
9493
}
9594
}
96-
log.Printf("Grace Period: %s\n", gracePeriod)
95+
log.G(ctx).WithField("grace_period", gracePeriod).Info("KUBEXIT_GRACE_PERIOD parsed")
9796

9897
podName := os.Getenv("KUBEXIT_POD_NAME")
9998
if podName == "" {
10099
if len(birthDeps) > 0 {
101-
log.Println("Error: missing env var: KUBEXIT_POD_NAME")
100+
log.G(ctx).Error("missing env var: KUBEXIT_POD_NAME")
102101
os.Exit(2)
103102
}
104-
log.Println("Pod Name: N/A")
105-
} else {
106-
log.Printf("Pod Name: %s\n", podName)
107103
}
104+
log.G(ctx).WithField("pod_name", podName).Info("KUBEXIT_POD_NAME parsed")
108105

109106
namespace := os.Getenv("KUBEXIT_NAMESPACE")
110107
if namespace == "" {
111108
if len(birthDeps) > 0 {
112-
log.Println("Error: missing env var: KUBEXIT_NAMESPACE")
109+
log.G(ctx).Error("missing env var: KUBEXIT_NAMESPACE")
113110
os.Exit(2)
114111
}
115-
log.Println("Namespace: N/A")
116-
} else {
117-
log.Printf("Namespace: %s\n", namespace)
118112
}
113+
log.G(ctx).WithField("namespace", namespace).Info("KUBEXIT_POD_NAME parsed")
119114

120-
child := supervisor.New(args[0], args[1:]...)
115+
child := supervisor.New(ctx, args[0], args[1:]...)
121116

122117
// watch for death deps early, so they can interrupt waiting for birth deps
123118
if len(deathDeps) > 0 {
124-
ctx, stopGraveyardWatcher := context.WithCancel(context.Background())
119+
ctx, stopGraveyardWatcher := context.WithCancel(ctx)
125120
// stop graveyard watchers on exit, if not sooner
126121
defer stopGraveyardWatcher()
127122

128-
log.Println("Watching graveyard...")
123+
log.G(ctx).Info("Watching graveyard...")
129124
err = tombstone.Watch(ctx, graveyard, onDeathOfAny(deathDeps, func() error {
130125
stopGraveyardWatcher()
131126
// trigger graceful shutdown
@@ -138,32 +133,32 @@ func main() {
138133
return nil
139134
}))
140135
if err != nil {
141-
fatalf(child, ts, "Error: failed to watch graveyard: %v\n", err)
136+
fatal(ctx, child, ts, fmt.Errorf("failed to watch graveyard: %v", err))
142137
}
143138
}
144139

145140
if len(birthDeps) > 0 {
146141
err = waitForBirthDeps(birthDeps, namespace, podName, birthTimeout)
147142
if err != nil {
148-
fatalf(child, ts, "Error: %v\n", err)
143+
fatal(ctx, child, ts, err)
149144
}
150145
}
151146

152147
err = child.Start()
153148
if err != nil {
154-
fatalf(child, ts, "Error: %v\n", err)
149+
fatal(ctx, child, ts, err)
155150
}
156151

157-
err = ts.RecordBirth()
152+
err = ts.RecordBirth(ctx)
158153
if err != nil {
159-
fatalf(child, ts, "Error: %v\n", err)
154+
fatal(ctx, child, ts, err)
160155
}
161156

162-
code := waitForChildExit(child)
157+
code := waitForChildExit(ctx, child)
163158

164-
err = ts.RecordDeath(code)
159+
err = ts.RecordDeath(ctx, code)
165160
if err != nil {
166-
log.Printf("Error: %v\n", err)
161+
log.G(ctx).Printf("Error: %v\n", err)
167162
os.Exit(1)
168163
}
169164

@@ -178,9 +173,9 @@ func waitForBirthDeps(birthDeps []string, namespace, podName string, timeout tim
178173
// Stop pod watcher on exit, if not sooner
179174
defer stopPodWatcher()
180175

181-
log.Println("Watching pod updates...")
176+
log.G(ctx).Info("Watching pod updates...")
182177
err := kubernetes.WatchPod(ctx, namespace, podName,
183-
onReadyOfAll(birthDeps, stopPodWatcher),
178+
onReadyOfAll(ctx, birthDeps, stopPodWatcher),
184179
)
185180
if err != nil {
186181
return fmt.Errorf("failed to watch pod: %v", err)
@@ -196,7 +191,7 @@ func waitForBirthDeps(birthDeps []string, namespace, podName string, timeout tim
196191
return fmt.Errorf("waiting for birth deps to be ready: %v", err)
197192
}
198193

199-
log.Printf("All birth deps ready: %v\n", strings.Join(birthDeps, ", "))
194+
log.G(ctx).Printf("All birth deps ready: %v\n", strings.Join(birthDeps, ", "))
200195
return nil
201196
}
202197

@@ -215,7 +210,7 @@ func withCancelOnSignal(ctx context.Context, signals ...os.Signal) context.Conte
215210
if !ok {
216211
return
217212
}
218-
log.Printf("Received shutdown signal: %v", s)
213+
log.G(ctx).Printf("Received shutdown signal: %v", s)
219214
cancel()
220215
case <-ctx.Done():
221216
signal.Reset()
@@ -228,7 +223,7 @@ func withCancelOnSignal(ctx context.Context, signals ...os.Signal) context.Conte
228223
}
229224

230225
// wait for the child to exit and return the exit code
231-
func waitForChildExit(child *supervisor.Supervisor) int {
226+
func waitForChildExit(ctx context.Context, child *supervisor.Supervisor) int {
232227
var code int
233228
err := child.Wait()
234229
if err != nil {
@@ -237,35 +232,37 @@ func waitForChildExit(child *supervisor.Supervisor) int {
237232
} else {
238233
code = -1
239234
}
240-
log.Printf("Child Exited(%d): %v\n", code, err)
241235
} else {
242236
code = 0
243-
log.Println("Child Exited(0)")
244237
}
238+
log.G(ctx).
239+
WithField("exit_code", code).
240+
WithField("error", err).
241+
Info("child exited")
245242
return code
246243
}
247244

248-
// fatalf is for terminal errors.
245+
// fatal logs a terminal error and exits.
249246
// The child process may or may not be running.
250-
func fatalf(child *supervisor.Supervisor, ts *tombstone.Tombstone, msg string, args ...interface{}) {
251-
log.Printf(msg, args...)
247+
func fatal(ctx context.Context, child *supervisor.Supervisor, ts *tombstone.Tombstone, err error) {
248+
log.G(ctx).Error(err)
252249

253250
// Skipped if not started.
254-
err := child.ShutdownNow()
251+
err = child.ShutdownNow()
255252
if err != nil {
256-
log.Printf("Error: failed to shutdown child process: %v", err)
253+
log.G(ctx).Errorf("failed to shutdown child process: %v", err)
257254
os.Exit(1)
258255
}
259256

260257
// Wait for shutdown...
261258
//TODO: timout in case the process is zombie?
262-
code := waitForChildExit(child)
259+
code := waitForChildExit(ctx, child)
263260

264261
// Attempt to record death, if possible.
265262
// Another process may be waiting for it.
266-
err = ts.RecordDeath(code)
263+
err = ts.RecordDeath(ctx, code)
267264
if err != nil {
268-
log.Printf("Error: %v\n", err)
265+
log.G(ctx).Errorf("failed to record death of child process: %v", err)
269266
os.Exit(1)
270267
}
271268

@@ -274,22 +271,22 @@ func fatalf(child *supervisor.Supervisor, ts *tombstone.Tombstone, msg string, a
274271

275272
// onReadyOfAll returns an EventHandler that executes the callback when all of
276273
// the birthDeps containers are ready.
277-
func onReadyOfAll(birthDeps []string, callback func()) kubernetes.EventHandler {
274+
func onReadyOfAll(ctx context.Context, birthDeps []string, callback func()) kubernetes.EventHandler {
278275
birthDepSet := map[string]struct{}{}
279276
for _, depName := range birthDeps {
280277
birthDepSet[depName] = struct{}{}
281278
}
282279

283280
return func(event watch.Event) {
284-
fmt.Printf("Event Type: %v\n", event.Type)
281+
log.G(ctx).WithField("event_type", event.Type).Info("recieved pod watch event")
285282
// ignore Deleted (Watch will auto-stop on delete)
286283
if event.Type == watch.Deleted {
287284
return
288285
}
289286

290287
pod, ok := event.Object.(*corev1.Pod)
291288
if !ok {
292-
log.Printf("Error: unexpected non-pod object type: %+v\n", event.Object)
289+
log.G(ctx).WithField("object", event.Object).Warn("recieved unexpected non-pod object type")
293290
return
294291
}
295292

@@ -321,33 +318,34 @@ func onDeathOfAny(deathDeps []string, callback func() error) tombstone.EventHand
321318
deathDepSet[depName] = struct{}{}
322319
}
323320

324-
return func(event fsnotify.Event) error {
321+
return func(ctx context.Context, event fsnotify.Event) error {
325322
if event.Op&fsnotify.Create != fsnotify.Create && event.Op&fsnotify.Write != fsnotify.Write {
326323
// ignore other events
327324
return nil
328325
}
329326
graveyard := filepath.Dir(event.Name)
330327
name := filepath.Base(event.Name)
331328

332-
log.Printf("Tombstone modified: %s\n", name)
329+
log.G(ctx).WithField("tombstone", name).Info("recieved tombstone watch event")
333330
if _, ok := deathDepSet[name]; !ok {
334331
// ignore other tombstones
335332
return nil
336333
}
337334

338-
log.Printf("Reading tombstone: %s\n", name)
339335
ts, err := tombstone.Read(graveyard, name)
340336
if err != nil {
341-
log.Printf("Error: failed to read tombstone: %v\n", err)
337+
log.G(ctx).WithField("tombstone", name).Errorf("failed to read tombstone: %v", err)
342338
return nil
343339
}
344340

345341
if ts.Died == nil {
346342
// still alive
347343
return nil
348344
}
349-
log.Printf("New death: %s\n", name)
350-
log.Printf("Tombstone(%s): %s\n", name, ts)
345+
log.G(ctx).
346+
WithField("tombstone", name).
347+
WithField("tombstone_content", ts).
348+
Errorf("recieved new death event")
351349

352350
return callback()
353351
}

‎go.mod

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ go 1.14
44

55
require (
66
github.com/fsnotify/fsnotify v1.4.9
7+
github.com/sirupsen/logrus v1.6.0
78
k8s.io/api v0.18.2
89
k8s.io/apimachinery v0.18.2
910
k8s.io/client-go v0.18.2

‎go.sum

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,7 @@ github.com/json-iterator/go v1.1.8/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/u
7373
github.com/jstemmer/go-junit-report v0.0.0-20190106144839-af01ea7f8024/go.mod h1:6v2b51hI/fHJwM22ozAgKL4VKDeJcHhJFhtBdhmNjmU=
7474
github.com/kisielk/errcheck v1.2.0/go.mod h1:/BMXB+zMLi60iA8Vv6Ksmxu/1UDYcXs4uQLJ+jE2L00=
7575
github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck=
76+
github.com/konsorten/go-windows-terminal-sequences v1.0.3/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
7677
github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
7778
github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
7879
github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
@@ -97,11 +98,14 @@ github.com/onsi/gomega v1.7.0/go.mod h1:ex+gbHU/CVuBBDIJjb2X0qEXbFg53c61hWP/1Cpa
9798
github.com/peterbourgon/diskv v2.0.1+incompatible/go.mod h1:uqqh8zWWbv1HBMNONnaR/tNboyR3/BZd58JJSHlUSCU=
9899
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
99100
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
101+
github.com/sirupsen/logrus v1.6.0 h1:UBcNElsrwanuuMsnGSlYmtmgbb23qDR5dG+6X6Oo89I=
102+
github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88=
100103
github.com/spf13/afero v1.2.2/go.mod h1:9ZxEEn6pIJ8Rxe320qSDBk6AsU0r9pR7Q4OcevTdifk=
101104
github.com/spf13/pflag v0.0.0-20170130214245-9ff6c6923cff/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
102105
github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
103106
github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
104107
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
108+
github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
105109
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
106110
github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJyk=
107111
github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
@@ -139,6 +143,7 @@ golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e/go.mod h1:STP8DvDyc/dI5b8T5h
139143
golang.org/x/sys v0.0.0-20190209173611-3b5209105503/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
140144
golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
141145
golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
146+
golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
142147
golang.org/x/sys v0.0.0-20191005200804-aed5e4c7ecf9 h1:L2auWcuQIvxz9xSEqzESnV/QN/gNRXNApHi3fYwl2w0=
143148
golang.org/x/sys v0.0.0-20191005200804-aed5e4c7ecf9/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
144149
golang.org/x/sys v0.0.0-20191022100944-742c48ecaeb7 h1:HmbHVPwrPEKPGLAcHSrMe6+hqSUlvZU0rab6x5EXfGU=
@@ -186,6 +191,7 @@ k8s.io/api v0.18.2 h1:wG5g5ZmSVgm5B+eHMIbI9EGATS2L8Z72rda19RIEgY8=
186191
k8s.io/api v0.18.2/go.mod h1:SJCWI7OLzhZSvbY7U8zwNl9UA4o1fizoug34OV/2r78=
187192
k8s.io/apimachinery v0.18.2 h1:44CmtbmkzVDAhCpRVSiP2R5PPrC2RtlIv/MoB8xpdRA=
188193
k8s.io/apimachinery v0.18.2/go.mod h1:9SnR/e11v5IbyPCGbvJViimtJ0SwHG4nfZFjU77ftcA=
194+
k8s.io/apimachinery v0.18.8 h1:jimPrycCqgx2QPearX3to1JePz7wSbVLq+7PdBTTwQ0=
189195
k8s.io/client-go v0.18.2 h1:aLB0iaD4nmwh7arT2wIn+lMnAq7OswjaejkQ8p9bBYE=
190196
k8s.io/client-go v0.18.2/go.mod h1:Xcm5wVGXX9HAA2JJ2sSBUn3tCJ+4SVlCbl2MNNv+CIU=
191197
k8s.io/gengo v0.0.0-20190128074634-0689ccc1d7d6/go.mod h1:ezvh/TsK7cY6rbqRK0oQQ8IAqLxYwwyPxAX1Pzy0ii0=

0 commit comments

Comments
 (0)