Ticket #25835

SSH認証ダイアログで数秒の待ちが発生する

Open Date: 2011-07-28 00:51 Last Update: 2011-08-16 21:37

Reporter:
Owner:
(None)
Type:
Status:
Closed
Component:
MileStone:
(None)
Priority:
5 - Medium
Severity:
5 - Medium
Resolution:
Fixed
File:
None
Vote
Score: 0
No votes
0.0% (0/0)
0.0% (0/0)

Details

「新しい接続」ダイアログよりIPアドレスを入力し「OK」をクリックすると、「SSH認証」ダイアログが表示されますが、 数秒間の間マウスカーソル+砂時計の状態となり、ユーザ名/パスフレーズの入力ができません。

(数秒待つと(この環境では)rhosts(SSH1)を使うがグレーアウトされ、砂時計が消え、ユーザ名/パスフレーズが入力できるようになります。)

この待ちをなくすことは可能でしょうか。

パケットキャプチャを見ると、サーバから「Server: Key Exchange Init」のパケットが 来てACKを返した後、待ち状態となり、クライアントが3秒後に「Client: Key Exchange Init」の パケットを送信しています。ですので、クライアント側の問題なのですが、この間に時間の かかる処理があるのでしょうか。

時系列にすると、以下の通りとなります(ログは秒の精度なので、多少前後するとは思います)。

  00:06:59.58 パケット: 「Client Protocol: SSH-2.0-TTSSH/2.57...」
  00:06:59    ログ:     「name: client ID」のメッセージ
  00:06:59.58 パケット: 「Server: Key Exchange Init」受信
  (00:06:59.78 パケット:「Server: Key Exchange Init」に対するACK送信)
   (空白の3秒)
  00:07:02    ログ:     「name: KEXINIT」「description: exchange algorithm list: receiving」のメッセージ
  00:07:02.38 パケット   「Client: Key Exchange Init」送信

■環境 ・Windows Vista ・TeraTerm 4.70

■ログ

TTSSH.LOG
~~~
Thu Jul 28 00:06:59 2011 [5660] ---------------------------------------------------------------------
Thu Jul 28 00:06:59 2011 [5660] Initiating SSH session
Thu Jul 28 00:06:59 2011 [5660] Received server prologue string: SSH-2.0-OpenSSH_5.1p1 Debian-5
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_KEXINIT was sent at SSH2_send_kexinit().
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_KEXINIT was received.
Thu Jul 28 00:07:02 2011 [5660] KEX algorithm: diffie-hellman-group-exchange-sha256
Thu Jul 28 00:07:02 2011 [5660] server host key algorithm: ssh-rsa
Thu Jul 28 00:07:02 2011 [5660] encryption algorithm client to server: aes256-ctr
Thu Jul 28 00:07:02 2011 [5660] encryption algorithm server to client: aes256-ctr
Thu Jul 28 00:07:02 2011 [5660] MAC algorithm client to server: hmac-sha1
Thu Jul 28 00:07:02 2011 [5660] MAC algorithm server to client: hmac-sha1
Thu Jul 28 00:07:02 2011 [5660] compression algorithm client to server: none
Thu Jul 28 00:07:02 2011 [5660] compression algorithm server to client: none
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_KEX_DH_GEX_REQUEST was sent at SSH2_dh_gex_kex_init().
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_KEX_DH_GEX_GROUP was received.
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_KEX_DH_GEX_INIT was sent at handle_SSH2_dh_gex_group().
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_KEX_DH_GEX_REPLY was received.
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_NEWKEYS was sent at handle_SSH2_dh_gex_reply().
Thu Jul 28 00:07:02 2011 [5660] SSH2_MSG_NEWKEYS was received(DH key generation is completed).
~~~

ssh2connect.log(抜粋)
~~~
<<< Tera Term SSH2 log dump >>>
saved time: 2011/07/28 00:07:02

============================================
name: pure server ID
--------------------------------------------
description: start protocol version exchange
--------------------------------------------
time: Thu Jul 28 00:06:59 2011
============================================
00000000 : 5353482D 322E302D 4F70656E 5353485F     SSH-2.0-OpenSSH_
00000010 : 352E3170 31204465 6269616E 2D350D0A     5.1p1 Debian-5..



