SoftEther VPNのクラッシュについて

[dorjpalam-batbaatar]

下記の環境でSoftEtherを運用しています。

SoftEther バージョン：4.42.9798
OS： AlmaLinux 9.3
カスケード接続：別サーバー（CentOS 7.9）で稼働するバージョン 4.29.9680のSoftEtherからカスケード接続があり、4.42.9798のサーバーではカスケード経由のVPN接続とサーバーに直接接続したVPN接続が混在しています。どちらもVPN内ではSecureNatでローカルのネットワーク上のAPサーバーと通信しています。

構成概要は下記のようになります。


(CentOS 7.9 / 4.29.9680) ----カスケード接続---> (AlmaLinux 9.3 / 4.42.9798) -----ローカルLAN---- (APサーバー)
　　　/\　　　　　　　　　　　　　　　　　　　　　　　　/\
　　　 |　　　　　　　　　　　　　　　　　　　　　　　　 |
　　VPN端末　　　　　　　　　　　　　　　　　　　　　VPN端末

VPN端末台数は合計で約360台で、10分おきにAPサーバーに向けて一斉にデータ送信します。

当初は 4.29.9680 の方にのみVPN端末が接続されており、APサーバーと通信していましたが、4.42.9798の方に
VPN端末を接続し始めたころから4.42.9798のvpnserverプロセスがSIGABRTで断続的にクラッシュするようになりました。
コアダンプは残っていないです。

4.29.9680からのカスケード接続を停止して、4.42.9798を単独で動作させるように変更してから数日経っていますが、
安定しているようでクラッシュはまだ発生していないです。

もう一つ、当初の 4.29.9680のみにVPN端末があったときは、クラッシュは起きていないですが、4.42.9798の方の
vpnserverプロセスの固有メモリ使用量が増加する一方で約1GiBまでになりました。4.42.9798の単独動作ではメモリ
増加はしますがずっと増え続けることはなくなりました。

上記のような現象について何かご存じでしたら情報共有お願いします。

[cedar]

VPN サーバーの処理能力を超えて送受信を行った場合、一時的にデータを貯めておくためにメモリの消費量が増えることがあります。
SecureNAT も、メモリ消費が増えやすいので、可能であればAPサーバーも直接仮想 HUB に繋いでしまったほうが安定するかも知れません。

[dorjpalam-batbaatar]

ご回答ありがとうございます。

現象が発生していたときの 4.42.9798 のVPNサーバーのCPU使用率は約20%、ピークでも40%で、100～150本のスレッドが常に
実行されていました。但しサーバースペックはCPUが2コア、メモリが4GiBでした。
CPU使用率だけみるとまだ余裕があるように見えますが、別の容認で処理制限がかかることはあり得るでしょうか。またこれが
クラッシュに繋がることは考えられますか。シスログからみると頻度は少ない（数回）ですが、１分未満の間隔で発生する
こともありました。
因みに現在はサーバースペックを上げて4コア、8GiBのメモリで動作させています。

[cedar]

実はクラッシュ(SIGABRT)については、高負荷の場合でも経験がなく原因は見当がつきません。
コアダンプが出せるようであれば、クラッシュが起きている場所を特定できるかも知れません。

[dorjpalam-batbaatar]

SoftEtherをsystemdで動かしており、コアダンプの出力設定を有効にしましたがやはりコアが出力されません。
シスログの/var/log/messagesには次のログが記録されます。

systemd-coredump[2256399]: Resource limits disable core dumping for process 2231098 (vpnserver).
systemd-coredump[2256399]: Process 2231098 (vpnserver) of user 0 dumped core.

そこでv4.42-9798のソースを確認しましたが、次の2カ所でコアダンプを無効にしていました。
Mayaqua/Kernel.c：
void AbortExit()
void AbortExitEx(char *msg)

もしここを通っていればコアダンプが出ないとは思いますが、後者の方は abort_error_log.txt ファイルを
作成するようになっており、このファイルもない様なので前者が候補になりますが、これが発生する
可能性は何があるでしょうか。VPNセッションを頻繁に切断、接続すると発生しやすいようです。

今回使っているのは下記からダウンロードしたバイナリです。
https://jp.softether-download.com/files ... bit.tar.gz

ダウンロードしたバイナリをAlmaLinux 9.3でビルド（リンク）して使っています。もし可能でしたら
このバイナリをビルドした条件（コンパイラ及び使用したライブラリのバージョン等）を教えて頂けない
でしょうか。確認でコアダンプの無効化なしで動作させてみたいと思います。

[cedar]

