Skip to content

Commit 281690d

Browse files
haugenjhaugenj
authored
Revert date format in human-readable logs (#155)
* Revert date format in logs to preveserve backwards compatibility * Fix msg -> msgf in webhook_test
1 parent 24e3320 commit 281690d

File tree

8 files changed

+55
-50
lines changed

8 files changed

+55
-50
lines changed

‎cmd/node-termination-handler.go

Lines changed: 23 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -33,13 +33,14 @@ import (
3333
const (
3434
scheduledMaintenance = "Scheduled Maintenance"
3535
spotITN = "Spot ITN"
36+
timeFormat = "2006/01/02 15:04:05"
3637
)
3738

3839
type monitorFunc func(chan<- interruptionevent.InterruptionEvent, chan<- interruptionevent.InterruptionEvent, *ec2metadata.Service) error
3940

4041
func main() {
4142
// Zerolog uses json formatting by default, so change that to a human-readable format instead
42-
log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339, NoColor: true})
43+
log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: timeFormat, NoColor: true, FormatLevel: logFormatLevel})
4344

4445
signalChan := make(chan os.Signal, 1)
4546
signal.Notify(signalChan, syscall.SIGTERM)
@@ -71,7 +72,7 @@ func main() {
7172
if nthConfig.EnableScheduledEventDraining {
7273
err = handleRebootUncordon(interruptionEventStore, *node)
7374
if err != nil {
74-
log.Printf("Unable to complete the uncordon after reboot workflow on startup: %v", err)
75+
log.Log().Msgf("Unable to complete the uncordon after reboot workflow on startup: %v", err)
7576
}
7677
}
7778

@@ -90,22 +91,22 @@ func main() {
9091

9192
for eventType, fn := range monitoringFns {
9293
go func(monitorFn monitorFunc, eventType string) {
93-
log.Printf("Started monitoring for %s events", eventType)
94+
log.Log().Msgf("Started monitoring for %s events", eventType)
9495
for range time.Tick(time.Second * 2) {
9596
err := monitorFn(interruptionChan, cancelChan, imds)
9697
if err != nil {
97-
log.Printf("There was a problem monitoring for %s events: %v", eventType, err)
98+
log.Log().Msgf("There was a problem monitoring for %s events: %v", eventType, err)
9899
}
99100
}
100101
}(fn, eventType)
101102
}
102103

103104
go watchForInterruptionEvents(interruptionChan, interruptionEventStore, nodeMetadata)
104-
log.Print("Started watching for interruption events")
105-
log.Print("Kubernetes AWS Node Termination Handler has started successfully!")
105+
log.Log().Msg("Started watching for interruption events")
106+
log.Log().Msg("Kubernetes AWS Node Termination Handler has started successfully!")
106107

107108
go watchForCancellationEvents(cancelChan, interruptionEventStore, node, nodeMetadata)
108-
log.Print("Started watching for event cancellations")
109+
log.Log().Msg("Started watching for event cancellations")
109110

110111
for range time.NewTicker(1 * time.Second).C {
111112
select {
@@ -116,7 +117,7 @@ func main() {
116117
drainOrCordonIfNecessary(interruptionEventStore, *node, nthConfig, nodeMetadata)
117118
}
118119
}
119-
log.Print("AWS Node Termination Handler is shutting down")
120+
log.Log().Msg("AWS Node Termination Handler is shutting down")
120121
}
121122

122123
func handleRebootUncordon(interruptionEventStore *interruptioneventstore.Store, node node.Node) error {
@@ -142,25 +143,25 @@ func handleRebootUncordon(interruptionEventStore *interruptioneventstore.Store,
142143
func watchForInterruptionEvents(interruptionChan <-chan interruptionevent.InterruptionEvent, interruptionEventStore *interruptioneventstore.Store, nodeMetadata ec2metadata.NodeMetadata) {
143144
for {
144145
interruptionEvent := <-interruptionChan
145-
log.Printf("Got interruption event from channel %+v %+v", nodeMetadata, interruptionEvent)
146+
log.Log().Msgf("Got interruption event from channel %+v %+v", nodeMetadata, interruptionEvent)
146147
interruptionEventStore.AddInterruptionEvent(&interruptionEvent)
147148
}
148149
}
149150

150151
func watchForCancellationEvents(cancelChan <-chan interruptionevent.InterruptionEvent, interruptionEventStore *interruptioneventstore.Store, node *node.Node, nodeMetadata ec2metadata.NodeMetadata) {
151152
for {
152153
interruptionEvent := <-cancelChan
153-
log.Printf("Got cancel event from channel %+v %+v", nodeMetadata, interruptionEvent)
154+
log.Log().Msgf("Got cancel event from channel %+v %+v", nodeMetadata, interruptionEvent)
154155
interruptionEventStore.CancelInterruptionEvent(interruptionEvent.EventID)
155156
if interruptionEventStore.ShouldUncordonNode() {
156-
log.Print("Uncordoning the node due to a cancellation event")
157+
log.Log().Msg("Uncordoning the node due to a cancellation event")
157158
err := node.Uncordon()
158159
if err != nil {
159-
log.Printf("Uncordoning the node failed: %v", err)
160+
log.Log().Msgf("Uncordoning the node failed: %v", err)
160161
}
161162
node.RemoveNTHLabels()
162163
} else {
163-
log.Print("Another interruption event is active, not uncordoning the node")
164+
log.Log().Msg("Another interruption event is active, not uncordoning the node")
164165
}
165166
}
166167
}
@@ -170,27 +171,31 @@ func drainOrCordonIfNecessary(interruptionEventStore *interruptioneventstore.Sto
170171
if drainEvent.PreDrainTask != nil {
171172
err := drainEvent.PreDrainTask(*drainEvent, node)
172173
if err != nil {
173-
log.Printf("There was a problem executing the pre-drain task: %v", err)
174+
log.Log().Msgf("There was a problem executing the pre-drain task: %v", err)
174175
}
175176
}
176177
if nthConfig.CordonOnly {
177178
err := node.Cordon()
178179
if err != nil {
179-
log.Printf("There was a problem while trying to cordon the node: %v", err)
180+
log.Log().Msgf("There was a problem while trying to cordon the node: %v", err)
180181
os.Exit(1)
181182
}
182-
log.Printf("Node %q successfully cordoned.", nthConfig.NodeName)
183+
log.Log().Msgf("Node %q successfully cordoned.", nthConfig.NodeName)
183184
} else {
184185
err := node.CordonAndDrain()
185186
if err != nil {
186-
log.Printf("There was a problem while trying to cordon and drain the node: %v", err)
187+
log.Log().Msgf("There was a problem while trying to cordon and drain the node: %v", err)
187188
os.Exit(1)
188189
}
189-
log.Printf("Node %q successfully cordoned and drained.", nthConfig.NodeName)
190+
log.Log().Msgf("Node %q successfully cordoned and drained.", nthConfig.NodeName)
190191
}
191192
interruptionEventStore.MarkAllAsDrained()
192193
if nthConfig.WebhookURL != "" {
193194
webhook.Post(nodeMetadata, drainEvent, nthConfig)
194195
}
195196
}
196197
}
198+
199+
func logFormatLevel(interface{}) string {
200+
return ""
201+
}

‎pkg/config/config.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -112,9 +112,9 @@ func ParseCliArgs() (config Config, err error) {
112112
flag.Parse()
113113

114114
if isConfigProvided("pod-termination-grace-period", podTerminationGracePeriodConfigKey) && isConfigProvided("grace-period", gracePeriodConfigKey) {
115-
log.Print("Deprecated argument \"grace-period\" and the replacement argument \"pod-termination-grace-period\" was provided. Using the newer argument \"pod-termination-grace-period\"")
115+
log.Log().Msg("Deprecated argument \"grace-period\" and the replacement argument \"pod-termination-grace-period\" was provided. Using the newer argument \"pod-termination-grace-period\"")
116116
} else if isConfigProvided("grace-period", gracePeriodConfigKey) {
117-
log.Print("Deprecated argument \"grace-period\" was provided. This argument will eventually be removed. Please switch to \"pod-termination-grace-period\" instead.")
117+
log.Log().Msg("Deprecated argument \"grace-period\" was provided. This argument will eventually be removed. Please switch to \"pod-termination-grace-period\" instead.")
118118
config.PodTerminationGracePeriod = gracePeriod
119119
}
120120

‎pkg/ec2metadata/ec2metadata.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -184,7 +184,7 @@ func (e *Service) Request(contextPath string) (*http.Response, error) {
184184
if err != nil {
185185
e.v2Token = ""
186186
e.tokenTTL = -1
187-
log.Printf("Unable to retrieve an IMDSv2 token, continuing with IMDSv1: %v", err)
187+
log.Log().Msgf("Unable to retrieve an IMDSv2 token, continuing with IMDSv1: %v", err)
188188
} else {
189189
e.v2Token = token
190190
e.tokenTTL = ttl
@@ -219,7 +219,7 @@ func (e *Service) getV2Token() (string, int, error) {
219219
httpReq := func() (*http.Response, error) {
220220
return e.httpClient.Do(req)
221221
}
222-
log.Print("Trying to get token from IMDSv2")
222+
log.Log().Msg("Trying to get token from IMDSv2")
223223
resp, err := retry(1, 2*time.Second, httpReq)
224224
if err != nil {
225225
return "", -1, err
@@ -236,7 +236,7 @@ func (e *Service) getV2Token() (string, int, error) {
236236
if err != nil {
237237
return "", -1, fmt.Errorf("IMDS v2 Token TTL header not sent in response: %w", err)
238238
}
239-
log.Print("Got token from IMDSv2")
239+
log.Log().Msg("Got token from IMDSv2")
240240
return string(token), ttl, nil
241241
}
242242

@@ -259,8 +259,8 @@ func retry(attempts int, sleep time.Duration, httpReq func() (*http.Response, er
259259
jitter := time.Duration(rand.Int63n(int64(sleep)))
260260
sleep = sleep + jitter/2
261261

262-
log.Printf("Request failed. Attempts remaining: %d", attempts)
263-
log.Printf("Sleep for %s seconds", sleep)
262+
log.Log().Msgf("Request failed. Attempts remaining: %d", attempts)
263+
log.Log().Msgf("Sleep for %s seconds", sleep)
264264
time.Sleep(sleep)
265265
return retry(attempts, 2*sleep, httpReq)
266266
}
@@ -279,7 +279,7 @@ func (e *Service) GetNodeMetadata() NodeMetadata {
279279
metadata.LocalHostname, _ = e.GetMetadataInfo(LocalHostnamePath)
280280
metadata.LocalIP, _ = e.GetMetadataInfo(LocalIPPath)
281281

282-
log.Printf("Startup Metadata Retrieved: %+v", metadata)
282+
log.Log().Msgf("Startup Metadata Retrieved: %+v", metadata)
283283

284284
return metadata
285285
}

‎pkg/interruptionevent/scheduled-event.go

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -42,10 +42,10 @@ func MonitorForScheduledEvents(interruptionChan chan<- InterruptionEvent, cancel
4242
}
4343
for _, interruptionEvent := range interruptionEvents {
4444
if isStateCanceledOrCompleted(interruptionEvent.State) {
45-
log.Print("Sending cancel events to the cancel channel")
45+
log.Log().Msg("Sending cancel events to the cancel channel")
4646
cancelChan <- interruptionEvent
4747
} else {
48-
log.Print("Sending interruption events to the interruption channel")
48+
log.Log().Msg("Sending interruption events to the interruption channel")
4949
interruptionChan <- interruptionEvent
5050
}
5151
}
@@ -93,7 +93,7 @@ func uncordonAfterRebootPreDrain(interruptionEvent InterruptionEvent, node node.
9393
// if the node is already marked as unschedulable, then don't do anything
9494
unschedulable, err := node.IsUnschedulable()
9595
if err == nil && unschedulable {
96-
log.Print("Node is already marked unschedulable, not taking any action to add uncordon label.")
96+
log.Log().Msg("Node is already marked unschedulable, not taking any action to add uncordon label.")
9797
return nil
9898
} else if err != nil {
9999
return fmt.Errorf("Encountered an error while checking if the node is unschedulable. Not setting an uncordon label: %w", err)
@@ -102,7 +102,7 @@ func uncordonAfterRebootPreDrain(interruptionEvent InterruptionEvent, node node.
102102
if err != nil {
103103
return fmt.Errorf("Unable to mark the node for uncordon: %w", err)
104104
}
105-
log.Print("Successfully applied uncordon after reboot action label to node.")
105+
log.Log().Msg("Successfully applied uncordon after reboot action label to node.")
106106
return nil
107107
}
108108

‎pkg/interruptionevent/spot-itn-event.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ func MonitorForSpotITNEvents(interruptionChan chan<- InterruptionEvent, cancelCh
3434
return err
3535
}
3636
if interruptionEvent != nil && interruptionEvent.Kind == SpotITNKind {
37-
log.Print("Sending interruption event to the interruption channel")
37+
log.Log().Msg("Sending interruption event to the interruption channel")
3838
interruptionChan <- *interruptionEvent
3939
}
4040
return nil

‎pkg/node/node.go

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -74,7 +74,7 @@ func NewWithValues(nthConfig config.Config, drainHelper *drain.Helper) (*Node, e
7474
// CordonAndDrain will cordon the node and evict pods based on the config
7575
func (n Node) CordonAndDrain() error {
7676
if n.nthConfig.DryRun {
77-
log.Printf("Node %s would have been cordoned and drained, but dry-run flag was set", n.nthConfig.NodeName)
77+
log.Log().Msgf("Node %s would have been cordoned and drained, but dry-run flag was set", n.nthConfig.NodeName)
7878
return nil
7979
}
8080
err := n.Cordon()
@@ -92,7 +92,7 @@ func (n Node) CordonAndDrain() error {
9292
// Cordon will add a NoSchedule on the node
9393
func (n Node) Cordon() error {
9494
if n.nthConfig.DryRun {
95-
log.Printf("Node %s would have been cordoned, but dry-run flag was set", n.nthConfig.NodeName)
95+
log.Log().Msgf("Node %s would have been cordoned, but dry-run flag was set", n.nthConfig.NodeName)
9696
return nil
9797
}
9898
node, err := n.fetchKubernetesNode()
@@ -109,7 +109,7 @@ func (n Node) Cordon() error {
109109
// Uncordon will remove the NoSchedule on the node
110110
func (n Node) Uncordon() error {
111111
if n.nthConfig.DryRun {
112-
log.Printf("Node %s would have been uncordoned, but dry-run flag was set", n.nthConfig.NodeName)
112+
log.Log().Msgf("Node %s would have been uncordoned, but dry-run flag was set", n.nthConfig.NodeName)
113113
return nil
114114
}
115115
node, err := n.fetchKubernetesNode()
@@ -126,7 +126,7 @@ func (n Node) Uncordon() error {
126126
// IsUnschedulable checks if the node is marked as unschedulable
127127
func (n Node) IsUnschedulable() (bool, error) {
128128
if n.nthConfig.DryRun {
129-
log.Print("IsUnschedulable returning false since dry-run is set")
129+
log.Log().Msg("IsUnschedulable returning false since dry-run is set")
130130
return false, nil
131131
}
132132
node, err := n.fetchKubernetesNode()
@@ -164,7 +164,7 @@ func (n Node) GetEventID() (string, error) {
164164
}
165165
val, ok := node.Labels[EventIDLabelKey]
166166
if n.nthConfig.DryRun && !ok {
167-
log.Printf("Would have returned Error: Event ID Lable %s was not found on the node, but dry-run flag was set", EventIDLabelKey)
167+
log.Log().Msgf("Would have returned Error: Event ID Lable %s was not found on the node, but dry-run flag was set", EventIDLabelKey)
168168
return "", nil
169169
}
170170
if !ok {
@@ -214,7 +214,7 @@ func (n Node) addLabel(key string, value string) error {
214214
return err
215215
}
216216
if n.nthConfig.DryRun {
217-
log.Printf("Would have added label (%s=%s) to node %s, but dry-run flag was set", key, value, n.nthConfig.NodeName)
217+
log.Log().Msgf("Would have added label (%s=%s) to node %s, but dry-run flag was set", key, value, n.nthConfig.NodeName)
218218
return nil
219219
}
220220
_, err = n.drainHelper.Client.CoreV1().Nodes().Patch(node.Name, types.StrategicMergePatchType, payloadBytes)
@@ -245,7 +245,7 @@ func (n Node) removeLabel(key string) error {
245245
return err
246246
}
247247
if n.nthConfig.DryRun {
248-
log.Printf("Would have removed label with key %s from node %s, but dry-run flag was set", key, n.nthConfig.NodeName)
248+
log.Log().Msgf("Would have removed label with key %s from node %s, but dry-run flag was set", key, n.nthConfig.NodeName)
249249
return nil
250250
}
251251
_, err = n.drainHelper.Client.CoreV1().Nodes().Patch(node.Name, types.JSONPatchType, payload)
@@ -274,7 +274,7 @@ func (n Node) UncordonIfRebooted() error {
274274
}
275275
timeVal, ok := k8sNode.Labels[ActionLabelTimeKey]
276276
if !ok {
277-
log.Printf("There was no %s label found requiring action label handling", ActionLabelTimeKey)
277+
log.Log().Msgf("There was no %s label found requiring action label handling", ActionLabelTimeKey)
278278
return nil
279279
}
280280
timeValNum, err := strconv.ParseInt(timeVal, 10, 64)
@@ -289,7 +289,7 @@ func (n Node) UncordonIfRebooted() error {
289289
return err
290290
}
291291
if secondsSinceLabel < int64(uptime) {
292-
log.Print("The system has not restarted yet.")
292+
log.Log().Msg("The system has not restarted yet.")
293293
return nil
294294
}
295295
err = n.Uncordon()
@@ -300,9 +300,9 @@ func (n Node) UncordonIfRebooted() error {
300300
if err != nil {
301301
return err
302302
}
303-
log.Printf("Successfully completed action %s.", UncordonAfterRebootLabelVal)
303+
log.Log().Msgf("Successfully completed action %s.", UncordonAfterRebootLabelVal)
304304
default:
305-
log.Print("There are no label actions to handle.")
305+
log.Log().Msg("There are no label actions to handle.")
306306
}
307307
return nil
308308
}

‎pkg/webhook/webhook.go

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,7 @@ func Post(additionalInfo ec2metadata.NodeMetadata, event *interruptionevent.Inte
3838

3939
webhookTemplate, err := template.New("message").Parse(nthconfig.WebhookTemplate)
4040
if err != nil {
41-
log.Printf("Webhook Error: Template parsing failed - %s", err)
41+
log.Log().Msgf("Webhook Error: Template parsing failed - %s", err)
4242
return
4343
}
4444

@@ -47,20 +47,20 @@ func Post(additionalInfo ec2metadata.NodeMetadata, event *interruptionevent.Inte
4747
var byteBuffer bytes.Buffer
4848
err = webhookTemplate.Execute(&byteBuffer, combined)
4949
if err != nil {
50-
log.Printf("Webhook Error: Template execution failed - %s", err)
50+
log.Log().Msgf("Webhook Error: Template execution failed - %s", err)
5151
return
5252
}
5353

5454
request, err := http.NewRequest("POST", nthconfig.WebhookURL, &byteBuffer)
5555
if err != nil {
56-
log.Printf("Webhook Error: Http NewRequest failed - %s", err)
56+
log.Log().Msgf("Webhook Error: Http NewRequest failed - %s", err)
5757
return
5858
}
5959

6060
headerMap := make(map[string]interface{})
6161
err = json.Unmarshal([]byte(nthconfig.WebhookHeaders), &headerMap)
6262
if err != nil {
63-
log.Printf("Webhook Error: Header Unmarshal failed - %s", err)
63+
log.Log().Msgf("Webhook Error: Header Unmarshal failed - %s", err)
6464
return
6565
}
6666
for key, value := range headerMap {
@@ -84,18 +84,18 @@ func Post(additionalInfo ec2metadata.NodeMetadata, event *interruptionevent.Inte
8484
}
8585
response, err := client.Do(request)
8686
if err != nil {
87-
log.Printf("Webhook Error: Client Do failed - %s", err)
87+
log.Log().Msgf("Webhook Error: Client Do failed - %s", err)
8888
return
8989
}
9090

9191
defer response.Body.Close()
9292

9393
if response.StatusCode < 200 || response.StatusCode > 299 {
94-
log.Printf("Webhook Error: Received Status Code %d", response.StatusCode)
94+
log.Log().Msgf("Webhook Error: Received Status Code %d", response.StatusCode)
9595
return
9696
}
9797

98-
log.Print("Webhook Success: Notification Sent!")
98+
log.Log().Msg("Webhook Success: Notification Sent!")
9999
}
100100

101101
// ValidateWebhookConfig will check if the template provided in nthConfig with parse and execute

‎pkg/webhook/webhook_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,7 @@ func parseScheduledEventTime(inputTime string) time.Time {
4646
func getExpectedMessage(event *interruptionevent.InterruptionEvent) string {
4747
webhookTemplate, err := template.New("").Parse(testWebhookTemplate)
4848
if err != nil {
49-
log.Printf("Webhook Error: Template parsing failed - %s", err)
49+
log.Log().Msgf("Webhook Error: Template parsing failed - %s", err)
5050
return ""
5151
}
5252

0 commit comments

Comments
 (0)