Skip to content

Improve ENI attachment logging#4887

Merged
sparrc merged 4 commits intoaws:devfrom
sparrc:sparrc-udev-logging
Mar 6, 2026
Merged

Improve ENI attachment logging#4887
sparrc merged 4 commits intoaws:devfrom
sparrc:sparrc-udev-logging

Conversation

@sparrc
Copy link
Contributor

@sparrc sparrc commented Mar 4, 2026

Summary

Overall enhance logging in the ENI watcher to have more detailed logs when ENI attachments happen, and convert some "legacy" logs to structured format.

  • Add structured logging (logger.Fields) to ENI Watcher for udev event handling and ENI state changes
  • Include primaryMAC field in all log messages
  • Add logs when udev events are received, filtered, or processed (only "net" subsystem events are logged at Info).
  • Change "already sent" Error logs to Info level for trunk ENIs
  • Prefix all logs with "ENI Watcher:" for consistency

Implementation details

Logs when running a non-trunking awsvpc task (debug logs will also show relevant logs from the wakeup, pci, and queues subsystems).

After change:

level=info time=2026-03-04T19:22:25Z msg="ENI Watcher: received udev event" primaryMAC="02:e9:99:dc:70:e1" action="add" subsystem="net" interface="eth0" devpath="/devices/pci0000:00/0000:00:06.0/net/eth0"
level=info time=2026-03-04T19:22:25Z msg="ENI Watcher: obtained MAC address for interface, sending state change" primaryMAC="02:e9:99:dc:70:e1" interface="eth0" macAddress="02:32:7a:78:e4:7d"
level=info time=2026-03-04T19:22:25Z msg="Handling ENI attachment: arn:aws:ecs:us-west-2:039193556298:attachment/c0ba6c09-f9d2-4305-90ba-0a33313bb947" module=attach_eni_common.go
level=info time=2026-03-04T19:22:25Z msg="Starting ENI ack timer" attachmentType="task-eni" attachmentSent=false mac="02:32:7a:78:e4:7d" status="NONE" expiresAt="2026-03-04T19:27:25Z" task="25423947376b46ebad016350d1c9061c" duration="4m59.999872176s" attachmentARN="arn:aws:ecs:us-west-2:039193556298:attachment/c0ba6c09-f9d2-4305-90ba-0a33313bb947"
level=info time=2026-03-04T19:22:25Z msg="Adding eni attachment info to state for task" task="25423947376b46ebad016350d1c9061c" attachmentARN="arn:aws:ecs:us-west-2:039193556298:attachment/c0ba6c09-f9d2-4305-90ba-0a33313bb947" mac="02:32:7a:78:e4:7d"
level=info time=2026-03-04T19:22:25Z msg="ENI Watcher: received udev event" devpath="/devices/pci0000:00/0000:00:06.0/net/ens6" primaryMAC="02:e9:99:dc:70:e1" action="move" subsystem="net" interface="ens6"
level=info time=2026-03-04T19:22:25Z msg="ENI Watcher: found ENI attachment in agent state" primaryMAC="02:e9:99:dc:70:e1" macAddress="02:32:7a:78:e4:7d"
level=info time=2026-03-04T19:22:25Z msg="ENI Watcher: successfully processed ENI attachment" primaryMAC="02:e9:99:dc:70:e1" interface="eth0" macAddress="02:32:7a:78:e4:7d"
level=info time=2026-03-04T19:22:25Z msg="ENI Watcher: emitting task ENI attached event" attachmentType="task-eni" primaryMAC="02:e9:99:dc:70:e1" taskARN="arn:aws:ecs:us-west-2:039193556298:task/usw2/25423947376b46ebad016350d1c9061c" attachmentARN="arn:aws:ecs:us-west-2:039193556298:attachment/c0ba6c09-f9d2-4305-90ba-0a33313bb947" macAddress="02:32:7a:78:e4:7d"
level=info time=2026-03-04T19:22:25Z msg="Sending state change to ECS" eventType="TaskStateChange" taskArn="arn:aws:ecs:us-west-2:039193556298:task/usw2/25423947376b46ebad016350d1c9061c" taskStatus="NONE" taskReason="" eniAttachment="ENI Attachment: task=arn:aws:ecs:us-west-2:039193556298:task/usw2/25423947376b46ebad016350d1c9061c attachment=arn:aws:ecs:us-west-2:039193556298:attachment/c0ba6c09-f9d2-4305-90ba-0a33313bb947 attachmentType=task-eni attachmentSent=false mac=02:32:7a:78:e4:7d status=ATTACHED expiresAt=2026-03-04T19:27:25Z"
level=info time=2026-03-04T19:22:32Z msg="ENI Watcher: received udev event" primaryMAC="02:e9:99:dc:70:e1" action="remove" subsystem="net" interface="ens6" devpath="/devices/pci0000:00/0000:00:06.0/net/ens6"
level=info time=2026-03-04T19:22:32Z msg="ENI Watcher: received udev event" devpath="/devices/virtual/net/veth99e202e6" primaryMAC="02:e9:99:dc:70:e1" action="add" subsystem="net" interface="veth99e202e6"
level=info time=2026-03-04T19:22:32Z msg="ENI Watcher: received udev event" primaryMAC="02:e9:99:dc:70:e1" action="move" subsystem="net" interface="veth99e202e6" devpath="/devices/virtual/net/veth99e202e6"

