icon

sambaiz-net
github
google maps
board game arena
aws golang machinelearning python etl kubernetes web fluentd gcp ios ...

ssh-over-ssm を ProxyCommand に設定して libssh の ssh_connect() するとタイムアウトしてしまう原因と解決法

awsspec

Private subnet の RDS に接続するにあたり、 Sandbox Mode で動く Sequel Ace では ssh-over-ssm を ProxyCommand とする SSH トンネリングを行えないようだったので、 この Issue で紹介されている TablePlus を試してみたのだがこれでも接続できなかった。

ssh-over-ssm で Session Manager を通して EC2 インスタンスに SSH 接続する - sambaiz-net

Help から Enable SSH Debug Log してみたところ libssh が使われていたので ssh_connect() だけ実行してみたところ接続後にタイムアウトした。

$ cat libsshtest.c
#include <libssh/libssh.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>

void connect_through_ssm() {
  ssh_session session = ssh_new();
  if (session == NULL) {
    fprintf(stderr, "failed to create a ssh_session for ssm\n");
    return;
  }

  int timeout_sec = 30;
  ssh_options_set(session, SSH_OPTIONS_TIMEOUT, &timeout_sec);

  int remote_port = 22;
  ssh_options_set(session, SSH_OPTIONS_HOST, "i-03b79ba2921757fe7");
  ssh_options_set(session, SSH_OPTIONS_PORT, &remote_port);

  int verbosity = SSH_LOG_FUNCTIONS;
  ssh_options_set(session, SSH_OPTIONS_LOG_VERBOSITY, &verbosity);

  if (ssh_connect(session) != SSH_OK) {
    fprintf(stderr, "failed to connect to remote host through ssm: %s\n", ssh_get_error(session));
    ssh_free(session);
    return;
  }

  ssh_disconnect(session);
  ssh_free(session);
}

int main() {
  connect_through_ssm(); 
}

$ brew install libssh
$ clang -I /opt/homebrew/include -I ext -L /opt/homebrew/lib -lssh libsshtest.c
$ ./a.out
failed to connect to remote host through ssm: Timeout connecting to i-03b79ba2921757fe7

SSH_OPTIONS_LOG_VERBOSITY を設定して詳細なログが出力されるようにしてみる。

int verbosity = SSH_LOG_FUNCTIONS;
ssh_options_set(session, SSH_OPTIONS_LOG_VERBOSITY, &verbosity);

すると ProxyCommand が実行され Banner が返っていることが分かった。

[2023/07/17 13:54:10.223126, 2] ssh_socket_connect_proxycommand:  Executing proxycommand 'exec sh -c "~/.ssh/ssh-ssm.sh %h %r"'
[2023/07/17 13:54:10.224973, 2] ssh_socket_connect_proxycommand:  ProxyCommand connection pipe: [3,4]
[2023/07/17 13:54:10.225031, 1] socket_callback_connected:  Socket connection callback: 1 (0)
[2023/07/17 13:54:10.225045, 3] ssh_client_connection_callback:  session_state=2
[2023/07/17 13:54:10.225066, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2023/07/17 13:54:10.225073, 4] ssh_socket_unbuffered_write:  wrote 23
[2023/07/17 13:54:10.225079, 2] ssh_connect:  Socket connecting, now waiting for the callbacks to work
[2023/07/17 13:54:10.225085, 3] ssh_connect:  Actual timeout : 30000
[2023/07/17 13:54:10.225109, 4] ssh_socket_pollcallback:  Poll callback on socket 4 (POLLOUT ), out buffer 0
[2023/07/17 13:54:15.126839, 4] ssh_socket_pollcallback:  Poll callback on socket 4 (POLLIN ), out buffer 0
[2023/07/17 13:54:15.127027, 4] ssh_socket_unbuffered_read:  read 336
[2023/07/17 13:54:15.127048, 3] callback_receive_banner:  ssh_protocol_version_exchange: Updates Information Summary: available
[2023/07/17 13:54:15.127059, 3] callback_receive_banner:  ssh_protocol_version_exchange:     1 Security notice(s)
[2023/07/17 13:54:15.127070, 3] callback_receive_banner:  ssh_protocol_version_exchange:         1 Important Security notice(s)
[2023/07/17 13:54:15.127080, 3] callback_receive_banner:  ssh_protocol_version_exchange: 
[2023/07/17 13:54:15.127090, 3] callback_receive_banner:  ssh_protocol_version_exchange:    ,     #_
[2023/07/17 13:54:15.127099, 3] callback_receive_banner:  ssh_protocol_version_exchange:    ~\_  ####_        Amazon Linux 2023
[2023/07/17 13:54:15.127109, 3] callback_receive_banner:  ssh_protocol_version_exchange:   ~~  \_#####\
[2023/07/17 13:54:15.127118, 3] callback_receive_banner:  ssh_protocol_version_exchange:   ~~     \###|
[2023/07/17 13:54:15.127127, 3] callback_receive_banner:  ssh_protocol_version_exchange:   ~~       \#/ ___   https://aws.amazon.com/linux/amazon-linux-2023
[2023/07/17 13:54:15.127498, 3] callback_receive_banner:  ssh_protocol_version_exchange:    ~~       V~' '->
[2023/07/17 13:54:15.127510, 3] callback_receive_banner:  ssh_protocol_version_exchange:     ~~~         /
[2023/07/17 13:54:15.127520, 3] callback_receive_banner:  ssh_protocol_version_exchange:       ~~._.   _/
[2023/07/17 13:54:15.127529, 3] callback_receive_banner:  ssh_protocol_version_exchange:          _/ _/
[2023/07/17 13:54:15.127538, 3] callback_receive_banner:  ssh_protocol_version_exchange:        _/m/'
[2023/07/17 13:54:40.226261, 1] ssh_connect:  Timeout connecting to i-03b79ba2921757fe7

