SCP 受信したデータが随時書き込まれない

nmaya commented 11 months ago

cf. ticket #47320

大きなファイルを受信すると固まったようになる。プログラムのメモリ使用量がどんどん増えていく。プログレスバーは動かない。

SCP_receive

ファイルの受信が終わってからファイルに保存が進み、プログレスバーも進み、ファイルの保存が終わる。

SCP_receive2

4-stable でも trunk でも発生する。 LAN 内で 200MB-500MB くらいのファイルを受信すると検証しやすい。

tasklist

trunk
- [x] 修正 r10958, r10959, r10960, r10961, r10962, r10966, r10967
- [x] 変更履歴 r10978(r10964, r10965)
4-stable
- [x] 修正 r10963(r10958), r10964(r10959, r10960, r10962), r10972(r10961), r10973(r1066), r10974(r10967)
- [x] 変更履歴 r10964, r10965

nmaya commented 11 months ago

問題の大きさ・影響範囲から、milestone を "5.0" にするか "5.1 or later" にするか、ご意見ください。 4.107 が 4.x 系の最後なのでできれば直してリリースに入れたいですが、難しければやむなしと思っています。

zmatsuo commented 11 months ago

trunk(debugビルド、VS上から動作)で、 300Mbyteのファイルを (dd if=/dev/random of=test_data.bin bs=1M count=300 で作成) Tera TermのVTWinへファイルをドロップして送信、 FILE - SSH SCP - 受信をつかって送信したファイルを受信しました。

送信、数度の受信でとくに引っ掛かることなくファイル転送できました。 OSはWindows10 64bitです。

zmatsuo commented 11 months ago

次のバイナリをダウンロードして試してみました。

Tera Term 5.0 RC2
Tera Term 4.107 RC3
Tera Term 4.106

特に引っ掛かることなくファイル受信できました。

テストに使っているPCには有線LANがなく、無線LANを使用しています。 7MByte/sec 程度の速度で転送していました。

以前、WindowsのバージョンによってスレッドへのCPU時間の割り振りが変化してうまく動かないことがあるのを思い出しました。予想ですが、忙しいスレッドに時間を割り振るような動作が新しいWindowsには入っているような気がしています。

Windowsのバージョン、転送速度、サーバーなどの要因で発生したりしなかったりがあるのかもしれないです。

nmaya commented 11 months ago

確認ありがとうございます。

いますぐテストできる環境の組み合わせで試しました。

Tera Term 5.0 dev r10925 (Release build)	OS	Network	Remote OS	Remote SSH
Windows 8.1	LAN	FreeBSD	OpenSSH_6.6.1p1	NG
Windows 8.1	LAN	Linux	OpenSSH_8.7p1	NG
Windows 8.1	Internet	Linux	OpenSSH_8.0p1	OK
Windows 11	LAN	Linux	OpenSSH_8.0p1	OK
Windows 11	Internet	FreeBSD	OpenSSH_6.6.1p1	OK

確実に再現するわけではなく、おっしゃるように環境が影響していそうですね。

zmatsuo commented 11 months ago

手もとで再現しました。

サーバー(WSL)とTera Termは同一マシンで動作させています。

Tera Term

Tera Term 5 r10953
Windows 10
VS2022上 ,Debug ビルド

server

WSLで動作

debian 12

$ cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
NAME="Debian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
$ /sbin/sshd -v
unknown option -- v
OpenSSH_9.2p1 Debian-2, OpenSSL 3.0.9 30 May 2023

Tera Term の動きをみていると、受信ダイアログの描画がもたついて、メニューなどをクリックしても反応がもたつきます。 GUIスレッドが後回しになっている感じです。

Tera Term とサーバー間の通信が速いとき発生するのでしょうか。

VS上Debugビルドでも再現したのでデバグはできそうですが、とっかかりがないです。

20231001

zmatsuo commented 11 months ago

SCP受信時、次の2スレッドが主な処理を行うことになります。

受信スレッド(=GUIスレッド)
ファイル書き出しスレッド(ssh.c内ssh_scp_receive_thread())

