Airflow SSHOperator任务执行完成后超时故障排查求助

DAG结构与任务说明 #

Group1 = ([GeneratedData1, GenerateData2] >> Join)
[Group1, Timeout20min] >> CheckStateOfData

• Timeout20min：PythonOperator，执行time.sleep(20*60)
• Join：EmptyOperator
• 其余任务（GeneratedData1/2、CheckStateOfData）：SSHOperator，连接同一远程主机，执行命令：

  source ~/.bashrc; conda activate myenv; cd /my/folder; python my_script.py
  

• GenerateData1/2配置cmd_timeout=1800（30分钟）

问题表现 #

• GenerateData2脚本实际执行耗时不足10分钟，日志已显示运行到最后一行：

  [2023-12-11, 00:08:26 UTC] {ssh.py:529} WARNING - 2023-12-11 00:08:26,033 [INFO] Finished (GenerateData2.py:252) # 脚本最后一行日志

• 但30分钟后触发超时错误，报错栈：

  [2023-12-11, 00:38:26 UTC] {taskinstance.py:1937} ERROR - Task failed with exception
  Traceback (most recent call last):
    File "/scratch/qrt_cmmbt/.conda/envs/my_env/lib/python3.11/site-packages/airflow/providers/ssh/operators/ssh.py", line 178, in execute
      result = self.run_ssh_client_command(ssh_client, self.command, context=context)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    File "/scratch/qrt_cmmbt/.conda/envs/my_env/lib/python3.11/site-packages/airflow/providers/ssh/operators/ssh.py", line 163, in run_ssh_client_command
      exit_status, agg_stdout, agg_stderr = self.hook.exec_ssh_client_command(
                                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    File "/scratch/qrt_cmmbt/.conda/envs/my_env/lib/python3.11/site-packages/airflow/providers/ssh/hooks/ssh.py", line 549, in exec_ssh_client_command
      raise AirflowException("SSH command timed out")
  airflow.exceptions.AirflowException: SSH command timed out
  ...
  

• DAG已配置dagrun_timeout=datetime.timedelta(hours=6)，排除全局超时影响
• 每日定时触发必现，手动回填/非午夜时段触发无法复现，GeneratedData1也曾出现两次相同问题
• 怀疑脚本末尾用subprocess调用rsync同步数据时，存在未关闭的SSH连接导致Airflow判定任务未结束

排查经验与解决方案 #

1. 确认rsync子进程状态 #

在远程脚本的rsync调用后添加日志，明确记录子进程的退出状态：

import subprocess
import os

rsync_cmd = "rsync -avz /source/path user@remote:/dest/path"
# 使用run确保子进程资源回收
result = subprocess.run(rsync_cmd, shell=True, capture_output=True, text=True)
print(f"rsync exit code: {result.returncode}")
print(f"rsync stdout: {result.stdout}")
print(f"rsync stderr: {result.stderr}")

若发现rsync未正常退出，排查午夜时段目标端负载是否过高导致连接挂起。

2. 避免未关闭的文件描述符 #

• 禁止使用subprocess.Popen却不调用communicate()或wait()，这会导致子进程成为僵尸进程，占用SSH通道资源
• 若必须使用Popen，显式关闭所有管道描述符，确保SSH连接能正常释放

3. 优化远程命令执行方式 #

将远程命令包装成独立脚本，显式返回退出码，减少环境变量加载的不确定性：
远程主机创建run_my_script.sh：

#!/bin/bash
source ~/.bashrc
conda activate myenv
cd /my/folder
python my_script.py
exit $?  # 显式返回脚本最终退出状态

SSHOperator执行命令改为bash /path/to/run_my_script.sh，确保脚本执行完成后正确触发SSH通道关闭。

4. 验证SSHOperator超时逻辑 #

临时增大cmd_timeout（比如设为7200），若问题不再出现，说明确实存在未关闭的SSH连接导致超时。此时需重点排查rsync的连接释放逻辑，比如添加--timeout参数限制rsync的连接时长：

rsync -avz --timeout=300 /source/path user@remote:/dest/path

5. 排查午夜时段系统状态 #

• 查看远程主机午夜时段的系统日志（/var/log/syslog、/var/log/messages），确认是否有资源耗尽、网络波动等情况
• 执行netstat -anp | grep ssh查看连接状态，是否存在大量未关闭的SSH连接堆积

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