デバッグビルドを作成されるのであれば、バイナリ版ではなくソース版を使用するのが良いかと思います。

[dorjpalam-batbaatar]

デバッグビルドしてコアダンプが取得できました。クラッシュが起きている箇所はいくつかありますが、いずれもFree()関数の中で「CheckMemTag2: tag2->Magic != canary_memtag_magic2」のエラーです。下記はクラッシュ時のスタックトレースです。

１）このパターンが一番多いです。
#0 0x00007efca02a154c in __pthread_kill_implementation () from /lib64/libc.so.6
#1 0x00007efca0254d06 in raise () from /lib64/libc.so.6
#2 0x00007efca02287f3 in abort () from /lib64/libc.so.6
#3 0x0000000000519700 in AbortExitEx (msg=0x5c59c8 "CheckMemTag2: tag2->Magic != canary_memtag_magic2") at src/Mayaqua/Kernel.c:2505
#4 0x00000000004112b3 in CheckMemTag2 (tag=0x7efc80a86c88) at src/Mayaqua/Memory.c:4857
#5 0x00000000004111c7 in Free (addr=0x7efc80a86c70) at src/Mayaqua/Memory.c:4814
#6 0x0000000000410216 in FreeBuf (b=0x7efc80a86c70) at src/Mayaqua/Memory.c:4133
#7 0x000000000047c209 in OvsSendControlPacketWithAutoSplit (c=0x7efc8c88b9f0, opcode=4 '\004', data=0x7efc8cd31360 "\027\003\003", data_size=56) at src/Cedar/Interop_OpenVPN.c:1265
#8 0x000000000047e428 in OvsRecvPacket (s=0x7efc8cf6ff70, recv_packet_list=0x7efc8cfdcb70, protocol=1) at src/Cedar/Interop_OpenVPN.c:2245
#9 0x000000000047f870 in OvsPerformTcpServer (cedar=0x24af2a0, sock=0x7efc7510a4f0) at src/Cedar/Interop_OpenVPN.c:2926
#10 0x0000000000467bba in ConnectionAccept (c=0x7efc8c885990) at src/Cedar/Connection.c:3121
#11 0x000000000048f1ac in TCPAcceptedThread (t=0x7efc74eb6e50, param=0x7efc7555bb20) at src/Cedar/Listener.c:267
#12 0x0000000000515f87 in ThreadPoolProc (t=0x7efc64aee320, param=0x7efc643127e0) at src/Mayaqua/Kernel.c:1062
#13 0x000000000045c176 in UnixDefaultThreadProc (param=0x7efc64343210) at src/Mayaqua/Unix.c:1723
#14 0x00007efca029f802 in start_thread () from /lib64/libc.so.6
#15 0x00007efca023f450 in clone3 () from /lib64/libc.so.6

２）もう一つのパターンです。
#0 0x00007efca02a154c in __pthread_kill_implementation () from /lib64/libc.so.6
#1 0x00007efca0254d06 in raise () from /lib64/libc.so.6
#2 0x00007efca02287f3 in abort () from /lib64/libc.so.6
#3 0x0000000000519700 in AbortExitEx (msg=0x5c59c8 "CheckMemTag2: tag2->Magic != canary_memtag_magic2") at src/Mayaqua/Kernel.c:2505
#4 0x00000000004112b3 in CheckMemTag2 (tag=0x7efc98d1b7a8) at src/Mayaqua/Memory.c:4857
#5 0x00000000004111c7 in Free (addr=0x7efc98d1b790) at src/Mayaqua/Memory.c:4814
#6 0x0000000000433f27 in FreeUdpPacket (p=0x7efc7ca3b6d0) at src/Mayaqua/Network.c:21541
#7 0x000000000047f8b2 in OvsPerformTcpServer (cedar=0x24af2a0, sock=0x7efc68e71d20) at src/Cedar/Interop_OpenVPN.c:2933
#8 0x0000000000467bba in ConnectionAccept (c=0x7efc7d4f6dc0) at src/Cedar/Connection.c:3121
#9 0x000000000048f1ac in TCPAcceptedThread (t=0x7efc68c40fd0, param=0x7efc68279740) at src/Cedar/Listener.c:267
#10 0x0000000000515f87 in ThreadPoolProc (t=0x7efc9443d020, param=0x7efc94427ae0) at src/Mayaqua/Kernel.c:1062
#11 0x000000000045c176 in UnixDefaultThreadProc (param=0x7efc9443f430) at src/Mayaqua/Unix.c:1723
#12 0x00007efca029f802 in start_thread () from /lib64/libc.so.6
#13 0x00007efca023f450 in clone3 () from /lib64/libc.so.6