受信スレッド(=GUIスレッド)が受信処理をしていて、データがとても速く送られくるときた時、他のメッセージ処理に時間が割けないようです。

多分、受送信の暗号化処理も受信スレッド(=GUIスレッド)で行われるためとても処理が重くなるんじゃないかと思います。

ファイル書き出しスレッドは、ファイル書き出し以外にダイアログの表示内容の更新も行います。この時、表示内容を更新のためにSendMessage()などでメッセージをダイアログに送ります。でも、GUIスレッドがデータ受信処理に忙しくてメッセージが処理されず、 SendMessage()呼び出しからリターンしてこなくなります。このため、処理が進まなくなり、受信データがファイルに出力されず、出力もされないので、受信データのメモリの開放が行われない、という動作になっている、と予想しました。

この予想があっているかどうかチェックするためにパッチしました。ダイアログの更新をすべて止めます。手もとではメモリの増加は抑えられています。

パッチで動作が変わるか試してみていただけないでしょうか? 20231001_#15.diff.txt

nmaya commented 11 months ago

パッチありがとうございます。適用すると、私のところで問題が起きていた2つの組み合わせでメモリ使用量が増加しなくなりました。

ttdoda commented 11 months ago

おそらく Ticket #34056と同じ問題ですね。根本的には書き込みより受信処理の方が速い事が原因なので、ポートフォワーディングと同じようにフロー制御を導入した方がいいと思います。

Ttssh2-devel 4065でも少し書いてますが、SCPの時はhandle_SSH2_channel_data()でSSH_MSG_CHANNEL_WINDOW_ADJUSTを送らず(do_SSH2_adjust_window_size()を呼ばず)、ファイルに書き込めた分だけSSH_MSG_CHANNEL_WINDOW_ADJUSTで通知すればいいように思います。

zmatsuo commented 11 months ago

処理のもたつきを減らそうと考えたのですが、 USBメモリなど遅いファイルシステムへの書き出しも考慮すると通信にフロー制御を入れるのが一番理にかなっていますね。

nmaya commented 11 months ago

SCPの時はhandle_SSH2_channel_data()でSSH_MSG_CHANNEL_WINDOW_ADJUSTを送らず(do_SSH2_adjust_window_size()を呼ばず)、ファイルに書き込めた分だけSSH_MSG_CHANNEL_WINDOW_ADJUSTで通知すればいいように思います。

単にこうしてみましたが全然だめでした。 #15_adjust_diff.txt

見てもわかりませんでしたが、作りかけのフロー制御はこれでしょうか？ https://github.com/TeraTermProject/teraterm-mirror-gitsvn/commits/scp_flowctrl

zmatsuo commented 11 months ago

調べ中です。なんとかできそうな感じがしてきています。

zmatsuo commented 11 months ago

フロー制御の実装をしようとしています。 Windowsのメッセージ処理は何とかなりそうなのですが通信がわからなくて悩んでいます。

仕様はrfc4254を参考にしています。

ヒント、アドバイスいただけないでしょうか

分かったこと & 疑問点

windows size で送受するサイズを決めている
- Tera Term 内では packet size は利用されていないように見える?

送信側(local)->受信側(remote)

      byte      SSH_MSG_CHANNEL_OPEN
      string    channel type in US-ASCII only
      uint32    sender channel
      uint32    initial window size
      uint32    maximum packet size
      ....      channel type specific data follows

送信側(local)<-受信側(remote)

      byte      SSH_MSG_CHANNEL_OPEN_CONFIRMATION
      uint32    recipient channel
      uint32    sender channel
      uint32    initial window size
      uint32    maximum packet size

Tera Term 動作中 window size の最大値を超えた値になっている?
- 仕様によると window size の最大値は 2^32-1 (デバッガで見た変数の値)
データが送られてくるが、どうやって止めたり再開したり(フロー制御)する?
```
  byte      SSH_MSG_CHANNEL_DATA
  uint32    recipient channel
  string    data
```
送受中に window size を変更できるが追加しかできない?
- windows size を 0 に設定できると送信を止めることができそう(フロー制御)な気がするが…(マイナスを送って0にする?)

      byte      SSH_MSG_CHANNEL_WINDOW_ADJUST
      uint32    recipient channel
      uint32    bytes to add

