Misleading errors about log level mapping

[ctaymor]

Summary

Regardless of what ECS_LOGLEVEL setting I use, the agent logs include an error that the log level mapping was not found. Especially when trying to use warn or error level logging, where those are the only log lines, it's very confusing.

Description

The error appears in the logs, but the ECS_LOGLEVEL appears to be respected anyways.

This error appears in the logs, but it doesn't seem to be breaking anything. The log level set in the env var is what is actually being logged. However, it's very confusing as a user, to see that in your logs. I spent a long time assuming that logging was not properly set up and not happening correctly.

{"level":"error","time":"2024-10-01T06:24:05Z","msg":"Driver log level mapping not found","module":"log.go"}
{"level":"error","time":"2024-10-01T06:24:05Z","msg":"Instance log level mapping not found","module":"log.go"}

Expected Behavior

No weird error about the log level mapping not found showing up when the log level is being correctly set.

Observed Behavior

I observed the same log error above, in the following scenarios:
ECS_LOGLEVEL=debug: Many debug and info messages were logged, but the above errors were present as well

ECS_LOGLEVEL=info: Many info messages were logged, but the above errors were present as well

ECS_LOGLEVEL=warn: Only the above errors were present. At first, I took this to be an indication that logging wasn't correctly set up, but now I think it was a red herring, and logging was happening correctly, there just weren't any other warnings.
ECS_LOGLEVEL=error: Same as warn.

Environment Details

Supporting Log Snippets