３）ここでも発生しています。
#0 0x00007efca02a154c in __pthread_kill_implementation () from /lib64/libc.so.6
#1 0x00007efca0254d06 in raise () from /lib64/libc.so.6
#2 0x00007efca02287f3 in abort () from /lib64/libc.so.6
#3 0x0000000000519700 in AbortExitEx (msg=0x5c59c8 "CheckMemTag2: tag2->Magic != canary_memtag_magic2") at src/Mayaqua/Kernel.c:2505
#4 0x00000000004112b3 in CheckMemTag2 (tag=0x7efc7c1caa88) at src/Mayaqua/Memory.c:4857
#5 0x00000000004111c7 in Free (addr=0x7efc7c1caa70) at src/Mayaqua/Memory.c:4814
#6 0x000000000047ecd0 in OvsSendPacketNow (s=0x7efc7c034370, se=0x7efc7c8bfda0, p=0x7efc7c187840) at src/Cedar/Interop_OpenVPN.c:2476
#7 0x000000000047e5aa in OvsRecvPacket (s=0x7efc7c034370, recv_packet_list=0x7efc7c84d1b0, protocol=1) at src/Cedar/Interop_OpenVPN.c:2278
#8 0x000000000047f870 in OvsPerformTcpServer (cedar=0x24af2a0, sock=0x7efc683a99d0) at src/Cedar/Interop_OpenVPN.c:2926
#9 0x0000000000467bba in ConnectionAccept (c=0x7efc7d0b1a60) at src/Cedar/Connection.c:3121
#10 0x000000000048f1ac in TCPAcceptedThread (t=0x7efc6877ddb0, param=0x7efc696d6820) at src/Cedar/Listener.c:267
#11 0x0000000000515f87 in ThreadPoolProc (t=0x7efc98123e60, param=0x7efc981228f0) at src/Mayaqua/Kernel.c:1062
#12 0x000000000045c176 in UnixDefaultThreadProc (param=0x7efc980ea7b0) at src/Mayaqua/Unix.c:1723
#13 0x00007efca029f802 in start_thread () from /lib64/libc.so.6
#14 0x00007efca023f450 in clone3 () from /lib64/libc.so.6

４）
#0 0x00007efca02a154c in __pthread_kill_implementation () from /lib64/libc.so.6
#1 0x00007efca0254d06 in raise () from /lib64/libc.so.6
#2 0x00007efca02287f3 in abort () from /lib64/libc.so.6
#3 0x0000000000519700 in AbortExitEx (msg=0x5c59c8 "CheckMemTag2: tag2->Magic != canary_memtag_magic2") at src/Mayaqua/Kernel.c:2505
#4 0x00000000004112b3 in CheckMemTag2 (tag=0x7efc8c709258) at src/Mayaqua/Memory.c:4857
#5 0x00000000004111c7 in Free (addr=0x7efc8c709240) at src/Mayaqua/Memory.c:4814
#6 0x000000000047ca51 in OvsSendDataPacket (c=0x7efc7131c930, key_id=0 '\000', data_packet_id=1, data=0x63bab0 <ping_signature>, data_size=16) at src/Cedar/Interop_OpenVPN.c:1516
#7 0x000000000047ea17 in OvsRecvPacket (s=0x7efc70c2f070, recv_packet_list=0x7efc710ef400, protocol=1) at src/Cedar/Interop_OpenVPN.c:2399
#8 0x000000000047f870 in OvsPerformTcpServer (cedar=0x24af2a0, sock=0x7efc74c52360) at src/Cedar/Interop_OpenVPN.c:2926
#9 0x0000000000467bba in ConnectionAccept (c=0x7efc711ee3e0) at src/Cedar/Connection.c:3121
#10 0x000000000048f1ac in TCPAcceptedThread (t=0x7efc7516d160, param=0x7efc74b65ec0) at src/Cedar/Listener.c:267
#11 0x0000000000515f87 in ThreadPoolProc (t=0x3008580, param=0x3008100) at src/Mayaqua/Kernel.c:1062
#12 0x000000000045c176 in UnixDefaultThreadProc (param=0x2ffd2b0) at src/Mayaqua/Unix.c:1723
#13 0x00007efca029f802 in start_thread () from /lib64/libc.so.6
#14 0x00007efca023f450 in clone3 () from /lib64/libc.so.6