SSH_MSG_CHANNEL_DATA 受信時に応答をする必要がある?
- SSH_MSG_CHANNEL_WINDOW_ADJUST を送信して応答する?
- 送信しないとしないと何が起こる?
- 試しに応答しないと、ある程度sshdからデータが送られてくる
- でも継続して送信されず、止まってしまう
- 手もとでは4packet送られてきて止まる

nmaya commented 11 months ago

scp_flowctrl のコードをよくわかっていませんし、作業中のコードも見られませんので的外れかもしれませんが、ウィンドウサイズを減らすメッセージがないのはこういうことだと思います。

送信側は受信側のウィンドウサイズを知っている（SSH_MSG_CHANNEL_OPEN の initial window size または SSH_MSG_CHANNEL_OPEN_CONFIRMATION の initial window size）
送信側がデータを送る
- 送信側は、自分が把握している「受信側のウィンドウサイズ」を送った分だけ減らす
- 受信側は、送られてきた長さだけ「自分のウィンドウサイズ」を減らす
- これにより、受信側のウィンドウサイズが共有される
受信側は、受信したデータを処理できてバッファを空けたら、空けたサイズを SSH_MSG_CHANNEL_WINDOW_ADJUST で送る
- 受信側は、「自分のウィンドウサイズ」を増やす
- 送信側は、送られてきたサイズぶん「受信側のウィンドウサイズ」を増やす
- これにより、受信側のウィンドウサイズが共有される

受信側が SSH_MSG_CHANNEL_WINDOW_ADJUST を返さないと、送信側の「受信側のウィンドウサイズ」が 0 になるため送れなくなります。受信側が SSH_MSG_CHANNEL_WINDOW_ADJUST を返すと、送信側の「受信側のウィンドウサイズ」が回復して送信を再開できるようになります。

nmaya commented 11 months ago

OSDN が読み込みづらく、経緯の確認が難しいので引用しておきます。

ticket #34056

cf. https://osdn.net/projects/ttssh2/ticket/34056

SCPダウンロードすると応答なしになる原因 SSHサーバから受信したファイルデータをリンクドリストにつなぎ、スレッドでリストの先頭からデータを取り出し、スレッド上でファイルに追記するという動きをしている。この時、リストのエントリ数に上限を設けていないため、受信スピードが速いと、リストが肥大化する。対策 SCP受信にフロー制御を追加する。

ちょっと調べた感じだと、ssh.c:SSH2_scp_fromremote() の PostThreadMessage() が失敗し続けてループしているようです。

この状況から思ったのですが、メッセージの処理が追いつかずメッセージキューが溢れている可能性はないでしょうか? メッセージキューが溢れる → PostThreadMessage()が失敗する → ループを回して PostThreadMessage() を繰り返す → メッセージの処理が行われずデッドロックする

PostThreadMessage() の無限リトライが悪さをしているように思うので、無限リトライをしない実装に変えようかとも思い始めました。

現状分かったことは下記の通りです。どうもスレッドが動けていないように見えています。・PostThreadMessage()が ERROR_NOT_ENOUGH_QUOTA(1816)を返し続けることにより、doループから抜けられていない。・ssh_scp_receive_thread()は SendMessage 関数でブロックしているように見える。

ssh_scp_receive_thread()で、SendMessage系処理をすべて無効化してみたら、問題が再現しなくなったので(正常にファイル受信できる)、どうやらスレッドキューを PeekMassage することと、同スレッド上でのメッセージ送信が競合することで、何かデッドロックが発生しているように見え、それによりスレッドがブロックしてしまっているように見えます。

r6528 で処置しました。手元の環境(Fedora24 on Hyper-V)で、100%問題が発生していましたが、修正により再現しなくなることを確認しました。

