

WORK in progress, needs reviewing

Starting UML /btmp/antony/ikev2/2008_01_14/UMLPOOL/west/start-netkey.sh
spawn /btmp/antony/ikev2/2008_01_14/UMLPOOL/west/start-netkey.sh single
Checking that ptrace can change system call numbers...OK
Checking syscall emulation patch for ptrace...OK
Checking advanced syscall emulation patch for ptrace...OK
Checking for tmpfs mount on /dev/shm...OK
Checking PROT_EXEC mmap in /dev/shm/...OK
Checking for the skas3 patch in the host:
  - /proc/mm...not found
  - PTRACE_FAULTINFO...not found
  - PTRACE_LDT...not found
UML running in SKAS0 mode
Checking that ptrace can change system call numbers...OK
Checking syscall emulation patch for ptrace...OK
Checking advanced syscall emulation patch for ptrace...OK
Linux version 2.6.18.6 (antony@sal) (gcc version 4.2.3 20080114 (prerelease) (Debian 4.2.2-7)) #6 Wed Feb 13 11:18:26 EST 2008
Built 1 zonelists.  Total pages: 8192
Kernel command line: initrd=/btmp/antony/ikev2/2008_01_14/UMLPOOL/initrd.uml umlroot=/btmp/antony/ikev2/2008_01_14/UMLPOOL/west/root root=/dev/ram0 rw ssl=pty eth0=daemon,10:00:00:ab:cd:ff,unix,/tmp/umljZyuOz.d/west/ctl,/tmp/umljZyuOz.d/west/data eth1=daemon,10:00:00:64:64:45,unix,/tmp/umljZyuOz.d/public/ctl,/tmp/umljZyuOz.d/public/data eth2=daemon,10:00:00:32:64:45,unix,/tmp/umljZyuOz.d/admin/ctl,/tmp/umljZyuOz.d/admin/data init=/linuxrc single
PID hash table entries: 256 (order: 8, 1024 bytes)
Dentry cache hash table entries: 4096 (order: 2, 16384 bytes)
Inode-cache hash table entries: 2048 (order: 1, 8192 bytes)
Memory: 27028k available
Mount-cache hash table entries: 512
Checking for host processor cmov support...Yes
Checking for host processor xmm support...No
Checking that host ptys support output SIGIO...Yes
Checking that host ptys support SIGIO on close...No, enabling workaround
checking if image is initramfs...it isn't (bad gzip magic numbers); looks like an initrd
Freeing initrd memory: 1212k freed
Using 2.6 host AIO
NET: Registered protocol family 16
NET: Registered protocol family 2
IP route cache hash table entries: 256 (order: -2, 1024 bytes)
TCP established hash table entries: 1024 (order: 0, 4096 bytes)
TCP bind hash table entries: 512 (order: -1, 2048 bytes)
TCP: Hash tables configured (established 1024 bind 512)
TCP reno registered
daemon_setup : Ignoring data socket specification
Netdevice 0 (10:00:00:ab:cd:ff) : daemon backend (uml_switch version 3) - unix:/tmp/umljZyuOz.d/west/ctl
daemon_setup : Ignoring data socket specification
Netdevice 1 (10:00:00:64:64:45) : daemon backend (uml_switch version 3) - unix:/tmp/umljZyuOz.d/public/ctl
daemon_setup : Ignoring data socket specification
Netdevice 2 (10:00:00:32:64:45) : daemon backend (uml_switch version 3) - unix:/tmp/umljZyuOz.d/admin/ctl
Checking host MADV_REMOVE support...OK
mconsole (version 2) initialized on /home/antony/.uml/west/mconsole
Host TLS support detected
Detected host type: i386
VFS: Disk quotas dquot_6.5.1
Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Initializing Cryptographic API
io scheduler noop registered
io scheduler anticipatory registered (default)
io scheduler deadline registered
io scheduler cfq registered
RAMDISK driver initialized: 16 RAM disks of 4096K size 1024 blocksize
loop: loaded (max 8 devices)
nbd: registered device at major 43
PPP generic driver version 2.4.2
SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256).
tun: Universal TUN/TAP device driver, 1.6
tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
Netfilter messages via NETLINK v0.30.
IPv4 over IPv4 tunneling driver
GRE over IPv4 tunneling driver
ip_conntrack version 2.4 (211 buckets, 1688 max) - 224 bytes per conntrack
ctnetlink v0.90: registering with nfnetlink.
ip_conntrack_pptp version 3.1 loaded
ip_nat_pptp version 3.0 loaded
ip_tables: (C) 2000-2006 Netfilter Core Team
ClusterIP Version 0.8 loaded successfully
arp_tables: (C) 2002 David S. Miller
TCP bic registered
TCP westwood registered
TCP highspeed registered
TCP hybla registered
TCP htcp registered
TCP vegas registered
TCP scalable registered
Initializing IPsec netlink socket
NET: Registered protocol family 1
NET: Registered protocol family 17
NET: Registered protocol family 15
Initialized stdio console driver
Console initialized on /dev/tty0
Initializing software serial port version 1
Failed to open 'root_fs', errno = 2
RAMDISK: cramfs filesystem found at block 0
RAMDISK: Loading 1212KiB [1 disk] into ram disk... |/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\done.
VFS: Mounted root (cramfs filesystem) readonly.
MOUNTING /btmp/antony/ikev2/2008_01_14/UMLPOOL/west/root for UML testing root.
Mounting a tmpfs over /dev...done.
Creating initial device nodes...done.
Invoked with Arguments: single
Creating initial device nodes...done.
crw-r--r--    1 root     root       5,   1 Feb 14 00:12 /dev/console
line_ioctl: tty0: ioctl KDSIGACCEPT called

INIT: version 2.78 booting

/dev/root on / type hostfs (rw)
proc on /proc type proc (rw)
devpts on /dev/pts type devpts (rw,gid=5,mode=620)
/dev/shm on /tmp type tmpfs (rw)
/dev/shm on /var/run type tmpfs (rw)
none on /usr/share type hostfs (ro)
none on /testing type hostfs (ro,/home/antony/ikev2/testing)
none on /usr/src type hostfs (ro,/home/antony/ikev2)
none on /usr/obj type hostfs (ro,/home/antony/ikev2/OBJ.linux.i386)
none on /usr/local type hostfs (rw,/btmp/antony/ikev2/2008_01_14/UMLPOOL/west/root/usr/local)
none on /var/tmp type hostfs (rw,/btmp/antony/ikev2/2008_01_14/UMLPOOL/west/root/var/tmp)
none on /proc type proc (rw)
crw-r--r--    1 root     root       5,   1 Feb 14 00:12 /dev/console
mount: proc already mounted
Activating swap...
Checking all file systems...
Parallelizing fsck version 1.18 (11-Nov-1999)
Setting kernel variables.
Mounting local filesystems...
mount: devpts already mounted on /dev/pts
/dev/shm on /tmp type tmpfs (rw)
/dev/shm on /var/run type tmpfs (rw)
none on /usr/share type hostfs (ro)
none on /testing type hostfs (ro,/home/antony/ikev2/testing)
none on /usr/src type hostfs (ro,/home/antony/ikev2)
none on /usr/obj type hostfs (ro,/home/antony/ikev2/OBJ.linux.i386)
none on /usr/local type hostfs (rw,/btmp/antony/ikev2/2008_01_14/UMLPOOL/west/root/usr/local)
none on /var/tmp type hostfs (rw,/btmp/antony/ikev2/2008_01_14/UMLPOOL/west/root/var/tmp)
Enabling packet forwarding: done.
Configuring network interfaces: done.
Cleaning: /tmp /var/lock /var/run.
Initializing random number generator... done.
Recovering nvi editor sessions... done.
Give root password for maintenance
(or type Control-D for normal startup): 
west:~# echo Starting loading module
Starting loading module
west:~# exec bash --noediting
west:~# ulimit -c unlimited
west:~# echo Finished loading module
Finished loading module
west:~# klogd -c 4 -x -f /tmp/klog.log
west:~# : ==== start ====
west:~# TESTNAME=netkey-pluto-02
west:~# source /testing/pluto/bin/westlocal.sh
west:~# ping -n -c 4 192.0.2.254
PING 192.0.2.254 (192.0.2.254): 56 data bytes
64 bytes from 192.0.2.254: icmp_seq=0 ttl=64 time=28.7 ms
64 bytes from 192.0.2.254: icmp_seq=1 ttl=64 time=0.4 ms
64 bytes from 192.0.2.254: icmp_seq=2 ttl=64 time=0.4 ms
64 bytes from 192.0.2.254: icmp_seq=3 ttl=64 time=0.4 ms

--- 192.0.2.254 ping statistics ---
4 packets transmitted, 4 packets received, 0% packet loss
round-trip min/avg/max = 0.4/7.4/28.7 ms
west:~# iptables -A INPUT -i eth1 -s 192.0.2.0/24 -j DROP
west:~# ping -n -c 4 192.0.2.254
PING 192.0.2.254 (192.0.2.254): 56 data bytes