５）
#0 0x00007efca02a154c in __pthread_kill_implementation () from /lib64/libc.so.6
#1 0x00007efca0254d06 in raise () from /lib64/libc.so.6
#2 0x00007efca02287f3 in abort () from /lib64/libc.so.6
#3 0x0000000000519700 in AbortExitEx (msg=0x5c59c8 "CheckMemTag2: tag2->Magic != canary_memtag_magic2") at src/Mayaqua/Kernel.c:2505
#4 0x00000000004112b3 in CheckMemTag2 (tag=0x7efc64ea6218) at src/Mayaqua/Memory.c:4857
#5 0x00000000004111c7 in Free (addr=0x7efc64ea6200) at src/Mayaqua/Memory.c:4814
#6 0x00000000004226f3 in UnixSelectInner (num_read=3, reads=0x7efc9e6d0d60, num_write=0, writes=0x7efc9e6d0c60, timeout=256) at src/Mayaqua/Network.c:9485
#7 0x0000000000421ebe in UnixSelect (set=0x7efc9e6d0f50, timeout=256, c1=0x7efc64c54b60, c2=0x7efc64229c50) at src/Mayaqua/Network.c:9166
#8 0x0000000000425778 in Select (set=0x7efc9e6d0f50, timeout=256, c1=0x7efc64c54b60, c2=0x7efc64229c50) at src/Mayaqua/Network.c:12843
#9 0x0000000000464b1d in ConnectionReceive (c=0x7efc642a16d0, c1=0x7efc64c54b60, c2=0x7efc64229c50) at src/Cedar/Connection.c:1782
#10 0x00000000004d7a96 in SessionMain (s=0x7efc649d3790) at src/Cedar/Session.c:353
#11 0x00000000004a7273 in ServerAccept (c=0x7efc642a16d0) at src/Cedar/Protocol.c:4223
#12 0x0000000000467e39 in ConnectionAccept (c=0x7efc642a16d0) at src/Cedar/Connection.c:3173
#13 0x000000000048f1ac in TCPAcceptedThread (t=0x7efc98829a50, param=0x7efc98814330) at src/Cedar/Listener.c:267
#14 0x0000000000515f87 in ThreadPoolProc (t=0x7efc980efc00, param=0x7efc980de6b0) at src/Mayaqua/Kernel.c:1062
#15 0x000000000045c176 in UnixDefaultThreadProc (param=0x7efc980efee0) at src/Mayaqua/Unix.c:1723
#16 0x00007efca029f802 in start_thread () from /lib64/libc.so.6
#17 0x00007efca023f450 in clone3 () from /lib64/libc.so.6

発生条件は下記です。
・VPNセッションはOpenVPNで300本
・vpnserverのスレッド数は約950本
・VPNセッションは5分周期で切断、接続を繰り返す
・VPN接続後、SecureNat経由でAPサーバーにデータ送信（平均して約1MB/sのデータ量）

[cedar]

いずれもメモリ開放時の領域破壊チェックで引っかかっているように見えます。
バッファオーバーランの可能性が高いですが、メモリの故障の可能性も若干あります。

[dorjpalam-batbaatar]

新たに分かったことを共有します。偶然かもしれませんがメモリの壊れ方に特徴があります。CheckMemTag2()でエラーになっているのはバッファー解放時に、バッファーの後ろに設定したMEMTAG2のマジック番号が計算値と一致しないためでした。数十回発生していますがすべてがこれです。
コアダンプを見るとメモリ割り当て時に設定したMEMTAG2のマジック番号が、計算値より1つだけ大きい値です。
CheckMemTag2()内で下記のテストをしていますが、tag->Magicが

Code: Select all

(canary_memtag_magic2 ^ ((UINT64)tag * GOLDEN_RATION_PRIME_U64))

より1つだけ大きいです。

また、関連があるか不明ですが、これが発生しているときのバッファーの割り当てサイズが24（実際の要求サイズが20バイトの場合もあり、割り当てるときは8の倍数にしているので24になります）バイトです。

もう一つ、

Code: Select all

void OvsSendControlPacketWithAutoSplit(OPENVPN_CHANNEL *c, UCHAR opcode, UCHAR *data, UINT data_size)

を通るパターンでは取得しているバッファーは

Code: Select all

struct BUF

のタイプで、この構造体自体には書込みしていない（構造体のメンバーのセットはしています）ですが、バッファー解放時で上記エラーが発生しています。

この状況から何が考えられるでしょうか。

[cedar]

これもメモリの故障である可能性を補強しているように思われます。
一度メモリテストを行われてみるか、他のPCでテストを行うことをお勧めします。