手元の環境ではまだハングアップします。また、転送速度が全体的に遅くなった感じがします。(数百kb/s程度) また、大きいファイルをダウンロードしているとクラッシュする事があります。

r6528の修正では、Tera Term(TTSSH)本体で PostMessage するときの無限ループを止めているので、当該箇所でハングアップすることはないと考えているのですが、どのあたりの処理でハングアップしているか、何か手がかりはないでしょうか。

可能かどうか未確認の思い付きレベルですが、SSHポート転送でのバッファリング処理と同じように、ある程度データが溜まった場合は受信を一時的に止めるという事は出来ないでしょうか?

できそうな感じなので、ブランチ作って検証を進めます。

修正

r6528 適用済み
diff -r7943:7953 on branches/scp_flowctrl 未適用

ttssh2-devel 4065

cf. https://lists.osdn.me/mailman/private/ttssh2-devel/2019-August/004065.html

このページには FD_READ イベントの発生条件として以下のように書かれています。

When WSAAsyncSelect is called, if there is data currently available to receive.

When data arrives, if FD_READ is not already posted.

After recv or recvfrom is called, with or without MSG_PEEK), if data is still available to receive.

この内の 1 に該当していますね。 Reenabling Function は 2 の新しいデータが来た時に再度イベントが発生する条件なので、別枠の話でしょう。

recv_data()を呼ばないようにすると ssh 通信全体が止まってしまい、他のチャネルも止まる事になるので嬉しくないですよね。

即応性も無く、修正箇所も増えて面倒ですが、該当のチャネルだけ一時的に SSH_MSG_CHANNEL_WINDOW_ADJUST を送らないようにはできないでしょうか?

ticket #39297 SSHリモートポートフォワード使用中に異常終了

cf. https://osdn.net/projects/ttssh2/ticket/39297

インターネットに出られないサーバ(以下、対象サーバ)に対して、TeraTermの SSHリモートポートフォワードを使って社内LANのProxyサーバと接続し、対象サーバ上でISOファイル等の大きなファイルをインターネットからwgetすると、 TeraTermが異常終了する(「TeraTermは動作を停止しました」のダイアログが出る)。この時、wget開始から異常終了直前までメモリが増え続けているように見える。上記ダイアログのボタンからTeraTermプログラムを終了させるとメモリが減る (wget開始前の容量に戻る)。

修正

r7732
r7736
r7737
r7764
r7945
diff -r7731:7764 on branches/portfwd_memleak

修正ブランチが portfwd_memleak と言う名前だが、メモリリークを起こしているわけではない。

ここでポートフォワードに対して入れられた「フロー制御」は、受信側の window size によって送信側の送信を制御するフロー制御ではなく（それは実装されている）、受信側が受信（読み取り）を（受け取ったデータを書き込んでバッファが空くまで）一時停止することで送信をコントロールすることを指していると思われる。

zmatsuo commented 11 months ago

ありがとうございます。通信の仕様が理解できてきました。今の理解を図にしました。

#15_1007_19.zip

zmatsuo commented 11 months ago

r10960に修正を入れました。試していただけないでしょうか。

以下修正内容です。

SCP受信時にファイル書き込みスレッドで、 GUI関連の処理を行わないようにすると受信データが溜まらずに書き込まれるようになったのは、

受信スレッド(=GUIスレッド)が受信処理をしていて、データがとても速く送られくるときた時、他のメッセージ処理に時間が割けないようです。

多分、受送信の暗号化処理も受信スレッド(=GUIスレッド)で行われるためとても処理が重くなるんじゃないかと思います。

と書きました。

このとても処理が重くなる原因ですが、WSAAsyncSelect() の、

When WSAAsyncSelect is called, if there is data currently available to receive.

で、FD_READが発生しますが、これが最優先で処理される(GUIスレッドのメッセージキューの先頭に積まれる)ようです。 (ドキュメントにはありませんが、こう解釈するとつじつまがあいます)