--- 192.0.2.254 ping statistics ---
4 packets transmitted, 0 packets received, 100% packet loss
west:~# ipsec setup start
ipsec_setup: Starting Libreswan IPsec U2.5.testing-g21680e0d-dirty/K2.6.18.6...
ipsec_setup: Trying hardware random, this may fail, which is okay.
ipsec_setup: Trying to load all NETKEY modules:xfrm6_tunnel xfrm6_mode_tunnel xfrm6_mode_beet xfrm6_mode_ro xfrm6_mode_transport xfrm4_mode_transport xfrm4_mode_tunnel xfrm4_tunnel xfrm4_mode_beet esp4 esp6 ah4 ah6 ipcomp ipcomp6 af_key 
ipsec_setup: Trying VIA padlock driver, this may fail, which is okay.
ipsec_setup: Trying to load Crypto API modules, some may fail, which is okay.
ipsec_setup: aes-x86_64 aes des sha512 sha256 md5 cbc xcbc ecb twofish blowfish serpent 
west:~# ipsec auto --add westnet-eastnet
west:~# ipsec whack --debug-control --debug-controlmore --debug-parsing --debug-crypt
west:~# /testing/pluto/bin/wait-until-pluto-started
west:~# echo done
done
west:~# : === NETJIG start of WEST westrun.sh 
west:~# ipsec auto --up  westnet-eastnet
104 "westnet-eastnet" #1: STATE_MAIN_I1: initiate
003 "westnet-eastnet" #1: received Vendor ID payload [Libreswan (this version) 2.5.testing-g21680e0d-dirty ]
003 "westnet-eastnet" #1: received Vendor ID payload [Dead Peer Detection]
106 "westnet-eastnet" #1: STATE_MAIN_I2: sent MI2, expecting MR2
108 "westnet-eastnet" #1: STATE_MAIN_I3: sent MI3, expecting MR3
004 "westnet-eastnet" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=aes_128 prf=oakley_sha group=modp2048}
117 "westnet-eastnet" #2: STATE_QUICK_I1: initiate
004 "westnet-eastnet" #2: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP=>0x6e20ef9a <0x08e4af15 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
west:~# ip xfrm policy
src 192.0.2.0/24 dst 192.0.1.0/24 
	dir in priority 2344 
	tmpl src 192.1.2.23 dst 192.1.2.45
		proto esp reqid 16385 mode tunnel
src 192.0.1.0/24 dst 192.0.2.0/24 
	dir out priority 2344 
	tmpl src 192.1.2.45 dst 192.1.2.23
		proto esp reqid 16385 mode tunnel
src 192.0.2.0/24 dst 192.0.1.0/24 
	dir fwd priority 2344 
	tmpl src 192.1.2.23 dst 192.1.2.45
		proto esp reqid 16385 mode tunnel
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
west:~# ip xfrm state
src 192.1.2.45 dst 192.1.2.23
	proto esp spi 0x6e20ef9a reqid 16385 mode tunnel
	replay-window 32 
	auth md5 0xa9696630ea8407f43a5276ef48cadf62
	enc des3_ede 0x65d094fdd272440f23f49cca238bb4538bd689b6ab425b1b
src 192.1.2.23 dst 192.1.2.45
	proto esp spi 0x08e4af15 reqid 16385 mode tunnel
	replay-window 32 
	auth md5 0x1f5131b991f7f2df8c07be36ffb9862d
	enc des3_ede 0x52ceb209417222453b7b3a2a02e27d5687c4e62e11c7e913
west:~# ipsec auto --down  westnet-eastnet
000 "westnet-eastnet" #2: request to replace with shunt a prospective erouted policy with netkey kernel --- not yet implemented
west:~# sleep 1
west:~# ip xfrm policy
src 192.0.1.0/24 dst 192.0.2.0/24 
	dir out priority 2344 
	tmpl src 192.1.2.45 dst 192.1.2.23
		proto esp reqid 16385 mode tunnel
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
west:~# ip xfrm state
west:~# ipsec auto --delete  westnet-eastnet
000 "westnet-eastnet": request to delete a unrouted policy with netkey kernel --- not yet implemented
west:~# sleep 1
west:~# ip xfrm policy
src 192.0.1.0/24 dst 192.0.2.0/24 
	dir out priority 2344 
	tmpl src 192.1.2.45 dst 192.1.2.23
		proto esp reqid 16385 mode tunnel
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir in priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
src 0.0.0.0/0 dst 0.0.0.0/0 
	dir out priority 0 
west:~# ip xfrm state
west:~# echo done
done
west:~# 

west:~# : ==== cut ====
west:~# ipsec auto --status
000 using kernel interface: netkey
000 interface eth0/eth0 192.0.1.254
000 interface eth1/eth1 192.1.2.45
000 interface eth2/eth2 192.9.4.45
000 interface lo/lo 127.0.0.1
000 %myid = (none)
000 debug crypt+parsing+control+controlmore
000  
000 algorithm ESP encrypt: id=2, name=ESP_DES, ivlen=8, keysizemin=64, keysizemax=64
000 algorithm ESP encrypt: id=3, name=ESP_3DES, ivlen=8, keysizemin=192, keysizemax=192
000 algorithm ESP encrypt: id=7, name=ESP_BLOWFISH, ivlen=8, keysizemin=40, keysizemax=448
000 algorithm ESP encrypt: id=11, name=ESP_NULL, ivlen=0, keysizemin=0, keysizemax=0
000 algorithm ESP encrypt: id=12, name=ESP_AES, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=252, name=ESP_SERPENT, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=253, name=ESP_TWOFISH, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP auth attr: id=1, name=AUTH_ALGORITHM_HMAC_MD5, keysizemin=128, keysizemax=128
000 algorithm ESP auth attr: id=2, name=AUTH_ALGORITHM_HMAC_SHA1, keysizemin=160, keysizemax=160
000 algorithm ESP auth attr: id=5, name=AUTH_ALGORITHM_HMAC_SHA2_256, keysizemin=256, keysizemax=256
000 algorithm ESP auth attr: id=251, name=(null), keysizemin=0, keysizemax=0
000  
000 algorithm IKE encrypt: id=3, name=OAKLEY_BLOWFISH_CBC, blocksize=8, keydeflen=128
000 algorithm IKE encrypt: id=5, name=OAKLEY_3DES_CBC, blocksize=8, keydeflen=192
000 algorithm IKE encrypt: id=7, name=OAKLEY_AES_CBC, blocksize=16, keydeflen=128
000 algorithm IKE encrypt: id=65004, name=OAKLEY_SERPENT_CBC, blocksize=16, keydeflen=128
000 algorithm IKE encrypt: id=65005, name=OAKLEY_TWOFISH_CBC, blocksize=16, keydeflen=128
000 algorithm IKE encrypt: id=65289, name=OAKLEY_TWOFISH_CBC_SSH, blocksize=16, keydeflen=128
000 algorithm IKE hash: id=1, name=OAKLEY_MD5, hashsize=16
000 algorithm IKE hash: id=2, name=OAKLEY_SHA1, hashsize=20
000 algorithm IKE hash: id=4, name=OAKLEY_SHA2_256, hashsize=32
000 algorithm IKE hash: id=6, name=OAKLEY_SHA2_512, hashsize=64
000 algorithm IKE dh group: id=2, name=OAKLEY_GROUP_MODP1024, bits=1024
000 algorithm IKE dh group: id=5, name=OAKLEY_GROUP_MODP1536, bits=1536
000 algorithm IKE dh group: id=14, name=OAKLEY_GROUP_MODP2048, bits=2048
000 algorithm IKE dh group: id=15, name=OAKLEY_GROUP_MODP3072, bits=3072
000 algorithm IKE dh group: id=16, name=OAKLEY_GROUP_MODP4096, bits=4096
000 algorithm IKE dh group: id=17, name=OAKLEY_GROUP_MODP6144, bits=6144
000 algorithm IKE dh group: id=18, name=OAKLEY_GROUP_MODP8192, bits=8192
000  
000 stats db_ops: {curr_cnt, total_cnt, maxsz} :context={0,2,36} trans={0,2,336} attrs={0,2,448} 
000  
000  
000  
west:~# cat /tmp/pluto.log
Plutorun started on Thu Feb 14 00:12:49 GMT 2008
Starting Pluto (Libreswan Version 2.5.testing-g21680e0d-dirty; Vendor ID OEGJMMweP{pQ) pid:923
Setting NAT-Traversal port-4500 floating to off
   port floating activation criteria nat_t=0/port_float=1
   including NAT-Traversal patch (Version 0.6c) [disabled]
using /dev/urandom as source of random entropy
ike_alg_register_enc(): Activating OAKLEY_TWOFISH_CBC_SSH: Ok (ret=0)
ike_alg_register_enc(): Activating OAKLEY_TWOFISH_CBC: Ok (ret=0)
ike_alg_register_enc(): Activating OAKLEY_SERPENT_CBC: Ok (ret=0)
ike_alg_register_enc(): Activating OAKLEY_AES_CBC: Ok (ret=0)
ike_alg_register_enc(): Activating OAKLEY_BLOWFISH_CBC: Ok (ret=0)
ike_alg_register_hash(): Activating OAKLEY_SHA2_512: Ok (ret=0)
ike_alg_register_hash(): Activating OAKLEY_SHA2_256: Ok (ret=0)
starting up 1 cryptographic helpers
using /dev/urandom as source of random entropy
started helper pid=924 (fd:6)
Using Linux XFRM/NETKY IPsec interface code on 2.6.18.6
Changed path to directory '/tmp/netkey-pluto-02/ipsec.d/cacerts'
Changed path to directory '/tmp/netkey-pluto-02/ipsec.d/aacerts'
Changed path to directory '/tmp/netkey-pluto-02/ipsec.d/ocspcerts'
Changing to directory '/tmp/netkey-pluto-02/ipsec.d/crls'
  Warning: empty directory
listening for IKE messages
adding interface lo/lo 127.0.0.1:500
adding interface eth2/eth2 192.9.4.45:500
adding interface eth1/eth1 192.1.2.45:500
adding interface eth0/eth0 192.0.1.254:500
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
added connection description "westnet-eastnet"
| base debugging = crypt+parsing+control+controlmore
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 119 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8140158) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8140158) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 119 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8141840) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8141840) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 117 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x81400e8) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x81400e8) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 115 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8142280) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8142280) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 113 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8142280) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8142280) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 111 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8140018) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8140018) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 109 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8140010) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8140010) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 107 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x81421f8) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x81421f8) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 105 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x813ff08) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x813ff08) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 103 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x81421f8) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x81421f8) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 100 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x813ff08) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x813ff08) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 98 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x81445d8) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x81445d8) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 96 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8143c90) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8143c90) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 94 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8144550) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8144550) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 92 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8146ce0) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8146ce0) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 90 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8149940) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8149940) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 88 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8146340) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8146340) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 86 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8148690) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8148690) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 84 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x814a258) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x814a258) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 82 seconds
|  
| *received whack message
listening for IKE messages
| found eth0 with address 192.0.1.254
| found eth1 with address 192.1.2.45
| found eth2 with address 192.9.4.45
| found lo with address 127.0.0.1
| could not open /proc/net/if_inet6
forgetting secrets
loading secrets from "/tmp/netkey-pluto-02/ipsec.secrets"
loaded private key for keyid: PPK_RSA:AQNzGEFs1
| id type added to secret(0x8144550) 1: C=ca, ST=Ontario, O=Libreswan, CN=west.libreswan.org, E=testing.libreswan.org
| id type added to secret(0x8144550) 1: %any
  could not open private key file '/etc/ipsec.d/private/west.key'
