SoftEther VPN User Forum

Posted: **Fri Apr 04, 2014 6:56 am**

お世話になります。

下記のような現象が発生していますので報告します。

VPNクライアント単独で、VPNサーバに接続できない状態のときの現象です。
（通信がサーバまで到達しないとか、ログイン接続エラーになるとか）
クライアント設定で、再接続間隔は15秒、無限に再接続を試行するにしています。

システム上のリソースを観察していると、UDPでファイルディスクリプタの使用量が上昇していくようです。
現象を顕著にするために、VPN接続設定を50個ほど作成して、すべて接続エラーの状態のままにすると、
システムによると思いますが、５時間ほどでファイルディスクリプタの上限に達して、
システムへのログインや各種コマンドの動作でエラーや無応答が発生します。

VPNクライアントがUDPで接続を試行して、そのタイムアウト時にファイルディスクリプタを解放していないように思えます。

●VPN起動前の最初の情報

[]# netstat -uanp
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
udp 0 0 172.16.100.1:137 0.0.0.0:* 11732/nmbd
udp 0 0 0.0.0.0:137 0.0.0.0:* 11732/nmbd
udp 0 0 172.16.100.1:138 0.0.0.0:* 11732/nmbd
udp 0 0 0.0.0.0:138 0.0.0.0:* 11732/nmbd
udp 0 0 0.0.0.0:161 0.0.0.0:* 4066/snmpd

●VPN起動後、エラー

[root@nsk51003 etc]# netstat -uanp
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
udp 0 0 0.0.0.0:47744 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:56192 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:50048 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:59904 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:58497 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:55809 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:39553 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:37889 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:37761 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:57474 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:45954 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:59778 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:40450 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:37891 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:39683 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:42627 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:39939 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:56324 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:57988 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:35332 0.0.0.0:* 28934/vpnclient
udp 0 0 0.0.0.0:43652 0.0.0.0:* 28934/vpnclient
(省略)...

●VPN起動後、接続エラーがつづくと、どんどん増加していく。

[]# date
Fri Apr 4 15:44:17 JST 2014
[]# netstat -uanp | grep vpnclient | wc
1114 6684 121426

[]# date
Fri Apr 4 15:44:21 JST 2014
[]# netstat -uanp | grep vpnclient | wc
1162 6972 126658

[]# date
Fri Apr 4 15:44:34 JST 2014
[]# netstat -uanp | grep vpnclient | wc
1205 7230 131345

[]# date
Fri Apr 4 15:44:39 JST 2014
[]# netstat -uanp | grep vpnclient | wc
1218 7308 132762

[]# date
Fri Apr 4 15:49:49 JST 2014
[]# netstat -uanp | grep vpnclient | wc
2440 14640 265960

-----------------------

1. オペレーティングシステムの名前および CPU ビット

　CentOS release 4.3 (Final) 32 bit
　CentOS release 5.5 (Final) 32 bit

4. SoftEther VPN のビルド番号
5. どの SoftEther VPN のコンポーネントを使用していますか?

　softether-vpnclient-v4.06-9435-beta-2014.03.26-linux-x86-32bit.tar.gz (4.66 MB)

6. VPN サーバーとインターネットとの間に NAT やファイアウォールデバイスはありますか?
(もし NAT またはファイアウォールがある場合、VPN サーバーの TCP リスナポートに対して TCP ポートを開く必要があります。)

　VPNクライアント単独状態での現象

7. SecureNAT 機能を使用していますか?

　いいえ

Posted: **Mon Apr 07, 2014 7:07 am**

追加情報です。

何かのタイミングによって、タイムアウトしたファイルディスクリプタをクローズするクローンが実行されていないようです。

