Re: isakmp debugging - what to watch out for?

[Andreas Schuldei <andreas@schuldei.org>]

* Angelos D. Keromytis (angelos@dsl.cis.upenn.edu) [001209 09:16]:
> 
> The logs are insufficient to diagnose that problem.

I observ strange interactions: both hosts seem to finalize phase 1 and start
sending encrypted messages. then suddenly they are unable to send or receive
packages to/from the other host. I had a tcpdump running and I could see that
eventhough they started phase1 again, no package was send/received on either
host. On top of that, direkt ssh connections from one to the other host do not
get anywhere. This could very well be a kernel problem, because the packages
on port 22 are received (visible on tcpdump) but are not received by the sshd.

theses are the sections from the isakmpd outputs where the problem just
happens.

Host A

170339.999955 Exch 10 exchange_finalize: msgid 2d5695b9 sa_list 0x123800 
170340.000161 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.105.112 SPI 0x85ec05f6
170340.000267 Timr 10 timer_add_event: event sa_soft_expire(0x123800) added before sa_soft_expire(0x105f00), expiration in 1070s
170340.000893 Timr 10 timer_add_event: event sa_hard_expire(0x123800) added before sa_soft_expire(0x105f00), expiration in 1200s
170340.001811 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.181.91 SPI 0x90003b2e
170340.003300 Timr 10 timer_remove_event: removing event exchange_free_aux(0x123700)
170340.170045 Timr 10 timer_handle_expirations: event message_send_expire(0x123500)
170340.170790 Timr 10 timer_add_event: event message_send_expire(0x123500) added before connection_checker(0x132070), expiration in 9s
170340.654005 Timr 10 timer_remove_event: removing event message_send_expire(0x123500)
170340.654304 Cryp 10 crypto_decrypt: before decryption:
170340.654407 Cryp 10 a9ab34c4 6850094a a929b6df 5a091f7f a8406aea 0ffbe621 91fb6352 d688e305
170340.654484 Cryp 10 838d307f 201d4d02 5dade234 f348b1a2 94c8763b 2db8b38e 9beed2d0 3a11593d
170340.655229 Cryp 10 8f5047bd ffc590fc 85a3d46c 32e7a0dd b2e9482f 1be1762c 3410cf27 1bc896d3
170340.655346 Cryp 10 502f9bdb ff54a1de 647b5ec6 33955e95 52aa9bcb 1af8add2 3c0e83a5 b901376e
170340.655420 Cryp 10 e0cef1bf c3268079 74a96500 17065633 f3383d98 c6a2ed8a b0eabcf2 241523c7
170340.655960 Cryp 10 3c982552 f95f29d3 1e1fdd1c 9b54e1c1 f8891677 4cbcecd5 134c5504 34193449
170340.656073 Cryp 10 4522cf65 b081cbc1 e0197f37 c2ed88fe cb1fafbc 941069d3 e9f0ae6e a0bd16be
170340.656148 Cryp 10 7cc5bc57 bb2e4924 1309d834 40d7c0f6 66f75577 77706e6e 2a0c3ab6 ffd9924f
170340.656627 Cryp 10 52fbe3e7 cbb98415 
170340.657001 Mesg 00 ipsec_validate_id_information: proto 0 port 0 type 4
170340.657106 Mesg 00 ipsec_validate_id_information: proto 0 port 0 type 4
170340.657990 Cryp 10 crypto_encrypt: before encryption:
170340.658203 Cryp 10 00000018 860ec748 de0aecd9 df5e4381 92d2d687 46f9c336 
170340.729696 Exch 10 exchange_finalize: 0x123000 incoming-from-schuldei Default-quick-mode policy initiator phase 2 doi 1 exchange 32 step 3
170340.729969 Exch 10 exchange_finalize: icookie 1b0ff7fcd16d73e9 rcookie fa41d57f2dbdda3d
170340.730043 Exch 10 exchange_finalize: msgid 8556f5bc sa_list 0x123300 
170340.730847 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.105.112 SPI 0x7f96af49
170340.730998 Timr 10 timer_add_event: event sa_soft_expire(0x123300) added before sa_hard_expire(0x123800), expiration in 1089s
170340.731095 Timr 10 timer_add_event: event sa_hard_expire(0x123300) added before sa_soft_expire(0x105f00), expiration in 1200s
170340.732576 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.181.91 SPI 0x59e689
170348.210096 Timr 10 timer_handle_expirations: event message_send_expire(0x105b00)
170348.210915 Timr 10 timer_add_event: event message_send_expire(0x105b00) added before connection_checker(0x132070), expiration in 11s
170359.220083 Timr 10 timer_handle_expirations: event message_send_expire(0x105b00)
170359.221451 Timr 10 timer_add_event: event message_send_expire(0x105b00) added before connection_checker(0x132070), expiration in 13s
170412.230069 Timr 10 timer_handle_expirations: event message_send_expire(0x105b00)


Host B, same time