"/tmp/netkey-pluto-02/ipsec.secrets" line 26: error loading RSA private key file
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 80 seconds
|  
| *received whack message
| processing connection westnet-eastnet
| kernel_alg_db_new() will return p_new->protoid=3, p_new->trans_cnt=1
| kernel_alg_db_new()     trans[0]: transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
| returning new proposal from esp_info
| creating state object #1 at 0x814c850
| processing connection westnet-eastnet
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  00 00 00 00  00 00 00 00
| state hash entry 10
| inserting state object #1 on chain 10
| inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #1
| processing connection westnet-eastnet
| Queuing pending Quick Mode with 192.1.2.23 "westnet-eastnet"
"westnet-eastnet" #1: initiating Main Mode
| no IKE algorithms for this connection 
| sending 404 bytes for main_outI1 through eth1:500 to 192.1.2.23:500 (using #1)
| inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
| * processed 0 messages from cryptographic helpers 
| next event EVENT_RETRANSMIT in 10 seconds for #1
|  
| *received 116 bytes from 192.1.2.23:500 on eth1 (port=500)
| **parse ISAKMP Message:
|    initiator cookie:
|   64 87 18 2d  ee 7c ff fb
|    responder cookie:
|   75 7b 48 54  0a 79 92 ea
|    next payload type: ISAKMP_NEXT_SA
|    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
|    exchange type: ISAKMP_XCHG_IDPROT
|    flags: none
|    message ID:  00 00 00 00
|    length: 116
|  processing version=1.0 packet with exchange type=ISAKMP_XCHG_IDPROT (2)
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| v1 state object not found
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  00 00 00 00  00 00 00 00
| state hash entry 10
| v1 peer and cookies match on #1, provided msgid 00000000 vs 00000000
| v1 state object #1 found, in STATE_MAIN_I1
| processing connection westnet-eastnet
| got payload 0x2(ISAKMP_NEXT_SA) needed: 0x2 opt: 0x2080
| ***parse ISAKMP Security Association Payload:
|    next payload type: ISAKMP_NEXT_VID
|    length: 52
|    DOI: ISAKMP_DOI_IPSEC
| got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x2080
| ***parse ISAKMP Vendor ID Payload:
|    next payload type: ISAKMP_NEXT_VID
|    length: 16
| got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x2080
| ***parse ISAKMP Vendor ID Payload:
|    next payload type: ISAKMP_NEXT_NONE
|    length: 20
"westnet-eastnet" #1: received Vendor ID payload [Libreswan (this version) 2.5.testing-g21680e0d-dirty ]
"westnet-eastnet" #1: received Vendor ID payload [Dead Peer Detection]
| ****parse IPsec DOI SIT:
|    IPsec DOI SIT: SIT_IDENTITY_ONLY
| ****parse ISAKMP Proposal Payload:
|    next payload type: ISAKMP_NEXT_NONE
|    length: 40
|    proposal number: 0
|    protocol ID: PROTO_ISAKMP
|    SPI size: 0
|    number of transforms: 1
| *****parse ISAKMP Transform Payload (ISAKMP):
|    next payload type: ISAKMP_NEXT_NONE
|    length: 32
|    transform number: 0
|    transform ID: KEY_IKE
| ******parse ISAKMP Oakley attribute:
|    af+type: OAKLEY_LIFE_TYPE
|    length/value: 1
|    [1 is OAKLEY_LIFE_SECONDS]
| ******parse ISAKMP Oakley attribute:
|    af+type: OAKLEY_LIFE_DURATION
|    length/value: 3600
| ******parse ISAKMP Oakley attribute:
|    af+type: OAKLEY_ENCRYPTION_ALGORITHM
|    length/value: 7
|    [7 is OAKLEY_AES_CBC]
| ******parse ISAKMP Oakley attribute:
|    af+type: OAKLEY_HASH_ALGORITHM
|    length/value: 2
|    [2 is OAKLEY_SHA1]
| ******parse ISAKMP Oakley attribute:
|    af+type: OAKLEY_AUTHENTICATION_METHOD
|    length/value: 3
|    [3 is OAKLEY_RSA_SIG]
| ******parse ISAKMP Oakley attribute:
|    af+type: OAKLEY_GROUP_DESCRIPTION
|    length/value: 14
|    [14 is OAKLEY_GROUP_MODP2048]
| Oakley Transform 0 accepted
| sender checking NAT-t: 0 and 0
| 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
| asking helper 0 to do build_kenonce op on seq: 1 (len=2668, pcw_work=1)
| crypto helper write of request: cnt=2668<wlen=2668.  
| inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
| complete state transition with STF_SUSPEND
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 77 seconds
|  
| helper 0 has finished work (cnt now 1)
| helper 0 replies to id: q#1
| calling callback function 0x8069c0d
| main inR1_outI2: calculated ke+nonce, sending I2
| processing connection westnet-eastnet
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  00 00 00 00  00 00 00 00
| state hash entry 10
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| inserting state object #1 on chain 11
| complete state transition with STF_OK
"westnet-eastnet" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
| sending reply packet to 192.1.2.23:500 (from port 500)
| sending 308 bytes for STATE_MAIN_I1 through eth1:500 to 192.1.2.23:500 (using #1)
| inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
"westnet-eastnet" #1: STATE_MAIN_I2: sent MI2, expecting MR2
| modecfg pull: noquirk policy:push not-client
| phase 1 is done, looking for phase 2 to unpend
| * processed 1 messages from cryptographic helpers 
| next event EVENT_RETRANSMIT in 10 seconds for #1
|  
| *received 308 bytes from 192.1.2.23:500 on eth1 (port=500)
| **parse ISAKMP Message:
|    initiator cookie:
|   64 87 18 2d  ee 7c ff fb
|    responder cookie:
|   75 7b 48 54  0a 79 92 ea
|    next payload type: ISAKMP_NEXT_KE
|    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
|    exchange type: ISAKMP_XCHG_IDPROT
|    flags: none
|    message ID:  00 00 00 00
|    length: 308
|  processing version=1.0 packet with exchange type=ISAKMP_XCHG_IDPROT (2)
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| v1 peer and cookies match on #1, provided msgid 00000000 vs 00000000
| v1 state object #1 found, in STATE_MAIN_I2
| processing connection westnet-eastnet
| got payload 0x10(ISAKMP_NEXT_KE) needed: 0x410 opt: 0x102080
| ***parse ISAKMP Key Exchange Payload:
|    next payload type: ISAKMP_NEXT_NONCE
|    length: 260
| got payload 0x400(ISAKMP_NEXT_NONCE) needed: 0x400 opt: 0x102080
| ***parse ISAKMP Nonce Payload:
|    next payload type: ISAKMP_NEXT_NONE
|    length: 20
| DH public value received:
|   59 d4 f7 a7  0e 15 85 07  5d 62 6c 6b  2d 72 86 53
|   6a 64 5e 8a  06 20 9f 0e  8e fa 8c 56  d2 ec f9 df
|   47 6d f8 f1  1b 11 9d dd  62 a4 9e eb  30 e1 38 ce
|   52 21 6e 9b  5c 95 2e 2e  fe 5f 63 71  a4 c2 32 36
|   75 00 ef ef  89 b0 79 b2  3f 0a 3b 26  67 ad 24 82
|   e2 c3 fc c1  e8 c3 1e 31  82 fc 73 08  e4 0c b2 1f
|   cb 90 8c 3f  73 99 6c 1e  7e a9 da 63  97 c1 a1 b2
|   b4 39 f0 21  7d 2a cb ad  3e 8f 4f e0  80 82 db 3c
|   da d7 45 aa  d9 8d 27 49  74 41 38 fd  3d ef e0 e0
|   1d 1b 64 ef  4b 52 5b 5a  28 fa 9a e4  3b 50 95 82
|   f1 2e 9b 4b  1d 00 26 46  b1 88 89 eb  21 39 4e cc
|   53 26 bc 19  cc 1c 6f 40  ee 30 6f 35  a4 a0 65 1e
|   2c b3 c2 45  c9 df 67 06  8c e0 33 0e  fe 3c 6c 6b
|   7d 9c e4 4c  3b 45 5f e7  e2 ad ec 15  59 28 be 25
|   2c 5b 6f 61  fd cf d8 24  59 1b 87 04  66 fa b7 8a
|   9a 87 ab 69  f1 ea 2b 8e  06 dd 6f 53  b9 39 d0 21
| started looking for secret for @west->@east of kind PPK_PSK
| actually looking for secret for @west->@east of kind PPK_PSK
| line 8: key type PPK_PSK(@west) to type PPK_RSA 
| concluding with best_match=0 best=(nil) (lineno=-1)
| parent1 type: 7 group: 14 len: 2668 
| 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
| asking helper 0 to do compute dh+iv op on seq: 2 (len=2668, pcw_work=1)
| crypto helper write of request: cnt=2668<wlen=2668.  
| inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
| complete state transition with STF_SUSPEND
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 77 seconds
|  
| helper 0 has finished work (cnt now 1)
| helper 0 replies to id: q#2
| calling callback function 0x806b553
| main inR2_outI3: calculated DH, sending R1
| processing connection westnet-eastnet
| thinking about whether to send my certificate:
|   I have RSA key: OAKLEY_RSA_SIG cert.type: CERT_NONE 
|   sendcert: CERT_ALWAYSSEND and I did not get a certificate request 
|   so do not send cert.
| I did not send a certificate because I do not have one.
|  I am not sending a certificate request
| hashing 336 bytes of SA
| started looking for secret for @west->@east of kind PPK_RSA
| actually looking for secret for @west->@east of kind PPK_RSA
| line 8: key type PPK_RSA(@west) to type PPK_RSA 
| 1: compared key (none) to @west / @east -> 6
| 2: compared key (none) to @west / @east -> 6
| line 8: match=6 
| best_match 0>6 best=0x814a1d0 (line=8)
| concluding with best_match=6 best=0x814a1d0 (lineno=8)
| signing hash with RSA Key *AQNzGEFs1
| encrypting:
|   09 00 00 0c  02 00 00 00  77 65 73 74  00 00 01 04
|   19 2a fb 07  03 e5 c5 cb  53 d8 7a 67  1f fe 9a 1a
|   b5 12 ee 3c  ab 70 86 77  de 22 28 44  66 4b 3c bc
|   b7 08 41 40  e2 03 22 e3  eb b9 21 40  8d f2 39 be
|   01 db 14 6f  7d f6 c7 c3  82 1b 29 8a  eb 4e 87 33
|   83 dd f6 15  13 9d dd 57  2e 94 ad 29  c5 2e 2e e3
|   3b 1b 05 29  e4 8e 85 e5  a6 c6 89 94  f4 df b7 3f
|   5a da 05 ef  f8 82 b5 72  a5 8e bd ef  ea b1 03 b1
|   ba 1c 90 ce  52 a0 1b 32  40 94 ab 57  77 4f a2 d7
|   0b 50 11 fa  cc 99 a1 3f  41 30 ac 53  80 05 9e 31
|   99 9d a2 56  52 0a 46 d6  53 0d 7f 3a  7d f0 63 94
|   cb 9a ce a8  a3 f2 16 c8  5d 54 ed bf  67 12 28 0c
|   b5 65 bd f0  4c ae 0a d3  a0 a8 b8 10  6b ca bc f5
|   85 e6 34 ba  5f b6 84 86  60 55 e7 18  60 b6 6d 2e
|   31 db 01 db  9b 1b fb 8e  e3 d5 d6 7c  af 93 e4 5f
|   f1 43 3d e7  ca 84 41 0d  9a eb 06 63  6d d3 e1 38
|   e1 f6 b2 3a  1a 6f 8a cc  4d 60 78 27  8d 23 89 34
| IV:
|   96 f2 83 c2  2f 03 11 22  3b d7 1d 6f  29 e0 ea f7
|   79 b1 bf 6d
| unpadded size is: 272
| encrypting 272 using OAKLEY_AES_CBC
| next IV:  ad 44 4f 68  0e 37 ac 9c  86 25 1b 3b  87 0d 53 9d
| complete state transition with STF_OK
"westnet-eastnet" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
| sending reply packet to 192.1.2.23:500 (from port 500)
| sending 300 bytes for STATE_MAIN_I2 through eth1:500 to 192.1.2.23:500 (using #1)
| inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
"westnet-eastnet" #1: STATE_MAIN_I3: sent MI3, expecting MR3
| modecfg pull: noquirk policy:push not-client
| phase 1 is done, looking for phase 2 to unpend
| * processed 1 messages from cryptographic helpers 
| next event EVENT_RETRANSMIT in 10 seconds for #1
|  
| *received 300 bytes from 192.1.2.23:500 on eth1 (port=500)
| **parse ISAKMP Message:
|    initiator cookie:
|   64 87 18 2d  ee 7c ff fb
|    responder cookie:
|   75 7b 48 54  0a 79 92 ea
|    next payload type: ISAKMP_NEXT_ID
|    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
|    exchange type: ISAKMP_XCHG_IDPROT
|    flags: ISAKMP_FLAG_ENCRYPTION
|    message ID:  00 00 00 00
|    length: 300
|  processing version=1.0 packet with exchange type=ISAKMP_XCHG_IDPROT (2)
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| v1 peer and cookies match on #1, provided msgid 00000000 vs 00000000
| v1 state object #1 found, in STATE_MAIN_I3
| processing connection westnet-eastnet
| received encrypted packet from 192.1.2.23:500
| decrypting 272 bytes using algorithm OAKLEY_AES_CBC
| decrypted:
|   09 00 00 0c  02 00 00 00  65 61 73 74  00 00 01 04
|   40 6e 2d 6d  6c 7a 51 84  1a 16 36 08  dd 3d 25 ac
|   62 42 06 e2  70 d3 39 4d  04 fa 3e 7a  e0 59 bf ef
|   d1 53 18 78  01 d1 62 e9  14 fc 0c e8  10 ca 71 f3
|   c1 65 5f bd  db 9d 11 d3  17 57 33 17  2a 85 2b 6f
|   9f 33 36 7a  a5 7a 48 68  09 cb fd 02  95 eb 9f 40
|   e3 ce 3f ca  ce 26 1d ee  f4 e1 44 a4  13 78 95 c1
|   c7 ad ee 4e  01 63 e0 99  09 33 74 39  72 9d 4b 21
|   f3 fa 5f 76  25 a0 e4 02  06 31 ba 91  f6 6a e8 5e
|   e6 08 ab a5  d1 c6 54 80  24 a2 69 b1  24 6a ff 46
|   f6 a0 89 dd  04 26 6f f7  17 db b4 65  30 1c 20 c1
|   5d 2c 1e 2e  5c 28 46 b7  d7 77 0c 82  03 2c 31 89
|   d8 59 d3 dd  ab 99 26 22  5c 1b ee 47  de 93 0b 37
|   29 0c f2 0a  d8 39 a7 da  94 f3 b1 96  ee a3 0e 4f
|   88 20 73 c4  62 44 85 2e  72 f5 12 0d  cd 0a 07 5a
|   7d 63 55 d3  d3 6e 90 32  26 c1 7a 39  db 45 f9 20
|   f4 6e 89 85  60 14 e2 11  79 89 b4 f0  7e 74 27 1f
| next IV:  65 38 7f d7  47 6d 4f 56  db 39 5d 6a  c8 f6 d4 e2
| got payload 0x20(ISAKMP_NEXT_ID) needed: 0x220 opt: 0x20c0
| ***parse ISAKMP Identification Payload:
|    next payload type: ISAKMP_NEXT_SIG
|    length: 12
|    ID type: ID_FQDN
|    DOI specific A: 0
|    DOI specific B: 0
|      obj:   65 61 73 74  00 00 01 04  40 6e 2d 6d
| got payload 0x200(ISAKMP_NEXT_SIG) needed: 0x200 opt: 0x20c0
| ***parse ISAKMP Signature Payload:
|    next payload type: ISAKMP_NEXT_NONE
|    length: 260
"westnet-eastnet" #1: Main mode peer ID is ID_FQDN: '@east'
| hashing 336 bytes of SA
| required CA is '%any'
|   trusted_ca called with a=(empty) b=(empty)
| key issuer CA is '%any'
| an RSA Sig check passed with *AQN3cn11F [preloaded key]
| authentication succeeded
| complete state transition with STF_OK
"westnet-eastnet" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
| inserting event EVENT_SA_REPLACE, timeout in 2766 seconds for #1
"westnet-eastnet" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=aes_128 prf=oakley_sha group=modp2048}
| modecfg pull: noquirk policy:push not-client
| phase 1 is done, looking for phase 2 to unpend
| unqueuing pending Quick Mode with 192.1.2.23 "westnet-eastnet" import:admin initiate
| duplicating state object #1
| creating state object #2 at 0x814de18
| processing connection westnet-eastnet
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| inserting state object #2 on chain 11
| inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #2
| kernel_alg_esp_auth_keylen(auth=1, sadb_aalg=2): a_keylen=16
"westnet-eastnet" #2: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW {using isakmp#1 msgid:b41681c5 proposal=3DES(3)_192-MD5(1)_128 pfsgroup=OAKLEY_GROUP_MODP2048}
| 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
| asking helper 0 to do build_kenonce op on seq: 3 (len=2668, pcw_work=1)
| crypto helper write of request: cnt=2668<wlen=2668.  
| inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #2
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 77 seconds
|  
| helper 0 has finished work (cnt now 1)
| helper 0 replies to id: q#3
| calling callback function 0x806fcab
| quick outI1: calculated ke+nonce, sending I1
| processing connection westnet-eastnet
| kernel_alg_db_new() will return p_new->protoid=3, p_new->trans_cnt=1
| kernel_alg_db_new()     trans[0]: transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
| returning new proposal from esp_info
| HASH(1) computed:
|   2c 96 f3 3e  d4 c1 37 64  13 8b 49 11  ec f4 fc c4
|   99 31 4b 9a
| last Phase 1 IV:  65 38 7f d7  47 6d 4f 56  db 39 5d 6a  c8 f6 d4 e2
| current Phase 1 IV:  65 38 7f d7  47 6d 4f 56  db 39 5d 6a  c8 f6 d4 e2
| computed Phase 2 IV:
|   17 9f 64 78  b1 7b 8a 86  96 cb 56 64  d9 6c 64 19
|   ea e3 2e da
| encrypting:
|   01 00 00 18  2c 96 f3 3e  d4 c1 37 64  13 8b 49 11
|   ec f4 fc c4  99 31 4b 9a  0a 00 00 34  00 00 00 01
|   00 00 00 01  00 00 00 28  00 03 04 01  08 e4 af 15
|   00 00 00 1c  00 03 00 00  80 03 00 0e  80 04 00 01
|   80 01 00 01  80 02 70 80  80 05 00 01  04 00 00 14
|   8b ff 7a 2a  93 76 17 ba  6f 4a 91 10  49 46 b9 06
|   05 00 01 04  b5 b5 e0 9f  03 49 01 f7  cd ed db a0
|   76 38 65 1e  cb ef bd 16  44 47 5d d8  83 b3 bd eb
|   bc 4a 65 a7  61 e6 c3 ac  54 a2 3e a8  71 67 52 a0
|   a2 11 7c ed  66 fd 18 44  6c a0 3a 1a  1b 62 42 c6
|   a4 24 ed 96  d5 e6 e8 ad  6f 0b e8 68  b7 08 38 ad
|   c7 83 dc 20  6a 9c 3a 05  3a d6 0b 78  79 a1 db 4c
|   18 4a 8b cd  70 9c 2e db  d7 46 a3 58  18 a1 fd ac
|   37 e5 88 c9  9e d5 b8 3c  3c 27 8d 2e  31 97 cf 60
|   b1 e1 f9 41  16 c0 b7 60  71 c2 8d 29  14 74 00 ad
|   89 2b d3 28  47 a1 84 a7  03 50 be 8d  cb b9 8b c0
|   3b bb 58 c0  e8 df c6 44  21 cf cf 75  2a 51 98 a4
|   47 68 ba d8  14 8e 07 b1  d3 50 8c ec  bd 1d 0f 7a
|   05 3b 0c 7a  3d 53 85 d4  25 ad 69 43  b2 f1 c1 7d
|   1b b7 e3 ae  04 dd f2 a8  ec 8f f1 52  72 72 e0 d7
|   37 79 4f 6c  8d 8c 55 6b  53 1f c6 d3  02 5f 98 b9
|   0f 08 e3 06  c5 e9 af 18  e0 15 e7 31  72 f5 04 dc
|   98 49 d2 bf  05 00 00 10  04 00 00 00  c0 00 01 00
|   ff ff ff 00  00 00 00 10  04 00 00 00  c0 00 02 00
|   ff ff ff 00
| IV:
|   17 9f 64 78  b1 7b 8a 86  96 cb 56 64  d9 6c 64 19
|   ea e3 2e da
| unpadded size is: 388
| encrypting 400 using OAKLEY_AES_CBC
| next IV:  ee d6 e2 18  6a 0c 22 e5  b4 ab c6 36  7e 3c b8 aa
| sending 428 bytes for quick_outI1 through eth1:500 to 192.1.2.23:500 (using #2)
| inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #2
| * processed 1 messages from cryptographic helpers 
| next event EVENT_RETRANSMIT in 10 seconds for #2
|  
| *received 428 bytes from 192.1.2.23:500 on eth1 (port=500)
| **parse ISAKMP Message:
|    initiator cookie:
|   64 87 18 2d  ee 7c ff fb
|    responder cookie:
|   75 7b 48 54  0a 79 92 ea
|    next payload type: ISAKMP_NEXT_HASH
|    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
|    exchange type: ISAKMP_XCHG_QUICK
|    flags: ISAKMP_FLAG_ENCRYPTION
|    message ID:  c5 81 16 b4
|    length: 428
|  processing version=1.0 packet with exchange type=ISAKMP_XCHG_QUICK (32)
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| v1 peer and cookies match on #2, provided msgid c58116b4 vs c58116b4
| v1 state object #2 found, in STATE_QUICK_I1
| processing connection westnet-eastnet
| received encrypted packet from 192.1.2.23:500
| decrypting 400 bytes using algorithm OAKLEY_AES_CBC
| decrypted:
|   01 00 00 18  5b 3d 30 c0  dd 28 5f bf  c3 64 21 1e
|   b8 b0 a6 98  a7 eb 91 64  0a 00 00 34  00 00 00 01
|   00 00 00 01  00 00 00 28  00 03 04 01  6e 20 ef 9a
|   00 00 00 1c  00 03 00 00  80 03 00 0e  80 04 00 01
|   80 01 00 01  80 02 70 80  80 05 00 01  04 00 00 14
|   da 84 6a e3  ed 3e c7 f9  a9 d2 51 9c  70 c7 79 0a
|   05 00 01 04  a5 a5 b7 29  fd 47 0d 6d  0f bc 7d d4
|   c1 2c 73 31  a0 23 c8 3d  9d 60 7c a7  30 42 62 c8
|   c5 f6 1d 43  74 3c 9d ba  6b 69 7a 38  92 cd d0 3d
|   6c 88 ca 7b  f0 76 a9 a3  2c ee 63 55  39 24 75 cb
|   37 5b 9f 8f  2c 9c 24 48  85 d9 d0 22  13 db 74 72
|   84 c4 1f 23  78 18 09 ff  4f e9 07 e3  8a 8a 8e 11
|   a2 03 7f 72  99 c3 bc f4  4e 1d 16 1c  61 16 83 e9
|   2f 51 74 12  2f 8e e2 84  1e 09 05 58  d2 ee 48 b0
|   3e 0e 8e 9e  ad 11 b0 16  9e ea 30 c5  7e 53 e1 9d
|   3a 90 d3 7e  d2 db 4c 73  10 0d da d3  da 6f c6 67
|   97 c6 41 e3  9e 1b 41 35  5b 75 52 78  10 0b ac 05
|   ca 8b 62 02  2b f1 d5 1a  65 b7 8a e8  18 e1 aa 0f
|   e6 2e a4 6e  79 6b 48 2c  ab 03 3a f9  bd 7b 2a dd
|   e2 1c 76 a3  06 ba 2a 6b  00 ee e6 46  e1 37 ba aa
|   2b e1 bd e6  d1 f1 4d 91  34 29 24 a9  62 1d 2b 99
|   95 67 df d3  97 c1 cc 80  da a2 9c 63  13 eb ca 5c
|   fb 7e d0 ad  05 00 00 10  04 00 00 00  c0 00 01 00
|   ff ff ff 00  00 00 00 10  04 00 00 00  c0 00 02 00
|   ff ff ff 00  00 00 00 00  00 00 00 00  00 00 00 00
| next IV:  fc c3 d1 c9  79 f2 6d 30  57 fc 15 5a  8b 9d 0e 49
| got payload 0x100(ISAKMP_NEXT_HASH) needed: 0x502 opt: 0x200030
| ***parse ISAKMP Hash Payload:
|    next payload type: ISAKMP_NEXT_SA
|    length: 24
| got payload 0x2(ISAKMP_NEXT_SA) needed: 0x402 opt: 0x200030
| ***parse ISAKMP Security Association Payload:
|    next payload type: ISAKMP_NEXT_NONCE
|    length: 52
|    DOI: ISAKMP_DOI_IPSEC
| got payload 0x400(ISAKMP_NEXT_NONCE) needed: 0x400 opt: 0x200030
| ***parse ISAKMP Nonce Payload:
|    next payload type: ISAKMP_NEXT_KE
|    length: 20
| got payload 0x10(ISAKMP_NEXT_KE) needed: 0x0 opt: 0x200030
| ***parse ISAKMP Key Exchange Payload:
|    next payload type: ISAKMP_NEXT_ID
|    length: 260
| got payload 0x20(ISAKMP_NEXT_ID) needed: 0x0 opt: 0x200030
| ***parse ISAKMP Identification Payload (IPsec DOI):
|    next payload type: ISAKMP_NEXT_ID
|    length: 16
|    ID type: ID_IPV4_ADDR_SUBNET
|    Protocol ID: 0
|    port: 0
|      obj:   c0 00 01 00  ff ff ff 00  00 00 00 10  04 00 00 00
| got payload 0x20(ISAKMP_NEXT_ID) needed: 0x0 opt: 0x200030
| ***parse ISAKMP Identification Payload (IPsec DOI):
|    next payload type: ISAKMP_NEXT_NONE
|    length: 16
|    ID type: ID_IPV4_ADDR_SUBNET
|    Protocol ID: 0
|    port: 0
|      obj:   c0 00 02 00  ff ff ff 00  00 00 00 00  00 00 00 00
| removing 12 bytes of padding
| HASH(2) computed:
|   5b 3d 30 c0  dd 28 5f bf  c3 64 21 1e  b8 b0 a6 98
|   a7 eb 91 64
| ****parse IPsec DOI SIT:
|    IPsec DOI SIT: SIT_IDENTITY_ONLY
| ****parse ISAKMP Proposal Payload:
|    next payload type: ISAKMP_NEXT_NONE
|    length: 40
|    proposal number: 0
|    protocol ID: PROTO_IPSEC_ESP
|    SPI size: 4
|    number of transforms: 1
| parsing 4 raw bytes of ISAKMP Proposal Payload into SPI
| SPI  6e 20 ef 9a
| *****parse ISAKMP Transform Payload (ESP):
|    next payload type: ISAKMP_NEXT_NONE
|    length: 28
|    transform number: 0
|    transform ID: ESP_3DES
| ******parse ISAKMP IPsec DOI attribute:
|    af+type: GROUP_DESCRIPTION
|    length/value: 14
|    [14 is OAKLEY_GROUP_MODP2048]
| ******parse ISAKMP IPsec DOI attribute:
|    af+type: ENCAPSULATION_MODE
|    length/value: 1
|    [1 is ENCAPSULATION_MODE_TUNNEL]
| ******parse ISAKMP IPsec DOI attribute:
|    af+type: SA_LIFE_TYPE
|    length/value: 1
|    [1 is SA_LIFE_TYPE_SECONDS]
| ******parse ISAKMP IPsec DOI attribute:
|    af+type: SA_LIFE_DURATION
|    length/value: 28800
| ******parse ISAKMP IPsec DOI attribute:
|    af+type: AUTH_ALGORITHM
|    length/value: 1
|    [1 is AUTH_ALGORITHM_HMAC_MD5]
| DH public value received:
|   a5 a5 b7 29  fd 47 0d 6d  0f bc 7d d4  c1 2c 73 31
|   a0 23 c8 3d  9d 60 7c a7  30 42 62 c8  c5 f6 1d 43
|   74 3c 9d ba  6b 69 7a 38  92 cd d0 3d  6c 88 ca 7b
|   f0 76 a9 a3  2c ee 63 55  39 24 75 cb  37 5b 9f 8f
|   2c 9c 24 48  85 d9 d0 22  13 db 74 72  84 c4 1f 23
|   78 18 09 ff  4f e9 07 e3  8a 8a 8e 11  a2 03 7f 72
|   99 c3 bc f4  4e 1d 16 1c  61 16 83 e9  2f 51 74 12
|   2f 8e e2 84  1e 09 05 58  d2 ee 48 b0  3e 0e 8e 9e
|   ad 11 b0 16  9e ea 30 c5  7e 53 e1 9d  3a 90 d3 7e
|   d2 db 4c 73  10 0d da d3  da 6f c6 67  97 c6 41 e3
|   9e 1b 41 35  5b 75 52 78  10 0b ac 05  ca 8b 62 02
|   2b f1 d5 1a  65 b7 8a e8  18 e1 aa 0f  e6 2e a4 6e
|   79 6b 48 2c  ab 03 3a f9  bd 7b 2a dd  e2 1c 76 a3
|   06 ba 2a 6b  00 ee e6 46  e1 37 ba aa  2b e1 bd e6
|   d1 f1 4d 91  34 29 24 a9  62 1d 2b 99  95 67 df d3
|   97 c1 cc 80  da a2 9c 63  13 eb ca 5c  fb 7e d0 ad
| started looking for secret for @west->@east of kind PPK_PSK
| actually looking for secret for @west->@east of kind PPK_PSK
| line 8: key type PPK_PSK(@west) to type PPK_RSA 
| concluding with best_match=0 best=(nil) (lineno=-1)
| 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
| asking helper 0 to do compute dh(p2) op on seq: 4 (len=2668, pcw_work=1)
| crypto helper write of request: cnt=2668<wlen=2668.  
| inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #2
| complete state transition with STF_SUSPEND
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 77 seconds
|  
| helper 0 has finished work (cnt now 1)
| helper 0 replies to id: q#4
| calling callback function 0x807329a
| quick inI1_outR1: calculated ke+nonce, calculating DH
| processing connection westnet-eastnet
| our client is subnet 192.0.1.0/24
| our client protocol/port is 0/0
| peer client is subnet 192.0.2.0/24
| peer client protocol/port is 0/0
| HASH(3) computed:  2b e4 39 e9  d3 07 c4 54  81 52 53 96  5f 40 02 5f
| HASH(3) computed:  89 c4 87 a9
| compute_proto_keymat:needed_len (after ESP enc)=24
| compute_proto_keymat:needed_len (after ESP auth)=40
| ESP KEYMAT 
|   KEYMAT computed:
|   52 ce b2 09  41 72 22 45  3b 7b 3a 2a  02 e2 7d 56
|   87 c4 e6 2e  11 c7 e9 13  1f 51 31 b9  91 f7 f2 df
|   8c 07 be 36  ff b9 86 2d
|   Peer KEYMAT computed:
|   65 d0 94 fd  d2 72 44 0f  23 f4 9c ca  23 8b b4 53
|   8b d6 89 b6  ab 42 5b 1b  a9 69 66 30  ea 84 07 f4
|   3a 52 76 ef  48 ca df 62
| install_ipsec_sa() for #2: inbound and outbound
| route owner of "westnet-eastnet" unrouted: NULL; eroute owner: NULL
| could_route called for westnet-eastnet (kind=CK_PERMANENT)
| looking for alg with transid: 3 keylen: 0 auth: 1 
| checking transid: 11 keylen: 0 auth: 1 
| checking transid: 11 keylen: 0 auth: 2 
| checking transid: 2 keylen: 8 auth: 0 
| checking transid: 2 keylen: 8 auth: 1 
| checking transid: 2 keylen: 8 auth: 2 
| checking transid: 3 keylen: 24 auth: 0 
| checking transid: 3 keylen: 24 auth: 1 
| looking for alg with transid: 3 keylen: 0 auth: 1 
| checking transid: 11 keylen: 0 auth: 1 
| checking transid: 11 keylen: 0 auth: 2 
| checking transid: 2 keylen: 8 auth: 0 
| checking transid: 2 keylen: 8 auth: 1 
| checking transid: 2 keylen: 8 auth: 2 
| checking transid: 3 keylen: 24 auth: 0 
| checking transid: 3 keylen: 24 auth: 1 
| add inbound eroute 192.0.2.0/24:0 --0-> 192.0.1.0/24:0 => tun.10000@192.1.2.45 (raw_eroute)
| raw_eroute result=1 
| sr for #2: unrouted
| route owner of "westnet-eastnet" unrouted: NULL; eroute owner: NULL
| route_and_eroute with c: westnet-eastnet (next: none) ero:null esr:{(nil)} ro:null rosr:{(nil)} and state: 2
| eroute_connection add eroute 192.0.1.0/24:0 --0-> 192.0.2.0/24:0 => tun.0@192.1.2.23 (raw_eroute)
| raw_eroute result=1 
| command executing up-client
|   trusted_ca called with a=(empty) b=(empty)
| executing up-client: 2>&1 PLUTO_VERSION='2.0' PLUTO_VERB='up-client' PLUTO_CONNECTION='westnet-eastnet' PLUTO_NEXT_HOP='192.1.2.23' PLUTO_INTERFACE='eth1' PLUTO_ME='192.1.2.45' PLUTO_MY_ID='@west' PLUTO_MY_CLIENT='192.0.1.0/24' PLUTO_MY_CLIENT_NET='192.0.1.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='192.1.2.23' PLUTO_PEER_ID='@east' PLUTO_PEER_CLIENT='192.0.2.0/24' PLUTO_PEER_CLIENT_NET='192.0.2.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' PLUTO_CONN_POLICY='RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW' PLUTO_XAUTH_USERNAME=''  ipsec _updown
| route_and_eroute: firewall_notified: true
| command executing prepare-client
|   trusted_ca called with a=(empty) b=(empty)
| executing prepare-client: 2>&1 PLUTO_VERSION='2.0' PLUTO_VERB='prepare-client' PLUTO_CONNECTION='westnet-eastnet' PLUTO_NEXT_HOP='192.1.2.23' PLUTO_INTERFACE='eth1' PLUTO_ME='192.1.2.45' PLUTO_MY_ID='@west' PLUTO_MY_CLIENT='192.0.1.0/24' PLUTO_MY_CLIENT_NET='192.0.1.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='192.1.2.23' PLUTO_PEER_ID='@east' PLUTO_PEER_CLIENT='192.0.2.0/24' PLUTO_PEER_CLIENT_NET='192.0.2.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' PLUTO_CONN_POLICY='RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW' PLUTO_XAUTH_USERNAME=''  ipsec _updown
| command executing route-client
|   trusted_ca called with a=(empty) b=(empty)
| executing route-client: 2>&1 PLUTO_VERSION='2.0' PLUTO_VERB='route-client' PLUTO_CONNECTION='westnet-eastnet' PLUTO_NEXT_HOP='192.1.2.23' PLUTO_INTERFACE='eth1' PLUTO_ME='192.1.2.45' PLUTO_MY_ID='@west' PLUTO_MY_CLIENT='192.0.1.0/24' PLUTO_MY_CLIENT_NET='192.0.1.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='192.1.2.23' PLUTO_PEER_ID='@east' PLUTO_PEER_CLIENT='192.0.2.0/24' PLUTO_PEER_CLIENT_NET='192.0.2.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' PLUTO_CONN_POLICY='RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW' PLUTO_XAUTH_USERNAME=''  ipsec _updown
| route_and_eroute: instance "westnet-eastnet", setting eroute_owner {spd=0x81403e8,sr=0x81403e8} to #2 (was #0) (newest_ipsec_sa=#0)
| encrypting:
|   00 00 00 18  2b e4 39 e9  d3 07 c4 54  81 52 53 96
|   5f 40 02 5f  89 c4 87 a9
| IV:
|   fc c3 d1 c9  79 f2 6d 30  57 fc 15 5a  8b 9d 0e 49
| unpadded size is: 24
| encrypting 32 using OAKLEY_AES_CBC
| next IV:  38 22 eb d4  df dd 42 12  cd 30 06 3d  eb 38 0f 44
| inR1_outI2: instance westnet-eastnet[0], setting newest_ipsec_sa to #2 (was #0) (spd.eroute=#2)
| complete state transition with STF_OK
"westnet-eastnet" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
| sending reply packet to 192.1.2.23:500 (from port 500)
| sending 60 bytes for STATE_QUICK_I1 through eth1:500 to 192.1.2.23:500 (using #2)
| inserting event EVENT_SA_REPLACE, timeout in 28115 seconds for #2
"westnet-eastnet" #2: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP=>0x6e20ef9a <0x08e4af15 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
| modecfg pull: noquirk policy:push not-client
| phase 1 is done, looking for phase 2 to unpend
| * processed 1 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 76 seconds
|  
| *received whack message
| processing connection westnet-eastnet
"westnet-eastnet": terminating SAs using this connection
| processing connection westnet-eastnet
"westnet-eastnet" #2: deleting state (STATE_QUICK_I2)
| deleting state #2
| processing connection westnet-eastnet
| HASH(1) computed:
|   1f 16 2c 6a  a8 4b f9 3a  a8 38 e4 fe  0d 75 65 2f
|   ac d5 45 8c
| last Phase 1 IV:  65 38 7f d7  47 6d 4f 56  db 39 5d 6a  c8 f6 d4 e2
| current Phase 1 IV:  65 38 7f d7  47 6d 4f 56  db 39 5d 6a  c8 f6 d4 e2
| computed Phase 2 IV:
|   2b cd 70 50  51 c1 b7 81  96 1b 71 5c  d4 84 48 f9
|   cf 0d 54 ae
| encrypting:
|   0c 00 00 18  1f 16 2c 6a  a8 4b f9 3a  a8 38 e4 fe
|   0d 75 65 2f  ac d5 45 8c  00 00 00 10  00 00 00 01
|   03 04 00 01  08 e4 af 15
| IV:
|   2b cd 70 50  51 c1 b7 81  96 1b 71 5c  d4 84 48 f9
|   cf 0d 54 ae
| unpadded size is: 40
| encrypting 48 using OAKLEY_AES_CBC
| next IV:  7f 05 67 58  5d 10 d7 c2  52 4a 7c ed  87 3a 9d 93
| sending 76 bytes for delete notify through eth1:500 to 192.1.2.23:500 (using #1)
| no suspended cryptographic state for 2 
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| command executing down-client
|   trusted_ca called with a=(empty) b=(empty)
| executing down-client: 2>&1 PLUTO_VERSION='2.0' PLUTO_VERB='down-client' PLUTO_CONNECTION='westnet-eastnet' PLUTO_NEXT_HOP='192.1.2.23' PLUTO_INTERFACE='eth1' PLUTO_ME='192.1.2.45' PLUTO_MY_ID='@west' PLUTO_MY_CLIENT='192.0.1.0/24' PLUTO_MY_CLIENT_NET='192.0.1.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='192.1.2.23' PLUTO_PEER_ID='@east' PLUTO_PEER_CLIENT='192.0.2.0/24' PLUTO_PEER_CLIENT_NET='192.0.2.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' PLUTO_CONN_POLICY='RSASIG+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW' PLUTO_XAUTH_USERNAME=''  ipsec _updown
"westnet-eastnet" #2: request to replace with shunt a prospective erouted policy with netkey kernel --- not yet implemented
| delete inbound eroute 192.0.2.0/24:0 --0-> 192.0.1.0/24:0 => unk255.10000@192.1.2.45 (raw_eroute)
| raw_eroute result=1 
| processing connection westnet-eastnet
"westnet-eastnet" #1: deleting state (STATE_MAIN_I4)
| deleting state #1
| processing connection westnet-eastnet
| HASH(1) computed:
|   94 b9 57 6f  48 87 6d 06  63 08 ac e6  ff ea f8 80
|   08 25 2c 7a
| last Phase 1 IV:  65 38 7f d7  47 6d 4f 56  db 39 5d 6a  c8 f6 d4 e2
| current Phase 1 IV:  65 38 7f d7  47 6d 4f 56  db 39 5d 6a  c8 f6 d4 e2
| computed Phase 2 IV:
|   06 96 2a 54  2b ea 36 c4  08 ad d0 2a  fe c1 38 36
|   04 85 d7 a4
| encrypting:
|   0c 00 00 18  94 b9 57 6f  48 87 6d 06  63 08 ac e6
|   ff ea f8 80  08 25 2c 7a  00 00 00 1c  00 00 00 01
|   01 10 00 01  64 87 18 2d  ee 7c ff fb  75 7b 48 54
|   0a 79 92 ea
| IV:
|   06 96 2a 54  2b ea 36 c4  08 ad d0 2a  fe c1 38 36
|   04 85 d7 a4
| unpadded size is: 52
| encrypting 64 using OAKLEY_AES_CBC
| next IV:  7d e7 7f c6  c7 7b 99 73  a3 41 43 0c  68 4b 6a bc
| sending 92 bytes for delete notify through eth1:500 to 192.1.2.23:500 (using #1)
| no suspended cryptographic state for 1 
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| unreference key: 0x813fc70 @east cnt 2--
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 76 seconds
|  
| *received 76 bytes from 192.1.2.23:500 on eth1 (port=500)
| **parse ISAKMP Message:
|    initiator cookie:
|   64 87 18 2d  ee 7c ff fb
|    responder cookie:
|   75 7b 48 54  0a 79 92 ea
|    next payload type: ISAKMP_NEXT_HASH
|    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
|    exchange type: ISAKMP_XCHG_INFO
|    flags: ISAKMP_FLAG_ENCRYPTION
|    message ID:  b2 f5 26 0b
|    length: 76
|  processing version=1.0 packet with exchange type=ISAKMP_XCHG_INFO (5)
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| p15 state object not found
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  00 00 00 00  00 00 00 00
| state hash entry 10
| v1 state object not found
packet from 192.1.2.23:500: Informational Exchange is for an unknown (expired?) SA
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 76 seconds
|  
| *received 92 bytes from 192.1.2.23:500 on eth1 (port=500)
| **parse ISAKMP Message:
|    initiator cookie:
|   64 87 18 2d  ee 7c ff fb
|    responder cookie:
|   75 7b 48 54  0a 79 92 ea
|    next payload type: ISAKMP_NEXT_HASH
|    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
|    exchange type: ISAKMP_XCHG_INFO
|    flags: ISAKMP_FLAG_ENCRYPTION
|    message ID:  ec 21 97 ea
|    length: 92
|  processing version=1.0 packet with exchange type=ISAKMP_XCHG_INFO (5)
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  75 7b 48 54  0a 79 92 ea
| state hash entry 11
| p15 state object not found
| ICOOKIE:  64 87 18 2d  ee 7c ff fb
| RCOOKIE:  00 00 00 00  00 00 00 00
| state hash entry 10
| v1 state object not found
packet from 192.1.2.23:500: Informational Exchange is for an unknown (expired?) SA
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 75 seconds
|  
| *received whack message
| processing connection westnet-eastnet
"westnet-eastnet": deleting connection
"westnet-eastnet": request to delete a unrouted policy with netkey kernel --- not yet implemented
| route owner of "westnet-eastnet" unrouted: NULL
| command executing unroute-client
|   trusted_ca called with a=(empty) b=(empty)
| executing unroute-client: 2>&1 PLUTO_VERSION='2.0' PLUTO_VERB='unroute-client' PLUTO_CONNECTION='westnet-eastnet' PLUTO_NEXT_HOP='192.1.2.23' PLUTO_INTERFACE='eth1' PLUTO_ME='192.1.2.45' PLUTO_MY_ID='@west' PLUTO_MY_CLIENT='192.0.1.0/24' PLUTO_MY_CLIENT_NET='192.0.1.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='192.1.2.23' PLUTO_PEER_ID='@east' PLUTO_PEER_CLIENT='192.0.2.0/24' PLUTO_PEER_CLIENT_NET='192.0.2.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' PLUTO_CONN_POLICY='RSASIG+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW'   ipsec _updown
| alg_info_delref(0x81406e8) alg_info->ref_cnt=2
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 74 seconds
|  
| *received whack message
| * processed 0 messages from cryptographic helpers 
| next event EVENT_PENDING_PHASE2 in 62 seconds
west:~# : ==== tuc ====
west:~# if [ -f /tmp/core ]; then echo CORE FOUND; mv /tmp/core /var/tmp; fi
west:~# : ==== end ====
west:~# ipsec setup stop
ipsec_setup: Stopping Libreswan IPsec...
west:~# kill `cat /var/run/klogd.pid`; cat /tmp/klog.log
klogd 1.3-3#33.1, log source = /proc/kmsg started.
<5>Linux version 2.6.18.6 (antony@sal) (gcc version 4.2.3 20080114 (prerelease) (Debian 4.2.2-7)) #6 Wed Feb 13 11:18:26 EST 2008
<7>On node 0 totalpages: 8192
<7>  DMA zone: 8192 pages, LIFO batch:1
<4>Built 1 zonelists.  Total pages: 8192
<5>Kernel command line: initrd=/btmp/antony/ikev2/2008_01_14/UMLPOOL/initrd.uml umlroot=/btmp/antony/ikev2/2008_01_14/UMLPOOL/west/root root=/dev/ram0 rw ssl=pty eth0=daemon,10:00:00:ab:cd:ff,unix,/tmp/umljZyuOz.d/west/ctl,/tmp/umljZyuOz.d/west/data eth1=daemon,10:00:00:64:64:45,unix,/tmp/umljZyuOz.d/public/ctl,/tmp/umljZyuOz.d/public/data eth2=daemon,10:00:00:32:64:45,unix,/tmp/umljZyuOz.d/admin/ctl,/tmp/umljZyuOz.d/admin/data init=/linuxrc single
<4>PID hash table entries: 256 (order: 8, 1024 bytes)
<4>Dentry cache hash table entries: 4096 (order: 2, 16384 bytes)
<4>Inode-cache hash table entries: 2048 (order: 1, 8192 bytes)
<6>Memory: 27028k available
<7>Calibrating delay loop... 3014.65 BogoMIPS (lpj=15073280)
<4>Mount-cache hash table entries: 512
<4>Checking for host processor cmov support...Yes
<4>Checking for host processor xmm support...No
<4>Checking that host ptys support output SIGIO...Yes
<4>Checking that host ptys support SIGIO on close...No, enabling workaround
<6>checking if image is initramfs...it isn't (bad gzip magic numbers); looks like an initrd
<4>Freeing initrd memory: 1212k freed
<4>Using 2.6 host AIO
<6>NET: Registered protocol family 16
<6>NET: Registered protocol family 2
<4>IP route cache hash table entries: 256 (order: -2, 1024 bytes)
<4>TCP established hash table entries: 1024 (order: 0, 4096 bytes)
<4>TCP bind hash table entries: 512 (order: -1, 2048 bytes)
<6>TCP: Hash tables configured (established 1024 bind 512)
<6>TCP reno registered
<4>daemon_setup : Ignoring data socket specification
<6>Netdevice 0 (10:00:00:ab:cd:ff) : daemon backend (uml_switch version 3) - unix:/tmp/umljZyuOz.d/west/ctl
<4>daemon_setup : Ignoring data socket specification
<6>Netdevice 1 (10:00:00:64:64:45) : daemon backend (uml_switch version 3) - unix:/tmp/umljZyuOz.d/public/ctl
<4>daemon_setup : Ignoring data socket specification
<6>Netdevice 2 (10:00:00:32:64:45) : daemon backend (uml_switch version 3) - unix:/tmp/umljZyuOz.d/admin/ctl
<4>Checking host MADV_REMOVE support...OK
<4>mconsole (version 2) initialized on /home/antony/.uml/west/mconsole
<6>Host TLS support detected
<6>Detected host type: i386
<5>VFS: Disk quotas dquot_6.5.1
<4>Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
<6>Initializing Cryptographic API
<6>io scheduler noop registered
<6>io scheduler anticipatory registered (default)
<6>io scheduler deadline registered
<6>io scheduler cfq registered
<4>RAMDISK driver initialized: 16 RAM disks of 4096K size 1024 blocksize
<6>loop: loaded (max 8 devices)
<6>nbd: registered device at major 43
<6>PPP generic driver version 2.4.2
<6>SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256).
<6>tun: Universal TUN/TAP device driver, 1.6
<6>tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
<4>Netfilter messages via NETLINK v0.30.
<6>IPv4 over IPv4 tunneling driver
<6>GRE over IPv4 tunneling driver
<4>ip_conntrack version 2.4 (211 buckets, 1688 max) - 224 bytes per conntrack
<4>ctnetlink v0.90: registering with nfnetlink.
<4>ip_conntrack_pptp version 3.1 loaded
<4>ip_nat_pptp version 3.0 loaded
<4>ip_tables: (C) 2000-2006 Netfilter Core Team
<5>ClusterIP Version 0.8 loaded successfully
<4>arp_tables: (C) 2002 David S. Miller
<6>TCP bic registered
<6>TCP westwood registered
<6>TCP highspeed registered
<6>TCP hybla registered
<6>TCP htcp registered
<6>TCP vegas registered
<6>TCP scalable registered
<6>Initializing IPsec netlink socket
<6>NET: Registered protocol family 1
<6>NET: Registered protocol family 17
<6>NET: Registered protocol family 15
<6>Initialized stdio console driver
<4>Console initialized on /dev/tty0
<6>Initializing software serial port version 1
<4>Failed to open 'root_fs', errno = 2
<5>RAMDISK: cramfs filesystem found at block 0
<5>RAMDISK: Loading 1212KiB [1 disk] into ram disk... |/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\done.
<4>VFS: Mounted root (cramfs filesystem) readonly.
<6>line_ioctl: tty0: ioctl KDSIGACCEPT called
west:~# halt -p -f
System halted.