・udpのソケットが残る場合：
　　cloneが実行されていない。
・udpのソケットが残らない場合：
　　下記のようにcloneが実行され、作成されたスレッドからudpのソケットがcloseされていています。
-----------------------------
12907 mmap2(NULL, 200000, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb746f000
12907 mprotect(0xb746f000, 4096, PROT_NONE) = 0
12907 clone(child_stack=0xb749f204, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED, parent_tidptr=0xb749f938, {entry_number:6, base_addr:0xb749f8f0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb749f938) = 12915
-----------------------------

できれば解析いただければと思います。
また、ソースも見てみたいと思いますが、該当のclone起動まわりの処理関数がどれかなど情報をいただけると、助かります。grepなどでいくつかのヒットがあるのですが、特定できておりません。

以下、それぞれのトレースしたログを添付いまします

■仮想NIC2個でクローズされている場合（クローンがある）
　※IPアドレスは「***.***.***.***」に置換しています。
　※仮想NIC2個の場合でも、ＦＤが増加する場合があるので、必ずクローズできているとはいえないようです。
-----------------------------
12907 socket(PF_INET, SOCK_DGRAM, IPPROTO_UDP) = 35
12907 bind(35, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
12907 setsockopt(35, SOL_SOCKET, SO_SNDBUF, [11911168], 4) = 0
12907 setsockopt(35, SOL_SOCKET, SO_RCVBUF, [11911168], 4) = 0
12907 getsockname(35, {sa_family=AF_INET, sin_port=htons(45710), sin_addr=inet_addr("0.0.0.0")}, [16]) = 0
12907 getsockopt(35, SOL_IP, IP_TTL, [64], [4]) = 0
12907 pipe([36, 37]) = 0
12907 ioctl(37, FIONBIO, [1]) = 0
12907 ioctl(36, FIONBIO, [1]) = 0
12907 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=125, ...}) = 0
12907 ioctl(35, FIONBIO, [1]) = 0
12907 write(37, "\1", 1) = 1
12907 mmap2(NULL, 200000, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb746f000
12907 mprotect(0xb746f000, 4096, PROT_NONE) = 0
12907 clone(child_stack=0xb749f204, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED, parent_tidptr=0xb749f938, {entry_number:6, base_addr:0xb749f8f0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb749f938) = 12915
12907 gettimeofday( <unfinished ...>
12915 futex(0x8672370, FUTEX_WAIT, 2, NULL <unfinished ...>
12907 <... gettimeofday resumed> {1396838534, 988822}, NULL) = 0

…　省略　…

12915 recvfrom(35, <unfinished ...>
12915 <... recvfrom resumed> 0x86890c8, 65536, 0, 0xb749ec00, 0xb749ebfc) = -1 EAGAIN (Resource temporarily unavailable)
12915 sendto(35, "\0\0d\210}\265#\321?:^w\256E\361D\304\324\202\27\334\21A\231\31\31\256\324\225\233\351eTA|\230u\240\305\t\216\22\3\33\253\344\7q\336+\3(\363x\3\221\6\370\271\347\246\305\303\v\3368\341\362\27\t\241\17\234|\f\337d\376\2304\270\205\221\357\f\233\25\251F\0304\251\372\242\331]\345\0=j\216\352\r\3366}0\33\204\230\370b\216\273\207E+", 117, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16 <unfinished ...>
12915 <... sendto resumed> ) = -1 EPERM (Operation not permitted)
12915 sendto(35, "\0\0\331\34}\265#\321\242\305Q)\233\302\346s\231Y#Z\262V=|>6\240\206\326\202\345\247\362U\240\3\213E\234! s\3314|\354B=\27\t\241\17\234|\f\337d\376\2304\270\205\221\357\f\233\25\251\2513\356Z\210I\320\r\340hG\233\22\315\250\234\26\24\346\2378\0\233$\351];\245l\202Y1\335\234\331\177\221\27U\17\3375\275\345\327\225\232\v\340\207\241\353\34\270J\340E\370o`\26679S\203\204\31\271Syd\224\203\265\350", 143, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16 <unfinished ...>
12915 <... sendto resumed> ) = -1 EPERM (Operation not permitted)
12915 sendto(35, "\0\0}u}\265#\321\3523\5{\231\r@\252\363\247?-\334\33\343\330\16\323\305[\373\264_\210\336\351\213\364\nDn\240Rm\30)r]}.\250\234\26\24\346\2378\0\233$\351];\245l\202Y1\335\234\216\246AI\341m\230h\361LB\337.\377\267\264\303l\33\231\324\267\202\22\20\222\233\332\214\2447\255>\206\212\241c\301\"\25f\275Z#}-\2370\345\2\340\233=\v\202:\4\364j\254\247\206\272\341 \215\22\222\204^\211\221?\7p\314(\31\300\272\347\303\22g\275T(\277\"*$\274\227j0\322\276\231a\245\377", 169, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16) = -1 EPERM (Operation not permitted)
12915 sendto(35, "\0\0{=}\265#\321\nG\311\215\270\373S\342?\337\f\240\344hgi\7\245J\367LB\366/N8R\tR\264\216\251NV\307\207-\341\td\250\234\26\24\346\2378\0\233$\351];\245l\202Y1\335\234\216\246AI\341m\230h\361LB\337.\377\267\264\303l\33\231\324\267\202\22\20\222\233\332\214\2447\255>\206\212\241\5\247Ds\0\333<E\33K\371V\203d\206\375[m\344\\b\222\f\312\301\340\334\207F\353t\364\3428\357\367Ya\26", 143, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16) = -1 EPERM (Operation not permitted)
12915 sendto(35, "\0\0\337G}\265#\321\244D\2731\314\336J\375@\341\320\216\263_|\203\272\345\243\335y\5\202\263\340J\361\262\37\316\247\271\"\351|1\341\212\365\367\33\231\324\267\202\22\20\222\233\332\214\2447\255>\206\212\241\5\247\213\236\7}p\321N%\245\"\330C\356*\23\306\327{K\256\235z]w\301\5\362o5\5\313\24\fA#\17\203\241\32\2\230`\275\347\200\300\7\305\25\5Lmn\375\5\216\260~B\217iW\371\237\0\3\316\242\211z\327", 139, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16) = -1 EPERM (Operation not permitted)
12915 sendto(35, "\10\0%4}\265#\321Z\240w\265\315c\237N\30c_\201\236\212\360\272\2743\vZ\327\235\340|\203$\202\216cC\36\311$\263\210\231\320@\260\342Zn;\25\251\333u\377\33XieM\366\v0\360\207B\202\273;\206\206\377\213\346H\242yU\331\231\350\4\360F\272\230\vj\252\375\212\22\307l\301\33x\10\235\316\302\247\267\357~w\376\210\254\251|A\300\261\277\274\231\221\211:\323{\274:\240I\222\271\v", 130, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16) = 130
12915 sendto(35, "\0\0#\211}\265#\321&p\210q\241G\343\1\266?\337Pu\200J\322l\271p\rq\4\342Qo\310/+\305\330\375q+\235B\271\27\300\231o", 48, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16) = -1 EPERM (Operation not permitted)
12915 sendto(35, "\17\0\24\211}\265#\321&p\210q\241G\343\1\266?\337Pu\200J\322l\271p\rq\4\342Qo\310/+\305\330\375q+\235B\271\27\300\231o", 48, 0, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("***.***.***.***")}, 16) = 48
12915 recvfrom(35, 0x86890c8, 65536, 0, 0xb749ec00, 0xb749ebfc) = -1 EAGAIN (Resource temporarily unavailable)
12915 write(37, "\1", 1) = 1
12915 close(35) = 0
-----------------------------

■仮想NIC62個でクローズされていない場合（クローンがない）
-----------------------------
32331 socket(PF_INET, SOCK_DGRAM, IPPROTO_UDP <unfinished ...>
32331 <... socket resumed> ) = 565
32331 bind(565, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}, 16 <unfinished ...>
32331 <... bind resumed> ) = 0
32331 setsockopt(565, SOL_SOCKET, SO_SNDBUF, [11911168], 4 <unfinished ...>
32331 <... setsockopt resumed> ) = 0
32331 setsockopt(565, SOL_SOCKET, SO_RCVBUF, [11911168], 4 <unfinished ...>
32331 <... setsockopt resumed> ) = 0
32331 getsockname(565, <unfinished ...>
32331 <... getsockname resumed> {sa_family=AF_INET, sin_port=htons(54528), sin_addr=inet_addr("0.0.0.0")}, [16]) = 0
32331 getsockopt(565, SOL_IP, IP_TTL <unfinished ...>
32331 <... getsockopt resumed> , [64], [4]) = 0
32331 pipe( <unfinished ...>
32331 <... pipe resumed> [604, 606]) = 0
32331 ioctl(606, FIONBIO <unfinished ...>
32331 <... ioctl resumed> , [1]) = 0
32331 ioctl(604, FIONBIO <unfinished ...>
32331 <... ioctl resumed> , [1]) = 0
32331 ioctl(565, FIONBIO <unfinished ...>
32331 <... ioctl resumed> , [1]) = 0
32331 write(606, "\1", 1 <unfinished ...>
32331 <... write resumed> ) = 1
32331 futex(0x869d6dc, FUTEX_WAKE, 1 <unfinished ...>
32331 <... futex resumed> ) = 1
32331 futex(0x869d6d8, FUTEX_WAKE, 1 <unfinished ...>
32331 <... futex resumed> ) = 0
32331 gettimeofday( <unfinished ...>
32331 <... gettimeofday resumed> {1396834666, 954328}, NULL) = 0
32331 clock_gettime(CLOCK_REALTIME, <unfinished ...>
-----------------------------

Posted: **Mon Apr 07, 2014 8:16 am**

もう１つ分かったことがありますので挙げます。

vpn_client.configファイルの各VPN接続設定のパラメタの
"PortUDP"を"0"から変更すると発生しなくなりました。
例えば、"Port"と同じ値。任意でも良さそうです（因果関係が不明ですが）。

---
declare root
{
bool DontSavePassword false
bool EnableVPNGateService false
byte EncryptedPassword ***
bool HideVPNGateServiceMessage false
bool PasswordRemoteOnly false
string UserAgent Mozilla/4.0$20(compatible;$20MSIE$206.0;$20Windows$20NT$205.1;$20.NET$20CLR$201.1.4322)
uint UseSecureDeviceId 0

declare AccountDatabase
{
declare Account0
{
bool CheckServerCert false
uint64 CreateDateTime 1396825569497
uint64 LastConnectDateTime 1396825569568
string ShortcutKey ***
bool StartupAccount true
uint64 UpdateDateTime 1396825569592

declare ClientAuth
{
uint AuthType 1
byte HashedPassword　***
string Username ***
}
declare ClientOption
{
string AccountName vpn_***
uint AdditionalConnectionInterval 1
uint ConnectionDisconnectSpan 0
string DeviceName ***
bool DisableQoS false
bool HalfConnection false
bool HideNicInfoWindow false
bool HideStatusWindow false
string Hostname ***
string HubName ***
uint MaxConnection 8
bool NoRoutingTracking false
bool NoTls1 false
bool NoUdpAcceleration true
uint NumRetry 4294967295
uint Port 443
uint PortUDP 0　★これを0から変更する
string ProxyName $
byte ProxyPassword $
uint ProxyPort 0
uint ProxyType 0
string ProxyUsername $
bool RequireBridgeRoutingMode true
bool RequireMonitorMode false
uint RetryInterval 15
bool UseCompress false
bool UseEncrypt true
}
}
}
declare ClientManagerSetting
{
bool EasyMode false
byte HashedPassword ***
bool LockMode true
}
declare CommonProxySetting
{
string ProxyHostName $
uint ProxyPort 0
uint ProxyType 0
string ProxyUsername $
}
declare Config
{
bool AllowRemoteConfig false
uint64 AutoDeleteCheckDiskFreeSpaceMin 1048576
string KeepConnectHost keepalive.softether.org
uint KeepConnectInterval 50
uint KeepConnectPort 80
uint KeepConnectProtocol 1
bool NoChangeWcmNetworkSettingOnWindows8 false
bool UseKeepConnect false
}
declare RootCA
{
}
declare UnixVLan
{
declare ***
{
bool Enabled true
string MacAddress ***
}
}
}
---

Posted: **Tue Apr 08, 2014 9:17 am**

さらに追加情報です。

USPを使用してDNSサーバへ自らのホスト名を問い合わせるようなことをしている処理部分のようです。
自装置内にDNSサーバを立てたところ、"unit PortUDP 0"でも問題が発生しなくなりました。

先の投稿の対処（ただし、無駄にDNSを外部に投げていてる）と、今回の対処(DNSサーバを自装置に立てる)ともに、元々処理の意図がわからないので、正しい対処であるか分からない状態です。

Posted: **Wed Apr 09, 2014 2:47 am**

バグレポートありがとうございました。

Linux 版においてメモリリークが発生していることを確認しました。
対策バージョン
SoftEther VPN Client (Ver 4.06, Build 9437) を
http://www.softether-download.com/
にアップロードさせていただきましたので、改善されているかどうかご確認いただければ幸いです。

よろしくお願い申し上げます。

Posted: **Wed Apr 09, 2014 11:55 pm**

お世話になります。

対策バージョンをダウンロードして試したところ、現象は発生しなくなりました。
ご対応ありがとうございました。

Posted: **Thu Apr 17, 2014 1:55 am**

お世話になります。

追加の確認をさせてください。
VPN Serverもアップデートされておりますが、
同様のメモリリークか何かがあり、修正されているのでしょうか？

下記の結果は古い以下のバージョンのものです。
softether-vpnserver-v2.00-9387-rtm-2013.09.16-linux-x64-64bit.tar.gz

freeコマンドの実行結果を時刻付で加工しています。
最後は下げ止まっていますが、それまではリニアにメモリ使用量が増加しています。
---
total used free shared buffers cached
2014/04/16 19:00:03 Mem: 2043524 603560 1439964 0 15572 194624
2014/04/16 20:00:02 Mem: 2043524 769648 1273876 0 21396 350192
2014/04/16 21:00:02 Mem: 2043524 934376 1109148 0 27076 505752
2014/04/16 22:00:01 Mem: 2043524 1104044 939480 0 32764 661328
2014/04/16 23:00:01 Mem: 2043524 1269296 774228 0 38456 816912
2014/04/17 00:00:00 Mem: 2043524 1435836 607688 0 44132 972476
2014/04/17 01:00:00 Mem: 2043524 1601208 442316 0 49412 1128092
2014/04/17 02:00:00 Mem: 2043524 1764800 278724 0 52872 1283984
2014/04/17 03:00:01 Mem: 2043524 1927572 115952 0 56300 1438164
2014/04/17 04:00:01 Mem: 2043524 1970048 73476 0 51460 1481272
2014/04/17 05:00:01 Mem: 2043524 1963620 79904 0 50760 1477232
2014/04/17 06:00:00 Mem: 2043524 1969124 74400 0 50320 1481984
2014/04/17 07:00:00 Mem: 2043524 1970360 73164 0 49832 1483044
2014/04/17 08:00:01 Mem: 2043524 1972728 70796 0 49488 1485320
2014/04/17 09:00:01 Mem: 2043524 1967124 76400 0 49492 1478320
---

SoftEther VPN User Forum

VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している

VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している

Re: VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している

Re: VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している

Re: VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している

Re: VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している

Re: VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している

Re: VPNクライアントがVPN接続エラー時にファイルディスクリプタを消費している