なので、サーバーからTera Termへの送信がとても速いとき、つねにFD_READが発生して他のメッセージ処理が行えなくなります。

ファイル書き込みスレッドで、 GUI関連の処理を行わないようにすると受信データが溜まらずに書き込まれるようになりますが、「キャンセル」ボタンが押せない、VTWinに文字が入れられない、メニューが動かないという状態になります。

そこで、サーバーからのデータを受信しない状態をほんの少し作ってメッセージ処理を行えるようにしました。

通常、ウィンドウサイズの更新を常に行って、サーバーからのデータをいつでも受信できるようにしています。

サーバーからのデータがとても速くデータがメモリにしきい値(1MByte)以上溜まる(ファイル書き込みスレッドが追いつかない) 状態になると、ウィンドウサイズの更新を止めます。そして、しきい値(0byte)までメモリ上のデータが減ったとき、ウィンドウサイズの更新を再開します。

この間にGUI関連の処理を行う隙間ができるため今まで通り処理ができます。

USBメモリなどファイル書き込みが遅いときはメモリ使用量が増えることが抑制されます。

サーバーからのデータが従来通りの速度の時は、 FD_READが緩慢に発生するので従来通りになります。

ウィンドウサイズを更新を行わない = そのうちサーバーからデータが来なくなる = フロー制御と考えられますね。

nmaya commented 11 months ago

ありがとうございます。試してみました。

ファイルの転送はうまくいっています。
使用メモリは増加しなくなりました。
ダイアログの表示は「1MBぶん勢いよく受信する」「減速する」を繰り返しているように見えます。
r10961 の修正を入れました。送受信部分への修正ではありません。

受信終了時に assert に引っかかることがあります。


// SDK71_GRMSDKX_EN_DVD.iso (598,589,440 bytes) を受信した場合

Assertion failed!

Program: T:\ttssh2-trunk\ttssh2\ttxssh\Debug\ttxssh.dll File: T:\ttssh2-trunk\ttssh2\ttxssh\ssh.c Line: 8764

Expression: pvar->recv.timer_id == 0

zmatsuo commented 11 months ago

ありがとうございます。

ダイアログの表示は「1MBぶん勢いよく受信する」「減速する」を繰り返しているように見えます。

ダイアログの表示はファイルへ書き込んだ時点の値で、受信サイズ、受信バッファサイズはダイアログには表示されていません。

1MBというのが受信バッファのしきい値に関係ありそうです。 ssh.h の SCPRCV_HIGH_WATER_MARK, SCPRCV_LOW_WATER_MARK を調整すると動作が変わりそうです。もっと最適な値がある気はします。通信速度、ストレージ書き込み速度、CPU速度,コア数なども影響しそうです。

Tera Termが反応しなくなったり、キャンセルボタンが押せないということはないでしょうか?

受信終了時に assert に引っかかることがあります。

手もとで調べていて、リモート(sshサーバー側)に存在しないファイルを指定したときも落ちるようです。しらべます。 (4-stableへの反映は後回しにします。)

nmaya commented 11 months ago

ダイアログの表示はファイルへ書き込んだ時点の値で、受信サイズ、受信バッファサイズはダイアログには表示されていません。

通信ならバッファがあふれてからバッファが0になるまでピタッと止まるはずだと思いましたが、書き込みバイト数であればこの動作に納得しました。

Tera Termが反応しなくなったり、キャンセルボタンが押せないということはないでしょうか?

VTWindow ではコマンドを打てます。SCP転送ダイアログも、タイトルバーをドラッグして動かしたり、キャンセルボタンを押してキャンセルできます。

zmatsuo commented 11 months ago

VTWindow ではコマンドを打てます。SCP転送ダイアログも、タイトルバーをドラッグして動かしたり、キャンセルボタンを押してキャンセルできます。

確認ありがとうございます。

受信終了時に assert に引っかかることがあります。

このassert()は不要のはずです。削除しました。(r10966)

リモート(sshサーバー側)に存在しないファイルを指定したときも落ちる

これも手を入れました。(r10967)

TeraTermProject / osdn-download