============================================
name: server ID
--------------------------------------------
description: (null)
--------------------------------------------
time: Thu Jul 28 00:06:59 2011
============================================
00000000 : 5353482D 322E302D 4F70656E 5353485F     SSH-2.0-OpenSSH_
00000010 : 352E3170 31204465 6269616E 2D35         5.1p1 Debian-5



============================================
name: client ID
--------------------------------------------
description: (null)
--------------------------------------------
time: Thu Jul 28 00:06:59 2011
============================================
00000000 : 5353482D 322E302D 54545353 482F322E     SSH-2.0-TTSSH/2.
00000010 : 35372057 696E3332                      57 Win32



============================================
name: KEXINIT
--------------------------------------------
description: exchange algorithm list: receiving
--------------------------------------------
time: Thu Jul 28 00:07:02 2011
============================================
00000000 : 6D93756C 9805D5BF BEF0E76F BAA498E5     m.ul.......o....
00000010 : 0000007E 64696666 69652D68 656C6C6D     ...~diffie-hellm
00000020 : 616E2D67 726F7570 2D657863 68616E67     an-group-exchang
00000030 : 652D7368 61323536 2C646966 6669652D     e-sha256,diffie-
00000040 : 68656C6C 6D616E2D 67726F75 702D6578     hellman-group-ex
00000050 : 6368616E 67652D73 6861312C 64696666     change-sha1,diff
00000060 : 69652D68 656C6C6D 616E2D67 726F7570     ie-hellman-group
00000070 : 31342D73 6861312C 64696666 69652D68     14-sha1,diffie-h
00000080 : 656C6C6D 616E2D67 726F7570 312D7368     ellman-group1-sh
00000090 : 61310000 000F7373 682D7273 612C7373     a1....ssh-rsa,ss
(略)
~~~

■パケット

http://twitpic.com/5wpkrq/full

Ticket History (3/10 Histories)

2011-07-28 00:51 Updated by: sunnyone
  • New Ticket "SSH認証ダイアログで数秒の待ちが発生する" created
2011-07-28 01:23 Updated by: sunnyone
Comment

ソースを見ると「00:07:02」(待ち発生後)の「SSH2_MSG_KEXINIT was sent at SSH2_send_kexinit().」 のメッセージを出しているのはttxssh/ssh.cの中の以下の部分のようです。