libssh のコードを見ると callback_receive_banner() は ssh_socket.callbacks->data に代入されていて、 s->state == SSH_SOCKET_CONNECTED である間呼ばれている。 このループは プロトコルバージョン交換のための文字列が届いて state が SSH_SESSION_STATE_BANNER_RECEIVED になることで終了する。

なぜバージョン交換が完了しないかを調べるため、SSM Agent のログレベルを trace に変更したところ、 クライアントとの通信に用いる Websocket コネクションを開き、 SSM のバージョンの Handshake を行った後、 Port plugin によって SSH Server へ 接続している ことが分かった。

$ sudo vi /etc/amazon/ssm/seelog.xml
<seelog type="adaptive" mininterval="2000000" maxinterval="100000000" critmsgcount="500" minlevel="trace">
...

$ sudo service amazon-ssm-agent restart
$ sudo tail -f /var/log/amazon/ssm/amazon-ssm-agent.log
...
2023-07-17 14:37:38 INFO [ssm-session-worker] [xxxxx] [DataBackend] [pluginName=Port] Opening websocket connection to: wss://ssmmessages.ap-northeast-1.amazonaws.com/v1/data-channel/xxxxx?role=publish_subscribe
2023-07-17 14:37:38 INFO [ssm-session-worker] [xxxxx] [DataBackend] [pluginName=Port] Successfully opened websocket connection to: wss://ssmmessages.ap-northeast-1.amazonaws.com/v1/data-channel/xxxxx?role=publish_subscribe
2023-07-17 14:37:38 DEBUG [ssm-session-worker] [xxxxx] [DataBackend] [pluginName=Port] Send agent_session_state message with session status Connected
...
2023-07-17 14:37:39 INFO [ssm-session-worker] [xxxxx] [DataBackend] [pluginName=Port] Handshake successfully completed.
2023-07-17 14:37:39 DEBUG [ssm-session-worker] [xxxxx] [DataBackend] [pluginName=Port] Start separate go routine to read from port connection and write to data channel
2023-07-17 14:37:39 INFO [ssm-session-worker] [xxxxx] [DataBackend] [pluginName=Port] Plugin Port started

Port plugin と同様に net.Dial() で SSH Server に接続してみたところ、接続後すぐにサーバーのバージョン文字列が送られてきて、 バージョン交換が終わると鍵交換に用いられる Key Exchange Method の一覧が送られてきた。

package main

import (
	"fmt"
	"log"
	"net"
)

func main() {
	conn, err := net.Dial("tcp", "localhost:22")
	if err != nil {
		log.Fatal(err)
	}
	defer conn.Close()

	packet := make([]byte, 1000)
	if _, err = conn.Read(packet); err != nil {
		log.Fatal(err)
	}

	fmt.Println(string(packet))

	fmt.Println("Send client version")
	conn.Write([]byte("SSH-2.0-OpenSSH_8.7\n"))

	if _, err = conn.Read(packet); err != nil {
		log.Fatal(err)
	}

	fmt.Println(string(packet))
}

// ./main 
// SSH-2.0-OpenSSH_8.7
//
// Send client version
// �
// �m�ľ�P�(�ci����curve25519-sha256,[email protected],...

では session-manager-plugin の方で何かやっているのかと思ったが、そういうわけでもなく start-session すると接続時のバージョン文字列が返ってきた。

% aws ssm start-session --document-name AWS-StartSSHSession --target "i-03b79ba2921757fe7" 

Starting session with SessionId: mba2022-07a32943362549199
SSH-2.0-OpenSSH_8.7

つまり、AWS-StartSSHSession は SSH とは書いてあるが TCP のコネクションだけ確立して SSH に関わる処理は行っていないということになる。 ここでもう一度 ssh-over-ssm のスクリプトを見てみたところ ssh コマンド以外から呼び出されたときに ssh コマンドに置き換える処理が行われていた。 これにより ssh コマンドがバージョン交換等を行っていることが分かった。

if [[ $(basename -- $(ps -o comm= -p $PPID)) != "ssh" ]]; then
  exec ssh -o IdentityFile="${SSH_TMP_KEY}" -o ProxyCommand="$0 $1 $2" "$2@$1"

なのでこの exec 部分を消して再実行したところ接続に成功するようになった。

接続成功