{"level":"error","time":"2024-10-01T06:24:05Z","msg":"Driver log level mapping not found","module":"log.go"}
{"level":"error","time":"2024-10-01T06:24:05Z","msg":"Instance log level mapping not found","module":"log.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Successfully got ECS instance credentials from provider: EC2RoleProvider"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Starting Amazon ECS Agent","commit":"78a2bf0c","version":"1.86.3"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Loading configuration"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Successfully got ECS instance credentials from provider: EC2RoleProvider"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Unable to get Docker client for version 1.17: Error response from daemon: client version 1.17 is too old. Minimum supported API version is 1.24, please upgrade your client to a newer version","module":"sdkclientfactory.
go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Unable to get Docker client for version 1.18: Error response from daemon: client version 1.18 is too old. Minimum supported API version is 1.24, please upgrade your client to a newer version","module":"sdkclientfactory.
go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Unable to get Docker client for version 1.19: Error response from daemon: client version 1.19 is too old. Minimum supported API version is 1.24, please upgrade your client to a newer version","module":"sdkclientfactory.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Unable to get Docker client for version 1.20: Error response from daemon: client version 1.20 is too old. Minimum supported API version is 1.24, please upgrade your client to a newer version","module":"sdkclientfactory.}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Unable to get Docker client for version 1.23: Error response from daemon: client version 1.23 is too old. Minimum supported API version is 1.24, please upgrade your client to a newer version","module":"sdkclientfactory.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Setting minimum docker API version","newMinAPIVersion":"1.24","previousMinAPIVersion":"1.21"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Registered transformation function with threshold 1.0.0."}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Successfully got ECS instance credentials from provider: EC2RoleProvider"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Image excluded from cleanup","image":"amazon/amazon-ecs-pause:0.1.0"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Image excluded from cleanup","image":"amazon/amazon-ecs-pause:0.1.0"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Image excluded from cleanup","image":"amazon/amazon-ecs-agent:latest"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"ECS task resource limits cgroupv2 functionality initialized","module":"cgroupv2_controller_linux.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Remaining memory","remainingMemory":31292}
go"
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Initializing host resource manager, initialHostResource","initialHostResource":{"CPU":{"DoubleValue":null,"IntegerValue":8192,"LongValue":null,"Name":"CPU","StringSetValue":null,"Type":"INTEGER"},"GPU":{"DoubleValue":nu
ll,"IntegerValue":null,"LongValue":null,"Name":"GPU","StringSetValue":[],"Type":"STRINGSET"},"MEMORY":{"DoubleValue":null,"IntegerValue"
:31292,"LongValue":null,"Name":"MEMORY","StringSetValue":null,"Type":"INTEGER"},"PORTS_TCP":{"DoubleValue":null,"IntegerValue":null,"Lon
gValue":null,"Name":"PORTS_TCP","StringSetValue":["22","2375","2376","51678","51679"],"Type":"STRINGSET"},"PORTS_UDP":{"DoubleValue":nul
l,"IntegerValue":null,"LongValue":null,"Name":"PORTS_UDP","StringSetValue":[],"Type":"STRINGSET"}}}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Initializing host resource manager, consumed resource","consumedResource":{"CPU":{"
DoubleValue":null,"IntegerValue":0,"LongValue":null,"Name":"CPU","StringSetValue":null,"Type":"INTEGER"},"GPU":{"DoubleValue":null,"Inte
gerValue":null,"LongValue":null,"Name":"GPU","StringSetValue":[],"Type":"STRINGSET"},"MEMORY":{"DoubleValue":null,"IntegerValue":0,"Long
Value":null,"Name":"MEMORY","StringSetValue":null,"Type":"INTEGER"},"PORTS_TCP":{"DoubleValue":null,"IntegerValue":null,"LongValue":null
,"Name":"PORTS_TCP","StringSetValue":["22","2375","2376","51678","51679"],"Type":"STRINGSET"},"PORTS_UDP":{"DoubleValue":null,"IntegerVa
lue":null,"LongValue":null,"Name":"PORTS_UDP","StringSetValue":[],"Type":"STRINGSET"}}}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Event stream ContainerChange start listening...","module":"eventstream.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Cluster was successfully restored","cluster":"primary"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"eni watcher has been initialized","module":"watcher_linux.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Successfully loaded Appnet agent container tarball: /managed-agents/serviceconnect/
ecs-service-connect-agent.interface-v1.tar","image":"ecs-service-connect-agent:interface-v1"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Restored from checkpoint file","cluster":"primary","containerInstanceARN":"arn:aws:
ecs:us-east-1:ID:container-instance/NAME/NUMBER"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Remaining memory","remainingMemory":31292}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Registered container instance with cluster!"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Starting to load Managed Daemon image","imageRef":"ebs-csi-driver:latest"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Image excluded from cleanup","image":"ecs-service-connect-agent:interface-v1"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Successfully loaded ebs-csi-driver container image from tarball: /var/lib/ecs/deps/
daemons/ebs-csi-driver/ebs-csi-driver.tar","image":"ebs-csi-driver:latest"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Successfully loaded Managed Daemon image","imageID":"sha256:9c04e0a0b222eeed2383173"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Image excluded from cleanup","image":"ebs-csi-driver:latest"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Reconciling host resources"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Initializing stats engine"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Monitoring Task Queue started"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Event stream DeregisterContainerInstance start listening...","module":"eventstream.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Beginning Polling for updates"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Starting EBS watcher.","module":"watcher.go"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Establishing a Websocket connection","url":"https://ecs-a-1.us-east-1.amazonaws.com/ws?agentHash=78a2bf0c\u0026agentVersion=1.86.3\u0026clusterArn=ARN\u0026containerInstanceArn=ARN\u0026dockerVersion=DockerVersion%3A+25.0.6\u0026protocolVersion=2\u0026sendCredentials=true\u0026seqNum=1"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"NO_PROXY is set: IPs,/var/run/docker.sock"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Establishing a Websocket connection","url":"https://ecs-t-1.us-east-1.amazonaws.com/ws?agentHash=78a2bf0c\u0026agentVersion=1.86.3\u0026cluster=CLUSTER\u0026containerInstance=arnARN\u0026dockerVersion=25.0.6"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Websocket connection established.","ConnectTime":"2024-10-01 06:24:05","ExpectedDisconnectTime":"2024-10-01 06:54:05","URL":"https://ecs-t-1.us-east-1.amazonaws.com/ws?agentHash=78a2bf0c\u0026agentVersion=1.86.3\u0026cluster=NAME\u0026containerInstance=ARN\u0026dockerVersion=25.0.6"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Connected to TCS endpoint"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Websocket connection established.","ConnectTime":"2024-10-01 06:24:05","ExpectedDisconnectTime":"2024-10-01 06:54:05","URL":"https://ecs-a-1.us-east-1.amazonaws.com/ws?agentHash=78a2bf0c\u0026agentVersion=1.86.3\u0026clusterArn=NAME\u0026containerInstanceArn=ARN\u0026dockerVersion=DockerVersion%3A+25.0.6\u0026protocolVersion=2\u0026sendCredentials=true\u0026seqNum=1"}
{"level":"info","time":"2024-10-01T06:24:05Z","msg":"Connected to ACS endpoint"}

[amogh09]

Submitted #4396 to fix this issue

[ctaymor]

Thanks for getting a fix in for this @amogh09 !

[mye956]

Resolving this issue as @amogh09 has merged in a fix for this. Please feel free to reopen/submit a new issue if we can help with anything else!