ソースを見ると「00:07:02」(待ち発生後)の「SSH2_MSG_KEXINIT was sent at SSH2_send_kexinit().」 のメッセージを出しているのはttxssh/ssh.cの中の以下の部分のようです。
Tera Termstatic 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する処理を入れる必要があると思います。)
ログの出力箇所を増やしてみましたが、これでどうなりますか？
以下の通りとなります。何かわかりますでしょうか。
■時系列
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.
■パケット
発生時刻周辺(ログの行間)の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
OpenSSL の RAND_screen() を呼んでから返ってくるのに時間がかかっているようです。
"HKLM\SOFTWARE\Microsoft\Cryptography\Defaults\Provider\Intel Hardware Cryptographic Service Provider" を開こうとして失敗しているのと一致しているように思います。
とりあえず現状解っているところまで。
解析ありがとうございます。こちらでももう少し調査してみましたが、同じ結果になりました。 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();
}
RAND_screen() を呼ばないようにしてみました。これだとどうなりますか？
かなり速くなりました。ありがとうございます。 （体感としては、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
「新しい接続」ダイアログよりIPアドレスを入力し「OK」をクリックすると、「SSH認証」ダイアログが表示されますが、 数秒間の間マウスカーソル＋砂時計の状態となり、ユーザ名/パスフレーズの入力ができません。
（数秒待つと（この環境では）rhosts(SSH1)を使うがグレーアウトされ、砂時計が消え、ユーザ名/パスフレーズが入力できるようになります。）
この待ちをなくすことは可能でしょうか。
パケットキャプチャを見ると、サーバから「Server: Key Exchange Init」のパケットが 来てACKを返した後、待ち状態となり、クライアントが3秒後に「Client: Key Exchange Init」の パケットを送信しています。ですので、クライアント側の問題なのですが、この間に時間の かかる処理があるのでしょうか。
時系列にすると、以下の通りとなります(ログは秒の精度なので、多少前後するとは思います)。
■環境 ・Windows Vista ・TeraTerm 4.70
■ログ
■パケット
http://twitpic.com/5wpkrq/full