static BOOL handle_SSH2_kexinit(PTInstVar pvar)
{
	char buf[1024];
	char *data;
	int len, i, size;
	int offset = 0;
	char *msg = NULL;
	char tmp[1024+512];
	char str_keytype[20];

	notify_verbose_message(pvar, "SSH2_MSG_KEXINIT was received.", LOG_LEVEL_VERBOSE);

「handle_SSH2_kexinit」は「static void init_protocol(PTInstVar pvar)」の中の 以下の部分で、ハンドラという形で設定されているようです。

enque_handler(pvar, SSH2_MSG_KEXINIT, handle_SSH2_kexinit);

このSSH2_MSG_KEYINITはどこで呼ばれるかというと、以下の部分に見受けられます。

BOOL SSH_handle_server_ID(PTInstVar pvar, char FAR * ID, int ID_len)
{
(略)
					push_memdump("server ID", NULL, pvar->server_version_string, strlen(pvar->server_version_string));
					push_memdump("client ID", NULL, pvar->client_version_string, strlen(pvar->client_version_string));

					// (略)
					init_protocol(pvar);

					SSH2_dispatch_init(1);
					SSH2_dispatch_add_message(SSH2_MSG_KEXINIT);

ログと照らし合わせると「client ID」のパケットログ出力時ではまだ待ちが発生しておらず、 「SSH2_MSG_KEXINIT was received.」のログ出力時には待ちが終わっているという状況ですが、 ssh.cだけを見ると、その間にほとんど処理があるように見えません。

局所的なソースしか読んでいないので想像なのですが、SSH2_dispatch_add_messageは handle_messagesという配列にデータをセットするだけのようなので、 今回の状況では、SSH2_dispatch_add_message(SSH2_MSG_KEXINIT)の前にパケットが到着していて、 handle_messagesを走査するようなディスパッチャがadd_messageした直後に走らず、なんらかの タイムアウト or 次のパケット到着等を待つことになり、そこで待ちになっているというのは 考えられないでしょうか。

(だとすると、dispatch_add_message(SSH2_MSG_KEYINIT)の後にテーブルを走査してイベントを fireする処理を入れる必要があると思います。)

2011-07-28 18:06 Updated by: (del#1144)
  • Component Update from (None) to TTSSH
Comment

ログの出力箇所を増やしてみましたが、これでどうなりますか?

http://ttssh2.sourceforge.jp/snapshot/snapshot-20110728.zip

2011-07-28 21:49 Updated by: sunnyone
Comment

以下の通りとなります。何かわかりますでしょうか。

■時系列

21:29:42.823   ログ:Sent client identification string: SSH-2.0-TTSSH/2.57...
21:29:42.830   パケット送信:Client Protocol: SSH-2.0-TTSSH/2.5...
21:29:42.831   パケット受信:ACK
21:29:42.833   パケット受信:Server: Key Exchange Init
21:29:43.022   パケット送信:ACK
   (空白の2秒)
21:29:45.022   ログ:client proposal: KEX algorithm: ecdh-sha2...
      (.038までclient proposalのログ)
21:29:45.039   パケット送信:Client: Key Exchange Init

■TTSSH.LOG

Thu Jul 28 21:29:42.760 2011 [5512] ---------------------------------------------------------------------
Thu Jul 28 21:29:42.760 2011 [5512] Initiating SSH session
Thu Jul 28 21:29:42.823 2011 [5512] Received server identification string: SSH-2.0-OpenSSH_5.1p1 Debian-5
Thu Jul 28 21:29:42.823 2011 [5512] Sent client identification string: SSH-2.0-TTSSH/2.57 Win32
Thu Jul 28 21:29:45.022 2011 [5512] client proposal: KEX algorithm: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Thu Jul 28 21:29:45.022 2011 [5512] client proposal: server host key algorithm: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss
Thu Jul 28 21:29:45.022 2011 [5512] client proposal: encryption algorithm client to server: aes256-ctr,aes256-cbc,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128,arcfour,cast128-ctr,cast128-cbc
Thu Jul 28 21:29:45.022 2011 [5512] client proposal: encryption algorithm server to client: aes256-ctr,aes256-cbc,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128,arcfour,cast128-ctr,cast128-cbc
Thu Jul 28 21:29:45.022 2011 [5512] client proposal: MAC algorithm client to server: hmac-sha1,hmac-ripemd160@openssh.com,hmac-md5
Thu Jul 28 21:29:45.022 2011 [5512] client proposal: MAC algorithm server to client: hmac-sha1,hmac-ripemd160@openssh.com,hmac-md5
Thu Jul 28 21:29:45.038 2011 [5512] client proposal: compression algorithm client to server: none
Thu Jul 28 21:29:45.038 2011 [5512] client proposal: compression algorithm server to client: none
Thu Jul 28 21:29:45.038 2011 [5512] SSH2_MSG_KEXINIT was sent at SSH2_send_kexinit().
Thu Jul 28 21:29:45.038 2011 [5512] SSH2_MSG_KEXINIT was received.

■パケット

http://twitpic.com/5x4suv/full

2011-07-28 23:32 Updated by: sunnyone
Comment

発生時刻周辺(ログの行間)のProcess Monitor ( http://technet.microsoft.com/ja-jp/sysinternals/bb896645 )の出力も採取してみました。 (時刻はProcess Monitorが観測した時刻だと思いますので、ログの時刻より若干遅いと思います) 参考になれば...

■TTSSH.LOG

Thu Jul 28 23:10:25.444 2011 [5276] ---------------------------------------------------------------------
Thu Jul 28 23:10:25.538 2011 [5276] Initiating SSH session
Thu Jul 28 23:10:26.099 2011 [5276] Received server identification string: SSH-2.0-OpenSSH_5.1p1 Debian-5
Thu Jul 28 23:10:26.177 2011 [5276] Sent client identification string: SSH-2.0-TTSSH/2.57 Win32
Thu Jul 28 23:10:28.689 2011 [5276] client proposal: KEX algorithm: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Thu Jul 28 23:10:28.689 2011 [5276] client proposal: server host key algorithm: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss

■Process Monitorの出力

23:10:26.1821881	ttermpro.exe	5276	WriteFile	C:\temp\snapshot-20110728\TTSSH.LOG	SUCCESS	Offset: 43,119, Length: 2
23:10:26.1822049	ttermpro.exe	5276	CloseFile	C:\temp\snapshot-20110728\TTSSH.LOG	SUCCESS	
23:10:26.1875965	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\NETAPI32.DLL	NAME NOT FOUND	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
23:10:26.1878751	ttermpro.exe	5276	CreateFile	C:\Windows\System32\netapi32.dll	SUCCESS	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:26.1879933	ttermpro.exe	5276	QueryBasicInformationFile	C:\Windows\System32\netapi32.dll	SUCCESS	CreationTime: 2010/11/23 19:17:03, LastAccessTime: 2010/11/23 19:17:03, LastWriteTime: 2009/04/10 23:28:24, ChangeTime: 2010/11/23 19:21:47, FileAttributes: A
23:10:26.1880035	ttermpro.exe	5276	CloseFile	C:\Windows\System32\netapi32.dll	SUCCESS	
23:10:26.1881306	ttermpro.exe	5276	CreateFile	C:\Windows\System32\netapi32.dll	SUCCESS	Desired Access: Read Data/List Directory, Execute/Traverse, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:26.1882583	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\netapi32.dll	FILE LOCKED WITH ONLY READERS	SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE
23:10:26.1882982	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\netapi32.dll	SUCCESS	SyncType: SyncTypeOther
23:10:26.1883156	ttermpro.exe	5276	CloseFile	C:\Windows\System32\netapi32.dll	SUCCESS	
23:10:26.1885668	ttermpro.exe	5276	Load Image	C:\Windows\System32\netapi32.dll	SUCCESS	Image Base: 0x756b0000, Image Size: 0x76000
23:10:26.1889027	ttermpro.exe	5276	Load Image	C:\Windows\System32\psapi.dll	SUCCESS	Image Base: 0x75b70000, Image Size: 0x7000
23:10:26.1889948	ttermpro.exe	5276	RegOpenKey	HKLM\SYSTEM\Setup	SUCCESS	Desired Access: Query Value
23:10:26.1890207	ttermpro.exe	5276	RegQueryValue	HKLM\SYSTEM\Setup\SystemSetupInProgress	SUCCESS	Type: REG_DWORD, Length: 4, Data: 0
23:10:26.1890350	ttermpro.exe	5276	RegCloseKey	HKLM\SYSTEM\Setup	SUCCESS	
23:10:26.1891078	ttermpro.exe	5276	RegOpenKey	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters	REPARSE	Desired Access: Query Value
23:10:26.1891279	ttermpro.exe	5276	RegOpenKey	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters	SUCCESS	Desired Access: Query Value
23:10:26.1891442	ttermpro.exe	5276	RegQueryValue	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters\RpcCacheTimeout	NAME NOT FOUND	Length: 144
23:10:26.1891545	ttermpro.exe	5276	RegCloseKey	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters	SUCCESS	
23:10:26.1902020	ttermpro.exe	5276	RegOpenKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001	SUCCESS	Desired Access: Read
23:10:26.1902539	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:26.1902645	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:26.1902749	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:26.1902835	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:26.1902933	ttermpro.exe	5276	RegCloseKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001	SUCCESS	
23:10:26.1903041	ttermpro.exe	5276	RegOpenKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider	SUCCESS	Desired Access: Read
23:10:26.1903331	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Type	SUCCESS	Type: REG_DWORD, Length: 4, Data: 1
23:10:26.1903435	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:26.1903517	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:26.1903604	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:26.1903686	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:26.1906178	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\rsaenh.dll	NAME NOT FOUND	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
23:10:26.1906675	ttermpro.exe	5276	QueryNameInformationFile	C:\temp\snapshot-20110728	SUCCESS	Name: \temp\snapshot-20110728
23:10:26.1907620	ttermpro.exe	5276	QueryNameInformationFile	C:\temp\snapshot-20110728	SUCCESS	Name: \temp\snapshot-20110728
23:10:26.1907763	ttermpro.exe	5276	QueryNameInformationFile	C:\temp\snapshot-20110728	SUCCESS	Name: \temp\snapshot-20110728
23:10:26.1908597	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\rsaenh.dll	NAME NOT FOUND	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
23:10:26.1910811	ttermpro.exe	5276	CreateFile	C:\Windows\System32\rsaenh.dll	SUCCESS	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:26.1911913	ttermpro.exe	5276	QueryBasicInformationFile	C:\Windows\System32\rsaenh.dll	SUCCESS	CreationTime: 2010/11/23 19:17:12, LastAccessTime: 2010/11/23 19:17:12, LastWriteTime: 2009/04/10 23:27:48, ChangeTime: 2010/11/23 19:21:46, FileAttributes: A
23:10:26.1912010	ttermpro.exe	5276	CloseFile	C:\Windows\System32\rsaenh.dll	SUCCESS	
23:10:26.1913228	ttermpro.exe	5276	CreateFile	C:\Windows\System32\rsaenh.dll	SUCCESS	Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, AllocationSize: n/a, OpenResult: Opened
23:10:26.1914590	ttermpro.exe	5276	QueryStandardInformationFile	C:\Windows\System32\rsaenh.dll	SUCCESS	AllocationSize: 241,664, EndOfFile: 241,128, NumberOfLinks: 2, DeletePending: False, Directory: False
23:10:26.1914707	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\rsaenh.dll	FILE LOCKED WITH ONLY READERS	SyncType: SyncTypeCreateSection, PageProtection: PAGE_READONLY
23:10:26.1914774	ttermpro.exe	5276	QueryStandardInformationFile	C:\Windows\System32\rsaenh.dll	SUCCESS	AllocationSize: 241,664, EndOfFile: 241,128, NumberOfLinks: 2, DeletePending: False, Directory: False
23:10:26.1914928	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\rsaenh.dll	SUCCESS	SyncType: SyncTypeOther
23:10:26.1945309	ttermpro.exe	5276	CloseFile	C:\Windows\System32\rsaenh.dll	SUCCESS	
23:10:26.1947448	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\rsaenh.dll	NAME NOT FOUND	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
23:10:26.1949523	ttermpro.exe	5276	CreateFile	C:\Windows\System32\rsaenh.dll	SUCCESS	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:26.1950554	ttermpro.exe	5276	QueryBasicInformationFile	C:\Windows\System32\rsaenh.dll	SUCCESS	CreationTime: 2010/11/23 19:17:12, LastAccessTime: 2010/11/23 19:17:12, LastWriteTime: 2009/04/10 23:27:48, ChangeTime: 2010/11/23 19:21:46, FileAttributes: A
23:10:26.1950644	ttermpro.exe	5276	CloseFile	C:\Windows\System32\rsaenh.dll	SUCCESS	
23:10:26.1951822	ttermpro.exe	5276	CreateFile	C:\Windows\System32\rsaenh.dll	SUCCESS	Desired Access: Read Data/List Directory, Execute/Traverse, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:26.1952986	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\rsaenh.dll	FILE LOCKED WITH ONLY READERS	SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE
23:10:26.1953318	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\rsaenh.dll	SUCCESS	SyncType: SyncTypeOther
23:10:26.1953472	ttermpro.exe	5276	CloseFile	C:\Windows\System32\rsaenh.dll	SUCCESS	
23:10:26.1955543	ttermpro.exe	5276	Load Image	C:\Windows\System32\rsaenh.dll	SUCCESS	Image Base: 0x74f50000, Image Size: 0x3b000
23:10:26.1958135	ttermpro.exe	5276	CreateFile	C:\Windows\System32\ja-JP\crypt32.dll.mui	SUCCESS	Desired Access: Generic Read, Disposition: Open, Options: , Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:26.1958625	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\ja-JP\crypt32.dll.mui	FILE LOCKED WITH ONLY READERS	SyncType: SyncTypeCreateSection, PageProtection: PAGE_WRITECOPY
23:10:26.1958692	ttermpro.exe	5276	QueryStandardInformationFile	C:\Windows\System32\ja-JP\crypt32.dll.mui	SUCCESS	AllocationSize: 28,672, EndOfFile: 26,112, NumberOfLinks: 2, DeletePending: False, Directory: False
23:10:26.1958866	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\ja-JP\crypt32.dll.mui	SUCCESS	SyncType: SyncTypeOther
23:10:26.2007921	ttermpro.exe	5276	RegOpenKey	HKLM\Software\Policies\Microsoft\Cryptography	SUCCESS	Desired Access: Read
23:10:26.2008148	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Policies\Microsoft\Cryptography\PrivKeyCacheMaxItems	NAME NOT FOUND	Length: 144
23:10:26.2008250	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Policies\Microsoft\Cryptography\PrivKeyCachePurgeIntervalSeconds	NAME NOT FOUND	Length: 144
23:10:26.2008333	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Policies\Microsoft\Cryptography\PrivateKeyLifetimeSeconds	NAME NOT FOUND	Length: 144
23:10:26.2008417	ttermpro.exe	5276	RegCloseKey	HKLM\SOFTWARE\Policies\Microsoft\Cryptography	SUCCESS	
23:10:26.2008515	ttermpro.exe	5276	RegOpenKey	HKLM\Software\Microsoft\Cryptography	SUCCESS	Desired Access: Read
23:10:26.2008809	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:26.2008915	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:26.2009007	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:26.2009088	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:26.2009221	ttermpro.exe	5276	RegCloseKey	HKLM\SOFTWARE\Microsoft\Cryptography	SUCCESS	
23:10:26.2009331	ttermpro.exe	5276	RegOpenKey	HKLM\Software\Microsoft\Cryptography\Offload	NAME NOT FOUND	Desired Access: Read
23:10:26.2045311	ttermpro.exe	5276	RegCloseKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider	SUCCESS	
23:10:26.2045798	ttermpro.exe	5276	RegOpenKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Intel Hardware Cryptographic Service Provider	NAME NOT FOUND	Desired Access: Read
23:10:27.9048851	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\ssh_known_hosts	SUCCESS	Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened
23:10:27.9049529	ttermpro.exe	5276	QueryStandardInformationFile	C:\temp\snapshot-20110728\ssh_known_hosts	SUCCESS	AllocationSize: 464, EndOfFile: 460, NumberOfLinks: 1, DeletePending: False, Directory: False
23:10:27.9049660	ttermpro.exe	5276	ReadFile	C:\temp\snapshot-20110728\ssh_known_hosts	SUCCESS	Offset: 0, Length: 460, Priority: Normal
23:10:27.9049941	ttermpro.exe	5276	CloseFile	C:\temp\snapshot-20110728\ssh_known_hosts	SUCCESS	
23:10:27.9053313	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\NETAPI32.DLL	NAME NOT FOUND	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
23:10:27.9055580	ttermpro.exe	5276	CreateFile	C:\Windows\System32\netapi32.dll	SUCCESS	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:27.9056676	ttermpro.exe	5276	QueryBasicInformationFile	C:\Windows\System32\netapi32.dll	SUCCESS	CreationTime: 2010/11/23 19:17:03, LastAccessTime: 2010/11/23 19:17:03, LastWriteTime: 2009/04/10 23:28:24, ChangeTime: 2010/11/23 19:21:47, FileAttributes: A
23:10:27.9056769	ttermpro.exe	5276	CloseFile	C:\Windows\System32\netapi32.dll	SUCCESS	
23:10:27.9057976	ttermpro.exe	5276	CreateFile	C:\Windows\System32\netapi32.dll	SUCCESS	Desired Access: Read Data/List Directory, Execute/Traverse, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened
23:10:27.9059158	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\netapi32.dll	FILE LOCKED WITH ONLY READERS	SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE
23:10:27.9059533	ttermpro.exe	5276	CreateFileMapping	C:\Windows\System32\netapi32.dll	SUCCESS	SyncType: SyncTypeOther
23:10:27.9059686	ttermpro.exe	5276	CloseFile	C:\Windows\System32\netapi32.dll	SUCCESS	
23:10:27.9061886	ttermpro.exe	5276	Load Image	C:\Windows\System32\netapi32.dll	SUCCESS	Image Base: 0x756b0000, Image Size: 0x76000
23:10:27.9064886	ttermpro.exe	5276	Load Image	C:\Windows\System32\psapi.dll	SUCCESS	Image Base: 0x75b70000, Image Size: 0x7000
23:10:27.9065768	ttermpro.exe	5276	RegOpenKey	HKLM\SYSTEM\Setup	SUCCESS	Desired Access: Query Value
23:10:27.9066015	ttermpro.exe	5276	RegQueryValue	HKLM\SYSTEM\Setup\SystemSetupInProgress	SUCCESS	Type: REG_DWORD, Length: 4, Data: 0
23:10:27.9066149	ttermpro.exe	5276	RegCloseKey	HKLM\SYSTEM\Setup	SUCCESS	
23:10:27.9066853	ttermpro.exe	5276	RegOpenKey	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters	REPARSE	Desired Access: Query Value
23:10:27.9067043	ttermpro.exe	5276	RegOpenKey	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters	SUCCESS	Desired Access: Query Value
23:10:27.9067203	ttermpro.exe	5276	RegQueryValue	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters\RpcCacheTimeout	NAME NOT FOUND	Length: 144
23:10:27.9067305	ttermpro.exe	5276	RegCloseKey	HKLM\System\CurrentControlSet\Services\LanmanWorkstation\Parameters	SUCCESS	
23:10:27.9076524	ttermpro.exe	5276	RegOpenKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001	SUCCESS	Desired Access: Read
23:10:27.9077004	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:27.9077108	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:27.9077209	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:27.9077293	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001\Name	SUCCESS	Type: REG_SZ, Length: 80, Data: Microsoft Strong Cryptographic Provider
23:10:27.9077388	ttermpro.exe	5276	RegCloseKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider Types\Type 001	SUCCESS	
23:10:27.9077497	ttermpro.exe	5276	RegOpenKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider	SUCCESS	Desired Access: Read
23:10:27.9077789	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Type	SUCCESS	Type: REG_DWORD, Length: 4, Data: 1
23:10:27.9077886	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:27.9077969	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:27.9078057	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:27.9078139	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider\Image Path	SUCCESS	Type: REG_SZ, Length: 22, Data: rsaenh.dll
23:10:27.9078438	ttermpro.exe	5276	RegOpenKey	HKLM\Software\Microsoft\Cryptography	SUCCESS	Desired Access: Read
23:10:27.9078700	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:27.9078794	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:27.9078887	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:27.9078969	ttermpro.exe	5276	RegQueryValue	HKLM\SOFTWARE\Microsoft\Cryptography\MachineGuid	SUCCESS	Type: REG_SZ, Length: 74, Data: c35d99da-2417-4670-b4bd-d89efa82e83f
23:10:27.9079104	ttermpro.exe	5276	RegCloseKey	HKLM\SOFTWARE\Microsoft\Cryptography	SUCCESS	
23:10:27.9079211	ttermpro.exe	5276	RegOpenKey	HKLM\Software\Microsoft\Cryptography\Offload	NAME NOT FOUND	Desired Access: Read
23:10:27.9079622	ttermpro.exe	5276	RegCloseKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Microsoft Strong Cryptographic Provider	SUCCESS	
23:10:27.9079876	ttermpro.exe	5276	RegOpenKey	HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Intel Hardware Cryptographic Service Provider	NAME NOT FOUND	Desired Access: Read
23:10:28.6836332	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\TTSSH.LOG	SUCCESS	Desired Access: Generic Read/Write, Disposition: OpenIf, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Opened
23:10:28.6837074	ttermpro.exe	5276	QueryStandardInformationFile	C:\temp\snapshot-20110728\TTSSH.LOG	SUCCESS	AllocationSize: 45,056, EndOfFile: 43,121, NumberOfLinks: 1, DeletePending: False, Directory: False
23:10:28.6837194	ttermpro.exe	5276	ReadFile	C:\temp\snapshot-20110728\TTSSH.LOG	SUCCESS	Offset: 43,120, Length: 1, Priority: Normal
23:10:28.6837525	ttermpro.exe	5276	QueryStandardInformationFile	C:\temp\snapshot-20110728\TTSSH.LOG	SUCCESS	AllocationSize: 45,056, EndOfFile: 43,121, NumberOfLinks: 1, DeletePending: False, Directory: False
23:10:28.6837828	ttermpro.exe	5276	WriteFile	C:\temp\snapshot-20110728\TTSSH.LOG	SUCCESS	Offset: 43,121, Length: 28, Priority: Normal

2011-07-29 00:34 Updated by: (del#1144)
Comment

OpenSSL の RAND_screen() を呼んでから返ってくるのに時間がかかっているようです。

"HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Intel Hardware Cryptographic Service Provider" を開こうとして失敗しているのと一致しているように思います。

とりあえず現状解っているところまで。

2011-07-29 00:51 Updated by: sunnyone
Comment

解析ありがとうございます。こちらでももう少し調査してみましたが、同じ結果になりました。 RAND_screen()が遅い事例はWebを検索するといくつかあるようなので、珍しいことではないようです。

当該処理では、opensslの擬似乱数シードを初期化できればいいと思いますので、他の 似たような動作をする関数(RAND_event()?)を使用するですとかか、恐らく存在するで あろうWin32 APIから乱数を得てRAND_add()するといった実装に変えて頂ければ速くなる のではないかと思います。

待てば良い話なので、致命的な問題では全然ありませんが、接続時に待ちがあるのとないのとでは 使っている快適度が違いますので、検討いただければと思います。

参考:

http://stackoverflow.com/questions/1940168/openssl-random-pseudo-bytes-is-slow-php

http://answerpot.com/showthread.php?1974575-2dded8%3A+ossl_seed%3A+no+more+RAND_screen

The RAND_screen() function is available for the convenience of Windows programmers. It adds the current contents of the screen to the PRNG .
For applications that can catch Windows events, seeding the PRNG by calling RAND_event() is a significantly better source of randomness.
It should be noted that both methods cannot be used on servers that run without user interaction. 

http://linux.die.net/man/3/rand_screen

~~以下、調査の経過です~~

Process Monitorの時刻を読むと、ssh_known_hostsの読み込みは、かなり待った後のように見えます。

23:10:27.9048851	ttermpro.exe	5276	CreateFile	C:\temp\snapshot-20110728\ssh_known_hosts	SUCCESS	Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened

ssh_known_hostsの読み込みは、ssh.cのinit_protocol()の中のHOSTS_prefetch_host_key()のようですが、 init_protocol()の呼び出し元とあわせて見ると、CRYPT_initialize_random_numbers()というのが怪しいことが わかりました。

BOOL SSH_handle_server_ID(PTInstVar pvar, char FAR * ID, int ID_len)
{
(略)
	notify_verbose_message(pvar, buf, LOG_LEVEL_VERBOSE); ⇒待つ前のTTSSH.LOGへの最後の出力
	free(buf);

	push_memdump("server ID", NULL, pvar->server_version_string, strlen(pvar->server_version_string));
	push_memdump("client ID", NULL, pvar->client_version_string, strlen(pvar->client_version_string));

	// SSHハンドラの登録を行う
	init_protocol(pvar);
(略)
static void init_protocol(PTInstVar pvar)
{
	CRYPT_initialize_random_numbers(pvar); ⇒ ????

	// known_hostsファイルからホスト公開鍵を先読みしておく
	HOSTS_prefetch_host_key(pvar, pvar->ssh_state.hostname, pvar->ssh_state.tcpport); ⇒ssh_known_hostsの読み込み
(略)

CRYPT_initialize_random_numbers()は、RAND_screen()を呼ぶ関数のようです。

ttxssh/crypt.h
/* this function is called during 'slack time' while we wait for a response
   from the server. Therefore we have some time available to do some
   moderately expensive computations. */
void CRYPT_initialize_random_numbers(PTInstVar pvar);

ttxssh/crypt.c
void CRYPT_initialize_random_numbers(PTInstVar pvar)
{
	RAND_screen();
}

2011-07-29 01:21 Updated by: (del#1144)
Comment

RAND_screen() を呼ばないようにしてみました。これだとどうなりますか?

http://ttssh2.sourceforge.jp/snapshot/snapshot-20110729.zip

2011-07-31 01:39 Updated by: sunnyone
Comment

かなり速くなりました。ありがとうございます。 (体感としては、3秒→1秒程度になりました。)

■TTSSH.LOG

Sun Jul 31 01:37:17.966 2011 [940] ---------------------------------------------------------------------
Sun Jul 31 01:37:17.966 2011 [940] Initiating SSH session
Sun Jul 31 01:37:18.013 2011 [940] Received server identification string: SSH-2.0-OpenSSH_5.1p1 Debian-5
Sun Jul 31 01:37:18.029 2011 [940] Sent client identification string: SSH-2.0-TTSSH/2.57 Win32
Sun Jul 31 01:37:18.777 2011 [940] client proposal: KEX algorithm: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Sun Jul 31 01:37:18.777 2011 [940] client proposal: server host key algorithm: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss
Sun Jul 31 01:37:18.777 2011 [940] client proposal: encryption algorithm client to server: aes256-ctr,aes256-cbc,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128,arcfour,cast128-ctr,cast128-cbc
Sun Jul 31 01:37:18.777 2011 [940] client proposal: encryption algorithm server to client: aes256-ctr,aes256-cbc,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128,arcfour,cast128-ctr,cast128-cbc

2011-08-16 21:37 Updated by: (del#1144)
  • Resolution Update from None to Fixed
  • Status Update from Open to Closed
  • Ticket Close date is changed to 2011-08-16 21:37

Attachment File List

No attachments

Edit

You are not logged in. I you are not logged in, your comment will be treated as an anonymous post. » Login