Before change:

level=info time=2026-03-04T19:29:09Z msg="Handling ENI attachment: arn:aws:ecs:us-west-2:039193556298:attachment/756a17fb-948b-4086-81a6-e010323b0ced" module=attach_eni_common.go
level=info time=2026-03-04T19:29:09Z msg="Starting ENI ack timer" attachmentARN="arn:aws:ecs:us-west-2:039193556298:attachment/756a17fb-948b-4086-81a6-e010323b0ced" attachmentType="task-eni" attachmentSent=false mac="02:b8:d7:c4:ff:1b" status="NONE" expiresAt="2026-03-04T19:34:09Z" task="ae51b726d10141c59c76be85bb6b5181" duration="4m59.999914003s"
level=info time=2026-03-04T19:29:09Z msg="Adding eni attachment info to state for task" attachmentARN="arn:aws:ecs:us-west-2:039193556298:attachment/756a17fb-948b-4086-81a6-e010323b0ced" mac="02:b8:d7:c4:ff:1b" task="ae51b726d10141c59c76be85bb6b5181"
level=info time=2026-03-04T19:29:09Z msg="Emitting task ENI attached event for: ENI Attachment: task=arn:aws:ecs:us-west-2:039193556298:task/usw2/ae51b726d10141c59c76be85bb6b5181 attachment=arn:aws:ecs:us-west-2:039193556298:attachment/756a17fb-948b-4086-81a6-e010323b0ced attachmentType=task-eni attachmentSent=false mac=02:b8:d7:c4:ff:1b status=ATTACHED expiresAt=2026-03-04T19:34:09Z" module=watcher.go
level=info time=2026-03-04T19:29:09Z msg="Sending state change to ECS" taskReason="" eniAttachment="ENI Attachment: task=arn:aws:ecs:us-west-2:039193556298:task/usw2/ae51b726d10141c59c76be85bb6b5181 attachment=arn:aws:ecs:us-west-2:039193556298:attachment/756a17fb-948b-4086-81a6-e010323b0ced attachmentType=task-eni attachmentSent=false mac=02:b8:d7:c4:ff:1b status=ATTACHED expiresAt=2026-03-04T19:34:09Z" eventType="TaskStateChange" taskArn="arn:aws:ecs:us-west-2:039193556298:task/usw2/ae51b726d10141c59c76be85bb6b5181" taskStatus="NONE"

Testing

manually ran awsvpc tasks on an EC2 instance, inspected logs

New tests cover the changes: no

Description for the changelog

Enhancement: Improve ENI watcher udev logging

Licensing

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

@sparrc sparrc requested a review from a team as a code owner March 4, 2026 00:55
@sparrc sparrc changed the title [wip] Improve ENI watcher udev logging Improve ENI watcher udev logging Mar 4, 2026
@sparrc sparrc force-pushed the sparrc-udev-logging branch from 1b2b507 to a285175 Compare March 4, 2026 19:19
@sparrc sparrc added the bot/test label Mar 4, 2026
@sparrc sparrc changed the title Improve ENI watcher udev logging Improve ENI attachment logging Mar 4, 2026
@sparrc sparrc added the bot/test label Mar 4, 2026
log.Infof("Emitting task ENI attached event for: %s", eni.String())
logger.Info("ENI Watcher: emitting task ENI attached event", logger.Fields{
"primaryMAC": eniWatcher.primaryMAC,
field.TaskARN: eni.TaskARN,
Copy link
Contributor

@mye956 mye956 Mar 4, 2026

Choose a reason for hiding this comment

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

q: do we want to have a read lock/have getters for the ENI attachment object before accessing its field values? (looks like there's a lock for ENI attachments)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

that's a good point, i can add a read lock here and below where I am replacing eni.String()

@sparrc sparrc force-pushed the sparrc-udev-logging branch from 70bac13 to 10f36fa Compare March 4, 2026 21:39
@sparrc sparrc force-pushed the sparrc-udev-logging branch from 10f36fa to a4da882 Compare March 4, 2026 21:39
testTask.Containers[0].Memory = 20
testTask.Containers[0].Image = testBusyboxImage
testTask.Containers[0].Command = []string{"sh", "-c", `x="a"; while true; do x=$x$x$x; done`}
// should cause sh to get oomkilled as pid 1
Copy link
Contributor Author

Choose a reason for hiding this comment

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

unrelated integ test fix that was causing TestInitOOMEvent to be flaky

TheanLim
TheanLim previously approved these changes Mar 5, 2026
Copy link
Contributor

@TheanLim TheanLim left a comment

Choose a reason for hiding this comment

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

--deleted--

@sparrc sparrc force-pushed the sparrc-udev-logging branch from 1a8c265 to 6c3f243 Compare March 5, 2026 22:57
@sparrc sparrc added the bot/test label Mar 5, 2026
@sparrc sparrc enabled auto-merge (squash) March 6, 2026 18:55
@sparrc sparrc requested review from TheanLim and mye956 March 6, 2026 18:55
@sparrc sparrc merged commit ccd8035 into aws:dev Mar 6, 2026
44 checks passed
@prateekchaudhry prateekchaudhry mentioned this pull request Mar 6, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants