切换新密钥时Paramiko报‘Invalid Packet Blocking’的原因排查

问题描述 #

我正在开发一款集成认证功能的Paramiko SFTP服务器，使用WinSCP作为SFTP客户端时，初始连接建立后，在接受通道阶段连接断开。自己编写的极简Paramiko客户端可正常完成认证、连接及文件传输，但WinSCP和一款谷歌浏览器SFTP扩展均无法连接。

服务器核心代码 #

try:
    sftp_logger.info('Starting SFTP Server')
    self.database = DatabaseInterface()
    
    # CONFIGURE A LISTENING SOCKET
    sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
    sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)

    # Get details of running machine
    dir_path = os.path.dirname(os.path.realpath(__file__))
    local_ip = socket.gethostbyname(socket.gethostname())

    sock.bind((local_ip, 22))
    sock.listen(10)

    # Configure Paramiko logging
    paramiko.common.logging.basicConfig(level=paramiko.common.DEBUG)

    # Configure Python logging to save logs to a file
    logging.basicConfig(filename='paramiko_debug.log', level=logging.DEBUG)

    # Redirect Paramiko logs to Python logging
    paramiko.common.logging.getLogger().addHandler(logging.FileHandler('paramiko_debug.log'))

    sftp_logger.info('Initial Server Set-Up Complete')
    server_key = paramiko.RSAKey.generate(2048)
    sftp_logger.info('Generated Key')

    # Serve indefinitely
    channels = []
    while True:
        
        conn, addr = sock.accept()

        sftp_logger.info(f"Accepted Connection from {str(addr)}")

        transport = paramiko.Transport((conn))
        sftp_logger.debug(f"Initiated Transport for {str(addr)}")
        transport.add_server_key(server_key)
        sftp_logger.debug(f"Bound Key for {str(addr)}")
        transport.set_subsystem_handler('sftp', paramiko.SFTPServer, Custom_Paramiko_SFTP)
        sftp_logger.debug(f"Added Subsystem handler for {str(addr)}")
        server = Underlying_SSH_Server()
        transport.start_server(server=server)
        sftp_logger.debug(f"Started Server for {str(addr)}")

        channels.append(transport.accept())
        # sftp_logger.debug(f"Channel Accepted")

        while transport.is_active():
            time.sleep(1)

except Exception:
    sftp_logger.error(traceback.format_exc())

服务器报错日志 #

=== Key exchange agreements ===
Kex: curve25519-sha256@libssh.org
HostKey: rsa-sha2-512
Cipher: aes256-ctr
MAC: hmac-sha1
Compression: none
=== End of kex handshake ===
kex engine KexCurve25519 specified hash_algo <built-in function openssl_sha256>
Switch to new keys ...
Started Server for ('31.117.38.192', 56391)
Exception (server): Invalid packet blocking
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/paramiko/transport.py", line 2129, in run
    ptype, m = self.packetizer.read_message()
  File "/usr/local/lib/python3.10/dist-packages/paramiko/packet.py", line 487, in read_message
    raise SSHException("Invalid packet blocking")
paramiko.ssh_exception.SSHException: Invalid packet blocking

WinSCP客户端日志 #

. 2023-08-21 16:07:43.621 Initialised AES-256 SDCTR (AES-NI accelerated) [aes256-ctr] outbound encryption
. 2023-08-21 16:07:43.621 Initialised HMAC-SHA-1 (bug-compatible) outbound MAC algorithm
. 2023-08-21 16:07:43.621 Initialised AES-256 SDCTR (AES-NI accelerated) [aes256-ctr] inbound encryption
. 2023-08-21 16:07:43.621 Initialised HMAC-SHA-1 (bug-compatible) inbound MAC algorithm
. 2023-08-21 16:07:43.621 Incoming packet was garbled on decryption
. 2023-08-21 16:07:43.621 Attempt to close connection due to fatal exception:
* 2023-08-21 16:07:43.621 Incoming packet was garbled on decryption
. 2023-08-21 16:07:43.621 Closing connection.
. 2023-08-21 16:07:43.621 Selecting events 0 for socket 2764
* 2023-08-21 16:07:43.706 (EFatal) Incoming packet was garbled on decryption
* 2023-08-21 16:07:43.706 Authentication failed.

疑问与求助 #

• 日志显示密钥交换算法已协商一致
• Paramiko报错Invalid packet blocking，该错误通常是移除消息头后无剩余消息体时触发
• WinSCP显示Incoming packet was garbled on decryption
• 无法确定问题出在哪一方，怀疑是Paramiko早期配置错误引发通信异常

作为Paramiko和高级网络领域的新手，仅能理解基本运行逻辑，想请教：

1. 极简Python SFTP客户端与WinSCP等成熟客户端的差异是什么？
2. 该连接异常问题的可能原因是什么？

内容的提问来源于stack exchange，提问作者Matthew Forth