Does not properly handle 'pause_publication'

[webdestroya]

The plugin does not properly handle the pause_publication message.

If connected to an ECS task that is killed while still being connected, the logs show:

2021-11-05 03:57:33 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:33 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:33 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:34 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:34 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:34 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:33 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:33 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:34 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:34 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:34 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
2021-11-05 03:57:34 WARN [OutputMessageHandler @ streaming.go.411] Invalid message type received: %spause_publication
2021-11-05 03:57:34 DEBUG [func1 @ streaming.go.339] Resend stream data message: 241
...

(This is an infinite loop and will just fill up the log file).

Ideally, the server should have closed the connection (and sent the channel_closed message).

Since that doesn't appear to be happening, it would be nice if the client could at least handle the pause_publication message.

In my use case, it would be best if this would exit the plugin.

Steps to recreate:

• Enable debug logging (not sure if this is required, but obviously I have it enabled)
• Start an ECS task where the command is sleep 86400 (you can probably set something lower)
• run an ExecuteCommand against that task with /bin/bash in interactive mode
• Wait for the sleep timer to expire
• plugin will remain running, but does not respond to input.
• log files will accumulate until you forcibly terminate the plugin.

[yuting-fan]

Hi webdestroya@,

The Session Manager service uses start_publication and pause_publication messages to establish data channel connections with Session Manager plugin and SSM agent. When there is a delay from either the SSM agent or the Session Manager plugin, customers may see additional log lines identifying these messages.

We understand that these superfluous logs due to the resend of pause_publication messages can fill up the log file. The service team is working on a change to improve the logging experience and remove the redundant logs, and will release the change in the upcoming Session Manager plugin release.

Cheers,
Yuting

[webdestroya]

This isn't really a superfluous logging issue. The program will not progress because it cannot acknowledge the message. So it completely stalls out and just does an infinite loop.

Also, I would argue that "pause_publication" is the wrong response to an ECS task being killed. There is nothing paused, it's never going to start, the task is dead. Why would it not send channel_closed ?

[yuting-fan]

How did you "kill" the ECS task? Was it a call to ECS StopTask API, or directly killing the containers on the instance?

[webdestroya]

Using the ECS StopTask API. (These containers are all Fargate)

[yuting-fan]

Thanks webdestroya@. I'm able to reproduce the issue. The service team will work on a fix and update you once it's live. In the meantime, you could try to configure "MaxSessionDuration" in Session Manager preferences. The session will close automatically up till this timeout. https://docs.aws.amazon.com/systems-manager/latest/userguide/session-preferences-max-timeout.html

[webdestroya]

@yuting-fan that setting is not respected for ECS ExecuteCommand sessions. It will boot you after 20 minutes regardless of what you set that setting to.

[yuting-fan]

We released a fix to time out hanging session if there is no response from the remote server in 5 minutes. Please upgrade to the latest version and try again https://github.com/aws/session-manager-plugin/releases/tag/1.2.295.0.