231929.851138 Exch 10 exchange_finalize: icookie ea3ee4d32d9fd83d rcookie ddf77c82e48f6878
231929.851447 Exch 10 exchange_finalize: msgid 2d5695b9 sa_list 0x123a00 
231929.853691 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.181.91 SPI 0x90003b2e
231929.854044 Timr 10 timer_add_event: event sa_soft_expire(0x123a00) added before sa_soft_expire(0x105f00), expiration in 1117s
231929.854391 Timr 10 timer_add_event: event sa_hard_expire(0x123a00) added before sa_soft_expire(0x105f00), expiration in 1200s
231929.857735 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.105.112 SPI 0x85ec05f6
231929.862830 Cryp 10 crypto_decrypt: before decryption:
231929.863315 Cryp 10 b2453013 d018f6f2 e04c1180 82992a97 fa5cd637 41e53809 f452c67c 3d8dcf15
231929.863765 Cryp 10 f4fb5a26 e155f3bf d3a69358 6bcd0471 aa09a136 90392b4a 554cc466 f3caaee5
231929.865907 Cryp 10 09c203fb 88080a51 27af9e35 4fafcd34 b75c22eb b6b2d235 0a26e7e9 e5dd4bab
231929.866361 Cryp 10 1a917e40 15d727ac 2eb48d92 d194bbb4 16c7e536 6421360e 90da706d ad54b317
231929.866810 Cryp 10 a3cf7566 5b935964 0a6a9c39 53ca7147 fd878de8 6fc79d49 de4ab0a9 f18f1929
231929.868741 Cryp 10 fd7f0c66 543c704b f4cec659 f6fb93d3 7d33b440 ea77734a c2230a62 0b0a64e4
231929.869197 Cryp 10 b0ccd81e 8c997f5b 574acd79 7234efda 2316725b cffbcf42 0a15d801 335c6fad
231929.869647 Cryp 10 72cd4bfc 3af1f328 d70dce36 fac6f6c3 e87777ec 8d6d09f6 99701cd0 b19c52ee
231929.871438 Cryp 10 14334a18 89bf286c 
231929.872300 Timr 10 timer_add_event: event exchange_free_aux(0x123c00) added before cookie_reset_event(0x0), expiration in 120s
231929.872653 Exch 10 exchange_setup_p2: 0x123c00 <unnamed> <no policy> policy responder phase 2 doi 1 exchange 32 step 0
231929.874670 Exch 10 exchange_setup_p2: icookie 1b0ff7fcd16d73e9 rcookie fa41d57f2dbdda3d
231929.875001 Exch 10 exchange_setup_p2: msgid 8556f5bc sa_list 
231929.875523 Mesg 00 ipsec_validate_id_information: proto 0 port 0 type 4
231929.875886 Mesg 00 ipsec_validate_id_information: proto 0 port 0 type 4
231930.195698 Cryp 10 crypto_encrypt: before encryption:
231930.196204 Cryp 10 01000018 92f40b5d dbc0f991 7479e198 b1fb2e31 a68256f1 0a000034 00000001
231930.196666 Cryp 10 00000001 00000028 01030401 7f96af49 0000001c 010c0000 80010001 800204b0
231930.197120 Cryp 10 80040001 80050002 80030002 04000014 10afd5cf 42c8bb39 1a4b5b06 a98263c6
231930.199350 Cryp 10 05000084 28fa4b68 b954c2aa f7cdb872 abe6c624 fed3d282 169d4ab4 d513271d
231930.199804 Cryp 10 6aed012c 76c85292 19d9be2d 191acf16 18189a9b 377e2ce5 caa11c40 d8290dc8
231930.200272 Cryp 10 59af80e7 409f1abb bcda37d6 c2cd85a8 229e44dd c7e1e691 c17dfc6e 8f82027b
231930.202187 Cryp 10 17c77bb1 e031d393 f544691a 917db59c e2aa3624 e9b5aedb 4b1ac06d 4ac8ac1b
231930.202654 Cryp 10 2736dce0 05000010 04000000 0a000100 ffffff00 00000010 04000000 c0a86400
231930.202982 Cryp 10 ffffff00 00000000 
231930.205504 Timr 10 timer_add_event: event message_send_expire(0x12a100) added before connection_checker(0x132070), expiration in 7s
231930.525049 Timr 10 timer_remove_event: removing event message_send_expire(0x12a100)
231930.525786 Cryp 10 crypto_decrypt: before decryption:
231930.526204 Cryp 10 f1d33d05 7ed5c117 6d1783b4 f908c0d5 3473b0dc 529fce6f 
231930.527488 Exch 10 exchange_finalize: 0x123c00 incoming-from-utilator <no policy> policy responder phase 2 doi 1 exchange 32 step 2
231930.529645 Exch 10 exchange_finalize: icookie 1b0ff7fcd16d73e9 rcookie fa41d57f2dbdda3d
231930.529967 Exch 10 exchange_finalize: msgid 8556f5bc sa_list 0x123e00 
231930.530410 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.181.91 SPI 0x59e689
231930.530758 Timr 10 timer_add_event: event sa_soft_expire(0x123e00) added before sa_soft_expire(0x123a00), expiration in 1111s
231930.532975 Timr 10 timer_add_event: event sa_hard_expire(0x123e00) added before sa_soft_expire(0x105f00), expiration in 1200s
231930.534594 Sdep 10 pf_key_v2_set_spi: satype 2 dst 195.84.105.112 SPI 0x7f96af49
231930.537615 Timr 10 timer_remove_event: removing event exchange_free_aux(0x123c00)
231936.970082 Timr 10 timer_handle_expirations: event message_send_expire(0x105b00)
231936.971464 Timr 10 timer_add_event: event message_send_expire(0x105b00) added before connection_checker(0x132070), expiration in 11s
231947.980095 Timr 10 timer_handle_expirations: event message_send_expire(0x105b00)
231947.981499 Timr 10 timer_add_event: event message_send_expire(0x105b00) added before connection_checker(0x132070), expiration in 13s
232000.990661 Timr 10 timer_handle_expirations: event message_send_expire(0x105b00)
232000.992267 Timr 10 timer_add_event: event message_send_expire(0x105b00) added before connection_checker(0x132070), expiration in 15s
232016.000166 Timr 10 timer_handle_expirations: event message_send_expire(0x105b00)
232016.001614 Default transport_send_messages: giving up on message 0x105b00


Do you need a more verbose loglevel? or a tcpdump? is it a known problem?