Racoon VPN Tunnel not passing traffic upstream

Help!

I have an issue with my current hub-and-spoke VPN setup whereby it is not passing traffic in one direction from Racoon across the ESP tunnel to my Juniper SRX. My tunnel is up and and my setup has previously worked before.

If I do a tcpdump -i gif0 I can see traffic from my SRX reaching the gif0 interface. (see below)
Code:
10:37:14.928187 IP 4.4.4.4 > ospf-all.mcast.net: OSPFv2, Hello, length 56
But the SRX reports zero input bytes from the Racoon side.

My racoon configuration is as follows:
Code:
path include "/usr/local/etc/racoon";
path pre_shared_key "/usr/local/etc/racoon/psk.txt";

log debug2;

padding # options are not to be changed
{
        maximum_length  20;	# maximum padding length
        randomize       off;	# enable randomize length
        strict_check    off;	# enable strict check
        exclusive_tail  off;	# extract last one octet
}



listen
{
        isakmp           89.89.89.123 [500];
        isakmp_natt      89.89.89.123 [4500];
        strict_address;
}



remote anonymous [500]
{
        exchange_mode   main;
	doi ipsec_doi;
        my_identifier   address xx.yy.zz.aa;
	dpd_delay 	20;
	dpd_maxfail 	2;
	ike_frag 	force;
	situation	identity_only;
        passive         off;
        proposal_check  obey;
        generate_policy on;
	verify_identifier off;
	initial_contact	on;
        lifetime        time 8 hour;
        script "/usr/local/etc/racoon/phase1_up_down.sh" 	phase1_up;
        script "/usr/local/etc/racoon/phase1_up_down.sh" 	phase1_down;
    	script "/usr/local/etc/racoon/phase1_up_down.sh" 	phase1_dead;

        proposal
        {
                encryption_algorithm  aes256;
                hash_algorithm        sha1;
                authentication_method pre_shared_key;
                dh_group              1;
        }


        proposal
        {

                encryption_algorithm  aes;
                hash_algorithm        sha1;
                authentication_method pre_shared_key;
                dh_group              1;
        }

        proposal
        {

                encryption_algorithm  3des;
                hash_algorithm        sha1;
                authentication_method pre_shared_key;
                dh_group              1;
        }




}



sainfo address 172.16.4.0/24 any address 192.168.22.0/24 any
{
	pfs_group 1;
        lifetime time 1 hour;
        encryption_algorithm des, 3des, aes, aes256;
        authentication_algorithm hmac_md5, hmac_sha1, hmac_sha256, hmac_sha384, hmac_sha512;
        compression_algorithm deflate;

}




sainfo anonymous
{
 	pfs_group 1;	
        lifetime time 1 hour;
        encryption_algorithm des, 3des, aes, aes256;
	authentication_algorithm hmac_md5, hmac_sha1, hmac_sha256, hmac_sha384, hmac_sha512;
        compression_algorithm deflate;

}

My firewall rules are as follows, but I have also just tried stopping the ipfw service to rule out a miss-configured rule.
Code:
#!/bin/sh
ipfw -q flush
WAN="em0"
GIF0="gif0"
GIF1="gif1"
add="ipfw -q add"
ks="keep-state"        # just too lazy to key this each time


$add 79 allow log icmp from any to any out via $WAN
$add 80 allow icmp from any to any in via $WAN
# Allow anything out


$add 81 allow ip from any to any out via $GIF0 
$add 82 allow ip from any to any in via $GIF0
$add 83 allow ip from any to any out via $GIF1
$add 84 allow ip from any to any in via $GIF1



$add 90 allow tcp from any to any 53 out via $WAN setup $ks
$add 91 allow udp from any to any 53 out via $WAN $ks
$add 92 allow tcp from any to any 22,80,8080,443 out via $WAN setup $ks
$add 93 allow tcp from any to any 22,80,8080,443 in via ng0 setup $ks


# Rules for incomming traffic - deny everything that is not explicitely allowed
$add 100 allow tcp from any to any 22, 4, 80, 443, 548 via $WAN in setup limit src-addr 10

$add 184 allow log esp from any to any
$add 185 allow log ah from any to any
$add 186 allow log ipencap from any to any
$add 188 allow log udp from any 500 to any



$add 191 allow udp from any to any 500 via $WAN in keep-state
$add 192 allow udp from any to any 4500 via $WAN in keep-state
$add 200 allow tcp from any to any 1723 via $WAN in setup keep-state
$add 202 allow udp from any to any 1701 via $WAN in keep-state




# Catch spoofing from outside
$add 90 deny ip from any to any not antispoof in

$add 5100 nat 1 all from any to any via $WAN in
$add 5100 divert natd ip from any to any in via $WAN
$add 5101 check-state


# Catch tcp/udp packets, but don't touch gre, esp, icmp traffic
$add 9998 deny log tcp from any to any via $WAN
$add 9999 deny log udp from any to any via $WAN

$add 10000 nat 1 ip from any to any via $WAN out

$add 65534 deny ip from any to any

My rc.conf is as follows:
Code:
hostname="myhost-freebsd"
ifconfig_em0="DHCP"
sshd_enable="YES"
# Set dumpdev to "AUTO" to enable crash dumps, "NO" to disable
dumpdev="NO"
gateway_enable="YES"
firewall_enable="YES"
firewall_script="YES"
firewall_logging="YES"
firewall_script="/usr/local/etc/ipfw.rules"
ipsec_enable="YES"
ipsec_program="/usr/local/sbin/setkey"
ipsec_file="/usr/local/etc/racoon/setkey.conf"
racoon_enable="YES"
racoon_flags="-l /var/log/racoon.log"

My message log generated provides the following:
Code:
Feb 12 22:15:38 myhost-freebsd logger: Finished phase1_down
Feb 12 22:15:59 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 12 22:15:59 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 12 22:15:59 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 12 22:15:59 myhost-freebsd logger: Found phase1_up match
Feb 12 22:15:59 myhost-freebsd logger: Phase_Up Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24,255.255.255.0,172.16.4.1 
Feb 12 22:15:59 myhost-freebsd logger: setkey cmd=setkey -c spdadd 0.0.0.0/0 any 192.168.22.0/24 any -P out ipsec         esp/tunnel/89.89.89.123-31.31.31.2/require;         spdadd 0.0.0.0/0 any 172.16.4.0/24 any -P in ipsec         esp/tunnel/31.31.31.2-89.89.89.123/require;
Feb 12 22:15:59 myhost-freebsd logger: Finished phase1_up
Feb 12 22:43:19 myhost-freebsd kernel: gif0: promiscuous mode enabled
Feb 12 22:45:57 myhost-freebsd kernel: gif0: promiscuous mode disabled
Feb 12 22:46:16 myhost-freebsd kernel: ipfw: limit 5 reached on entry 9998
Feb 12 22:47:00 myhost-freebsd kernel: ipfw: limit 5 reached on entry 184
Feb 12 22:47:00 myhost-freebsd kernel: ipfw: limit 5 reached on entry 186
Feb 12 23:36:04 myhost-freebsd kernel: ipfw: limit 5 reached on entry 188
Feb 13 06:15:59 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 06:15:59 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 06:15:59 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 06:15:59 myhost-freebsd logger: Found phase1_down match
Feb 13 06:15:59 myhost-freebsd logger: Phase_Down Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24, nternalMask,172.16.4.1 
Feb 13 06:15:59 myhost-freebsd logger: PhaseII Down: setkey -c spddelete 0.0.0.0/0 192.168.22.0/24 any -P out; \           spddelete 0.0.0.0/0 172.16.4.0/24 any -P in;
Feb 13 06:15:59 myhost-freebsd logger: Finished phase1_down
Feb 13 07:02:10 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 07:02:10 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 07:02:10 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 07:02:10 myhost-freebsd logger: Found phase1_up match
Feb 13 07:02:10 myhost-freebsd logger: Phase_Up Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24,255.255.255.0,172.16.4.1 
Feb 13 07:02:10 myhost-freebsd logger: setkey cmd=setkey -c spdadd 0.0.0.0/0 any 192.168.22.0/24 any -P out ipsec         esp/tunnel/89.89.89.123-31.31.31.2/require;         spdadd 0.0.0.0/0 any 172.16.4.0/24 any -P in ipsec         esp/tunnel/31.31.31.2-89.89.89.123/require;
Feb 13 07:02:10 myhost-freebsd logger: Finished phase1_up
Feb 13 10:06:01 myhost-freebsd kernel: gif0: promiscuous mode enabled
Feb 13 10:07:17 myhost-freebsd kernel: em0: promiscuous mode enabled
Feb 13 10:09:37 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 10:09:37 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 10:09:37 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 10:09:37 myhost-freebsd logger: Found phase1_down match
Feb 13 10:09:37 myhost-freebsd logger: Phase_Down Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24, nternalMask,172.16.4.1 
Feb 13 10:09:37 myhost-freebsd logger: PhaseII Down: setkey -c spddelete 0.0.0.0/0 192.168.22.0/24 any -P out; \           spddelete 0.0.0.0/0 172.16.4.0/24 any -P in;
Feb 13 10:09:37 myhost-freebsd logger: Finished phase1_down
Feb 13 10:09:37 myhost-freebsd kernel: gif0: promiscuous mode disabled
Feb 13 10:10:00 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 10:10:00 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 10:10:00 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 10:10:00 myhost-freebsd logger: Found phase1_up match
Feb 13 10:10:00 myhost-freebsd logger: Phase_Up Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24,255.255.255.0,172.16.4.1 
Feb 13 10:10:00 myhost-freebsd logger: setkey cmd=setkey -c spdadd 0.0.0.0/0 any 192.168.22.0/24 any -P out ipsec         esp/tunnel/89.89.89.123-31.31.31.2/require;         spdadd 0.0.0.0/0 any 172.16.4.0/24 any -P in ipsec         esp/tunnel/31.31.31.2-89.89.89.123/require;
Feb 13 10:10:00 myhost-freebsd logger: Finished phase1_up
Feb 13 10:10:29 myhost-freebsd kernel: gif0: promiscuous mode enabled
Feb 13 10:10:32 myhost-freebsd kernel: gif0: promiscuous mode disabled
Feb 13 10:10:34 myhost-freebsd kernel: gif0: promiscuous mode enabled
Feb 13 10:12:28 myhost-freebsd kernel: gif0: promiscuous mode disabled
Feb 13 10:12:36 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 10:12:36 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 10:12:36 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 10:12:36 myhost-freebsd logger: Found phase1_down match
Feb 13 10:12:36 myhost-freebsd logger: Phase_Down Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24, nternalMask,172.16.4.1 
Feb 13 10:12:36 myhost-freebsd logger: PhaseII Down: setkey -c spddelete 0.0.0.0/0 192.168.22.0/24 any -P out; \           spddelete 0.0.0.0/0 172.16.4.0/24 any -P in;
Feb 13 10:12:36 myhost-freebsd logger: Finished phase1_down
Feb 13 10:13:00 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 10:13:00 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 10:13:00 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 10:13:00 myhost-freebsd logger: Found phase1_up match
Feb 13 10:13:00 myhost-freebsd logger: Phase_Up Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24,255.255.255.0,172.16.4.1 
Feb 13 10:13:00 myhost-freebsd logger: setkey cmd=setkey -c spdadd 0.0.0.0/0 any 192.168.22.0/24 any -P out ipsec         esp/tunnel/89.89.89.123-31.31.31.2/require;         spdadd 0.0.0.0/0 any 172.16.4.0/24 any -P in ipsec         esp/tunnel/31.31.31.2-89.89.89.123/require;
Feb 13 10:13:00 myhost-freebsd logger: Finished phase1_up
Feb 13 10:13:00 myhost-freebsd kernel: ipsec_common_input: no key association found for SA 89.89.89.123/0be5b3da/50
Feb 13 10:13:19 myhost-freebsd kernel: gif0: promiscuous mode enabled
Feb 13 10:31:08 myhost-freebsd kernel: gif0: promiscuous mode disabled
Feb 13 10:31:11 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 10:31:11 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 10:31:11 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 10:31:11 myhost-freebsd logger: Found phase1_down match
Feb 13 10:31:11 myhost-freebsd logger: Phase_Down Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24, nternalMask,172.16.4.1 
Feb 13 10:31:11 myhost-freebsd logger: PhaseII Down: setkey -c spddelete 0.0.0.0/0 192.168.22.0/24 any -P out; \           spddelete 0.0.0.0/0 172.16.4.0/24 any -P in;
Feb 13 10:31:11 myhost-freebsd logger: Finished phase1_down
Feb 13 10:32:00 myhost-freebsd logger: Phase1-up: Remote ID 1.1.1.1 on 89.89.89.123<->31.31.31.2 Localport 500 Remoteport 500 
Feb 13 10:32:00 myhost-freebsd logger: The next file is 1.1.1.1, and RemoteID = 1.1.1.1
Feb 13 10:32:00 myhost-freebsd logger: Endpoint 1.1.1.1 identified
Feb 13 10:32:00 myhost-freebsd logger: Found phase1_up match
Feb 13 10:32:00 myhost-freebsd logger: Phase_Up Data being passed gif0 , 192.168.22.0/24, 255.255.255.0, 192.168.22.1,172.16.4.0/24,255.255.255.0,172.16.4.1 
Feb 13 10:32:00 myhost-freebsd logger: setkey cmd=setkey -c spdadd 0.0.0.0/0 any 192.168.22.0/24 any -P out ipsec         esp/tunnel/89.89.89.123-31.31.31.2/require;         spdadd 0.0.0.0/0 any 172.16.4.0/24 any -P in ipsec         esp/tunnel/31.31.31.2-89.89.89.123/require;
Feb 13 10:32:00 myhost-freebsd logger: Finished phase1_up
Feb 13 10:32:01 myhost-freebsd kernel: ipsec_common_input: no key association found for SA 89.89.89.123/0a4598da/50
Feb 13 10:32:05 myhost-freebsd kernel: em0: promiscuous mode disabled
Feb 13 10:32:23 myhost-freebsd kernel: em0: promiscuous mode enabled
Feb 13 10:32:53 myhost-freebsd kernel: gif0: promiscuous mode enabled
Feb 13 10:37:23 myhost-freebsd kernel: gif0: promiscuous mode disabled
Feb 13 10:43:13 myhost-freebsd kernel: em0: promiscuous mode disabled

My Racoon log looks like so:
Code:
2014-02-13 11:41:13: DEBUG: hmac(hmac_sha1)
2014-02-13 11:41:13: DEBUG: HASH computed:
2014-02-13 11:41:13: DEBUG:
ad70017b a7f281ce bea05279 d1f95270 b8822d9d
2014-02-13 11:41:13: DEBUG: hash validated.
2014-02-13 11:41:13: DEBUG: begin.
2014-02-13 11:41:13: DEBUG: seen nptype=8(hash)
2014-02-13 11:41:13: DEBUG: seen nptype=11(notify)
2014-02-13 11:41:13: DEBUG: succeed.
2014-02-13 11:41:13: [31.31.31.2] DEBUG: DPD R-U-There-Ack received
2014-02-13 11:41:13: DEBUG: received an R-U-THERE-ACK
2014-02-13 11:41:33: [31.31.31.2] DEBUG: DPD monitoring....
2014-02-13 11:41:33: DEBUG: compute IV for phase2
2014-02-13 11:41:33: DEBUG: phase1 last IV:
2014-02-13 11:41:33: DEBUG:
11617970 cd455aed d4b5ad33
2014-02-13 11:41:33: DEBUG: hash(sha1)
2014-02-13 11:41:33: DEBUG: encryption(3des)
2014-02-13 11:41:33: DEBUG: phase2 IV computed:
2014-02-13 11:41:33: DEBUG:
379bf71a 40353118
2014-02-13 11:41:33: DEBUG: HASH with:
2014-02-13 11:41:33: DEBUG:
d4b5ad33 00000020 00000001 01108d28 45942f67 13e5cdf4 38ea5adb 2ed25ea9
0000041d
2014-02-13 11:41:33: DEBUG: hmac(hmac_sha1)
2014-02-13 11:41:33: DEBUG: HASH computed:
2014-02-13 11:41:33: DEBUG:
7fb45868 f108c8ff 2ebd897f 22df3698 50a66720
2014-02-13 11:41:33: DEBUG: begin encryption.
2014-02-13 11:41:33: DEBUG: encryption(3des)
2014-02-13 11:41:33: DEBUG: pad length = 8
2014-02-13 11:41:33: DEBUG:
0b000018 7fb45868 f108c8ff 2ebd897f 22df3698 50a66720 00000020 00000001
01108d28 45942f67 13e5cdf4 38ea5adb 2ed25ea9 0000041d 00000000 00000008
2014-02-13 11:41:33: DEBUG: encryption(3des)
2014-02-13 11:41:33: DEBUG: with key:
2014-02-13 11:41:33: DEBUG:
2e821daa 872617fd f47d0969 038e4683 5ec99057 dc491d77
2014-02-13 11:41:33: DEBUG: encrypted payload by IV:
2014-02-13 11:41:33: DEBUG:
379bf71a 40353118
2014-02-13 11:41:33: DEBUG: save IV for next:
2014-02-13 11:41:33: DEBUG:
6fc74822 cb8e329b
2014-02-13 11:41:33: DEBUG: encrypted.
2014-02-13 11:41:33: DEBUG: 92 bytes from 89.89.89.123[500] to 31.31.31.2[500]
2014-02-13 11:41:33: DEBUG: sockname 89.89.89.123[500]
2014-02-13 11:41:33: DEBUG: send packet from 89.89.89.123[500]
2014-02-13 11:41:33: DEBUG: send packet to 31.31.31.2[500]
2014-02-13 11:41:33: DEBUG: 1 times of 92 bytes message will be sent to 31.31.31.2[500]
2014-02-13 11:41:33: DEBUG:
45942f67 13e5cdf4 38ea5adb 2ed25ea9 08100501 d4b5ad33 0000005c 8e0743f5
5d8eecec 5bfc7548 49d9dd15 bf1664e2 6b5bdf48 458f3dbc 6c23c3a3 bea834b6
20c413bd 5ad96bd6 edb7639f 75e3ac79 b044c864 6fc74822 cb8e329b
2014-02-13 11:41:33: DEBUG: sendto Information notify.
2014-02-13 11:41:33: DEBUG: IV freed
2014-02-13 11:41:33: [31.31.31.2] DEBUG: DPD R-U-There sent (0)
2014-02-13 11:41:33: [31.31.31.2] DEBUG: rescheduling send_r_u (5).
2014-02-13 11:41:33: DEBUG: ===
2014-02-13 11:41:33: DEBUG: 84 bytes message received from 31.31.31.2[500] to 89.89.89.123[500]
2014-02-13 11:41:33: DEBUG:
45942f67 13e5cdf4 38ea5adb 2ed25ea9 08100501 f2b8b50f 00000054 1e017b80
7f642d30 5e3bfde9 d369827f 5aee5256 b63e53ee d75095f4 2a57091a 68fc76ad
2828a547 3fb77e93 4d7eb291 bc01834b 51453f96
2014-02-13 11:41:33: DEBUG: receive Information.
2014-02-13 11:41:33: DEBUG: compute IV for phase2
2014-02-13 11:41:33: DEBUG: phase1 last IV:
2014-02-13 11:41:33: DEBUG:
11617970 cd455aed f2b8b50f
2014-02-13 11:41:33: DEBUG: hash(sha1)
2014-02-13 11:41:33: DEBUG: encryption(3des)
2014-02-13 11:41:33: DEBUG: phase2 IV computed:
2014-02-13 11:41:33: DEBUG:
2a08372c 0ff42fc6
2014-02-13 11:41:33: DEBUG: begin decryption.
2014-02-13 11:41:33: DEBUG: encryption(3des)
2014-02-13 11:41:33: DEBUG: IV was saved for next processing:
2014-02-13 11:41:33: DEBUG:
bc01834b 51453f96
2014-02-13 11:41:33: DEBUG: encryption(3des)
2014-02-13 11:41:33: DEBUG: with key:
2014-02-13 11:41:33: DEBUG:
2e821daa 872617fd f47d0969 038e4683 5ec99057 dc491d77
2014-02-13 11:41:33: DEBUG: decrypted payload by IV:
2014-02-13 11:41:33: DEBUG:
2a08372c 0ff42fc6
2014-02-13 11:41:33: DEBUG: decrypted payload, but not trimed.
2014-02-13 11:41:33: DEBUG:
0b000018 046c11fe 06271544 70fe974c 0f99efa9 46d2a60f 00000020 00000001
01108d29 45942f67 13e5cdf4 38ea5adb 2ed25ea9 0000041d
2014-02-13 11:41:33: DEBUG: padding len=29
2014-02-13 11:41:33: DEBUG: skip to trim padding.
2014-02-13 11:41:33: DEBUG: decrypted.
2014-02-13 11:41:33: DEBUG:
45942f67 13e5cdf4 38ea5adb 2ed25ea9 08100501 f2b8b50f 00000054 0b000018
046c11fe 06271544 70fe974c 0f99efa9 46d2a60f 00000020 00000001 01108d29
45942f67 13e5cdf4 38ea5adb 2ed25ea9 0000041d
2014-02-13 11:41:33: DEBUG: IV freed
2014-02-13 11:41:33: DEBUG: HASH with:
2014-02-13 11:41:33: DEBUG:
f2b8b50f 00000020 00000001 01108d29 45942f67 13e5cdf4 38ea5adb 2ed25ea9
0000041d
2014-02-13 11:41:33: DEBUG: hmac(hmac_sha1)
2014-02-13 11:41:33: DEBUG: HASH computed:
2014-02-13 11:41:33: DEBUG:
046c11fe 06271544 70fe974c 0f99efa9 46d2a60f
2014-02-13 11:41:33: DEBUG: hash validated.
2014-02-13 11:41:33: DEBUG: begin.
2014-02-13 11:41:33: DEBUG: seen nptype=8(hash)
2014-02-13 11:41:33: DEBUG: seen nptype=11(notify)
2014-02-13 11:41:33: DEBUG: succeed.
2014-02-13 11:41:33: [31.31.31.2] DEBUG: DPD R-U-There-Ack received
2014-02-13 11:41:33: DEBUG: received an R-U-THERE-ACK

My setup script looks like so:
Code:
#!/usr/bin/bash
# Setup and tear down script for Racoon / Setkey ESP tunnesls
#
#                     LOCAL_ADDR
#                             The local address of the phase 1 SA.
#                    LOCAL_PORT
#                             The local port used for IKE for the phase 1 SA.
#                    REMOTE_ADDR
#                             The remote address of the phase 1 SA.
#                     REMOTE_PORT
#                             The remote port used for IKE for the phase 1 SA.
#                     REMOTE_ID
#                             The remote identity received in IKE for the phase
#                             1 SA.
#
OUTPUT="logger"
#OUTPUT="echo"
ExternalSubNets=(192.168.22.0/24 192.168.4.0/24 )
ExternalGateways=(192.168.22.1 192.168.4.254 ) 
ExternalMasks=(255.255.255.0 255.255.255.0 )
InternalSubNets=(172.16.4.0/24 172.16.6.0/24 )
InternalGateways=(172.16.4.1 172.16.6.1 )
InternalMasks=(255.255.255.0 255.255.255.0 )
ExternalIDs="1.1.1.1 1.1.1.3 "
IPSec_Ifaces=(gif0 gif1)
ANY_SRC="0.0.0.0/0"


GIFCONFIG="/sbin/ifconfig"
HOSTNAME=`/bin/hostname`
NETMASK="255.255.255.0"


# Bring up the required interface and tunnel
#
vpnUp ()
{
	IPSec_Iface=$1
	ExternalSubNet=$2
	ExternalMask=$3
	ExternalGateway=$4
	InternalSubNet=$5
	InternalMask=$6
	InternalGateway=$7 
	$OUTPUT "Phase_Up Data being passed $IPSec_Iface , $ExternalSubNet, $ExternalMask, $ExternalGateway,$InternalSubNet,$InternalMask,$InternalGateway "
	# Take down / clear the interface first
	$GIFCONFIG $IPSec_Iface destroy
        # Bring up interface and create tunnel	
	$GIFCONFIG $IPSec_Iface create
        $GIFCONFIG $IPSec_Iface tunnel $LOCAL_ADDR $REMOTE_ADDR MTU 1380
        $GIFCONFIG $IPSec_Iface inet $InternalGateway $ExternalGateway netmask $ExternalMask
	

        SETKEYCMD="setkey -c spdadd $ANY_SRC any $ExternalSubNet any -P out ipsec \
        esp/tunnel/${LOCAL_ADDR}-${REMOTE_ADDR}/require; \
        spdadd $ANY_SRC any $InternalSubNet any -P in ipsec \
        esp/tunnel/${REMOTE_ADDR}-${LOCAL_ADDR}/require;"
	$OUTPUT "setkey cmd=$SETKEYCMD"
	$SETKEYCMD
        /sbin/route add $ExternalSubNet $InternalGateway
	

}


# Bring down the required interface and tunnel
#
vpnDown ()
{
	IPSec_Iface=$1
	ExternalSubNet=$2
	ExternalMask=$3
	ExternalGateway=$4
	InternalSubNet=$5
	InternalMask=$6
	InternalGateway=$7
 	$OUTPUT "Phase_Down Data being passed $IPSec_Iface , $ExternalSubNet, $ExternalMask, $ExternalGateway,$InternalSubNet,$I
nternalMask,$InternalGateway "

        # Take down interface and create tunnel
        
        SETKEYCMD="setkey -c spddelete $ANY_SRC $ExternalSubNet any -P out; \  
        spddelete $ANY_SRC $InternalSubNet any -P in;" 
	$OUTPUT "PhaseII Down: $SETKEYCMD"
	$SETKEYCMD
        /sbin/route del $ExternalSubNet $InternalGateway
        # Take down / clear the interface 
        $GIFCONFIG $IPSec_Iface destroy
 

}





$OUTPUT "Phase1-up: Remote ID ${REMOTE_ID} on ${LOCAL_ADDR}<->${REMOTE_ADDR} Localport $LOCAL_PORT Remoteport $REMOTE_PORT "
MODE=$1 # Get the mode
Ref=0
for fn in $ExternalIDs; do
    $OUTPUT "The next file is $fn, and RemoteID = $REMOTE_ID"
    if [ "$REMOTE_ID" == "$fn" ]; then
       $OUTPUT "Endpoint $REMOTE_ID identified"
       if [ "phase1_up" == "$MODE" ]; then 	
	  $OUTPUT "Found phase1_up match"
          vpnUp ${IPSec_Ifaces[$Ref]} ${ExternalSubNets[$Ref]} ${ExternalMasks[$Ref]} ${ExternalGateways[$Ref]} ${InternalSubNets[$Ref]} ${InternalMasks[$Ref]} ${InternalGateways[$Ref]}
          $OUTPUT "Finished phase1_up" 
          exit 1
	
       else {
        $OUTPUT "Found phase1_down match"
        vpnDown ${IPSec_Ifaces[$Ref]} ${ExternalSubNets[$Ref]} ${ExternalMasks[$Ref]} ${ExternalGateways[$Ref]} ${InternalSubNets[$Ref]} ${InternalMasks[$Ref]} ${InternalGateways[$Ref]}
	  $OUTPUT "Finished phase1_down"
	  exit 1
	}
       fi 
    fi
    Ref=`expr $Ref + 1`
done
$OUTPUT "No remote ID mactched!!"
 
Looking at the tcpdump(1) I'm not sure the SRX is actually sending traffic through, it looks like an OSPF message that's generated by the SRX itself. But it's hard to tell. I can't comment much on the Racoon part but I do know a little about the SRX firewalls. It can be a little tricky to figure out if it's actually passing the correct traffic or not. You can run a tcpdump on the SRX's shell but you can't capture traffic that's on the data plane. This little trick has helped me immensely and is a way to capture all traffic on the SRX itself.

http://kb.juniper.net/InfoCenter/index? ... id=KB11709
 
Thank you for the reply and info on debugging the Juniper side. I am 100% certain the problem rest at the RACOON side though. If you look below at my netstats for the ESP tunnel you can see that its confirms receiving packets from the Juniper side but zero packets are leaving the FreeBSD Racoon side.

Any ideas one where to look would be most helpful as it driving me crazy!!


Code:
root@yubique-freebsd:~ #
root@yubique-freebsd:~ #
root@yubique-freebsd:~ # ifconfig
em0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=209b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,WOL_MAGIC>
        ether 00:16:3c:bc:75:a2
        inet 89.89.89.234 netmask 0xffffffe0 broadcast 89.89.89.255
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
        media: Ethernet autoselect (1000baseT <full-duplex>)
        status: active
ipfw0: flags=8801<UP,SIMPLEX,MULTICAST> metric 0 mtu 65536
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
enc0: flags=0<> metric 0 mtu 1536
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
        options=600003<RXCSUM,TXCSUM,RXCSUM_IPV6,TXCSUM_IPV6>
        inet6 ::1 prefixlen 128
        inet6 fe80::1%lo0 prefixlen 64 scopeid 0x5
        inet 127.0.0.1 netmask 0xff000000
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
gif0: flags=8051<UP,POINTOPOINT,RUNNING,MULTICAST> metric 0 mtu 1280
        tunnel inet 89.89.89.234 --> 31.52.161.157
        inet 172.16.4.1 --> 192.168.22.1 netmask 0xffffff00
        inet6 fe80::216:3cff:febc:75a2%gif0 prefixlen 64 scopeid 0x6
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
        options=1<ACCEPT_REV_ETHIP_VER>
root@yubique-freebsd:~ # ping 192.168.22.1
PING 192.168.22.1 (192.168.22.1): 56 data bytes
^C
--- 192.168.22.1 ping statistics ---
2 packets transmitted, 0 packets received, 100.0% packet loss
root@yubique-freebsd:~ # netstat -sn
tcp:
        155691 packets sent
                142895 data packets (149834320 bytes)
                647 data packets (393575 bytes) retransmitted
                16 data packets unnecessarily retransmitted
                0 resends initiated by MTU discovery
                10365 ack-only packets (5398 delayed)
                0 URG only packets
                0 window probe packets
                10 window update packets
                2006 control packets
        99533 packets received
                80432 acks (for 149818515 bytes)
                3745 duplicate acks
                0 acks for unsent data
                27999 packets (2650732 bytes) received in-sequence
                179 completely duplicate packets (20378 bytes)
                2 old duplicate packets
                14 packets with some dup. data (4424 bytes duped)
                369 out-of-order packets (51216 bytes)
                0 packets (0 bytes) of data after window
                0 window probes
                89 window update packets
                2 packets received after close
                0 discarded for bad checksums
                0 discarded for bad header offset fields
                0 discarded because packet too short
                0 discarded due to memory problems
        33 connection requests
        1976 connection accepts
        0 bad connection attempts
        0 listen queue overflows
        14 ignored RSTs in the windows
        1983 connections established (including accepts)
        4029 connections closed (including 36 drops)
                1926 connections updated cached RTT on close
                1956 connections updated cached RTT variance on close
                1067 connections updated cached ssthresh on close
        7 embryonic connections dropped
        24797 segments updated rtt (of 23391 attempts)
        653 retransmit timeouts
                31 connections dropped by rexmit timeout
        0 persist timeouts
                0 connections dropped by persist timeout
        0 Connections (fin_wait_2) dropped because of timeout
        0 keepalive timeouts
                0 keepalive probes sent
                0 connections dropped by keepalive
        52679 correct ACK header predictions
        11993 correct data packet header predictions
        2242 syncache entries added
                166 retransmitted
                12 dupsyn
                0 dropped
                1976 completed
                0 bucket overflow
                0 cache overflow
                238 reset
                27 stale
                0 aborted
                0 badack
                1 unreach
                0 zone failures
        2242 cookies sent
        0 cookies received
        87 hostcache entries added
                0 bucket overflow
        51 SACK recovery episodes
        114 segment rexmits in SACK recovery episodes
        130880 byte rexmits in SACK recovery episodes
        1928 SACK options (SACK blocks) received
        564 SACK options (SACK blocks) sent
        0 SACK scoreboard overflow
        0 packets with ECN CE bit set
        0 packets with ECN ECT(0) bit set
        0 packets with ECN ECT(1) bit set
        0 successful ECN handshakes
        0 times ECN reduced the congestion window
udp:
        39132 datagrams received
        0 with incomplete header
        0 with bad data length field
        0 with bad checksum
        20 with no checksum
        349 dropped due to no socket
        22994 broadcast/multicast datagrams undelivered
        0 dropped due to full socket buffers
        0 not for hashed pcb
        15789 delivered
        15701 datagrams output
        0 times multicast source filter matched
sctp:
        0 input packets
                0 datagrams
                0 packets that had data
                0 input SACK chunks
                0 input DATA chunks
                0 duplicate DATA chunks
                0 input HB chunks
                0 HB-ACK chunks
                0 input ECNE chunks
                0 input AUTH chunks
                0 chunks missing AUTH
                0 invalid HMAC ids received
                0 invalid secret ids received
                0 auth failed
                0 fast path receives all one chunk
                0 fast path multi-part data
        0 output packets
                0 output SACKs
                0 output DATA chunks
                0 retransmitted DATA chunks
                0 fast retransmitted DATA chunks
                0 FR's that happened more than once to same chunk
                0 output HB chunks
                0 output ECNE chunks
                0 output AUTH chunks
                0 ip_output error counter
        Packet drop statistics:
                0 from middle box
                0 from end host
                0 with data
                0 non-data, non-endhost
                0 non-endhost, bandwidth rep only
                0 not enough for chunk header
                0 not enough data to confirm
                0 where process_chunk_drop said break
                0 failed to find TSN
                0 attempt reverse TSN lookup
                0 e-host confirms zero-rwnd
                0 midbox confirms no space
                0 data did not match TSN
                0 TSN's marked for Fast Retran
        Timeouts:
                0 iterator timers fired
                0 T3 data time outs
                0 window probe (T3) timers fired
                0 INIT timers fired
                0 sack timers fired
                0 shutdown timers fired
                0 heartbeat timers fired
                0 a cookie timeout fired
                0 an endpoint changed its cookiesecret
                0 PMTU timers fired
                0 shutdown ack timers fired
                0 shutdown guard timers fired
                0 stream reset timers fired
                0 early FR timers fired
                0 an asconf timer fired
                0 auto close timer fired
                0 asoc free timers expired
                0 inp free timers expired
        0 packet shorter than header
        0 checksum error
        0 no endpoint for port
        0 bad v-tag
        0 bad SID
        0 no memory
        0 number of multiple FR in a RTT window
        0 RFC813 allowed sending
        0 RFC813 does not allow sending
        0 times max burst prohibited sending
        0 look ahead tells us no memory in interface
        0 numbers of window probes sent
        0 times an output error to clamp down on next user send
        0 times sctp_senderrors were caused from a user
        0 number of in data drops due to chunk limit reached
        0 number of in data drops due to rwnd limit reached
        0 times a ECN reduced the cwnd
        0 used express lookup via vtag
        0 collision in express lookup
        0 times the sender ran dry of user data on primary
        0 same for above
        0 sacks the slow way
        0 window update only sacks sent
        0 sends with sinfo_flags !=0
        0 unordered sends
        0 sends with EOF flag set
        0 sends with ABORT flag set
        0 times protocol drain called
        0 times we did a protocol drain
        0 times recv was called with peek
        0 cached chunks used
        0 cached stream oq's used
        0 unread messages abandonded by close
        0 send burst avoidance, already max burst inflight to net
        0 send cwnd full avoidance, already max burst inflight to net
        0 number of map array over-runs via fwd-tsn's
ip:
        235318 total packets received
        0 bad header checksums
        0 with size smaller than minimum
        0 with data size < data length
        0 with ip length > max ip packet size
        0 with header length < data size
        0 with data length < header length
        0 with bad options
        0 with incorrect version number
        0 fragments received
        0 fragments dropped (dup or out of space)
        0 fragments dropped after timeout
        0 packets reassembled ok
        193810 packets for this host
        31873 packets for unknown/unsupported protocol
        0 packets forwarded (0 packets fast forwarded)
        2125 packets not forwardable
        0 packets received for unknown multicast group
        0 redirects sent
        174237 packets sent from this host
        0 packets sent with fabricated ip header
        0 output packets dropped due to no bufs, etc.
        0 output packets discarded due to no route
        0 output datagrams fragmented
        0 fragments created
        0 datagrams that can't be fragmented
        0 tunneling packets that can't find gif
        0 datagrams with bad address in header
icmp:
        349 calls to icmp_error
        0 errors not generated in response to an icmp message
        Output histogram:
                echo reply: 157
                destination unreachable: 349
        0 messages with bad code fields
        0 messages less than the minimum length
        0 messages with bad checksum
        1 message with bad length
        0 multicast echo requests ignored
        0 multicast timestamp requests ignored
        Input histogram:
                echo reply: 108
                destination unreachable: 52
                echo: 157
                time exceeded: 6
        157 message responses generated
        0 invalid return addresses
        0 no return routes
        ICMP address mask responses are disabled
igmp:
        4791 messages received
        0 messages received with too few bytes
        0 messages received with wrong TTL
        0 messages received with bad checksum
        4788 V1/V2 membership queries received
        0 V3 membership queries received
        0 membership queries received with invalid field(s)
        4788 general queries received
        0 group queries received
        0 group-source queries received
        0 group-source queries dropped
        0 membership reports received
        0 membership reports received with invalid field(s)
        0 membership reports received for groups to which we belong
        0 V3 reports received without Router Alert
        0 membership reports sent
ipsec:
        0 inbound packets processed successfully
        0 inbound packets violated process security policy
        0 inbound packets with no SA available
        0 invalid inbound packets
        0 inbound packets failed due to insufficient memory
        0 inbound packets failed getting SPI
        0 inbound packets failed on AH replay check
        0 inbound packets failed on ESP replay check
        0 inbound packets considered authentic
        0 inbound packets failed on authentication
        0 outbound packets processed successfully
        0 outbound packets violated process security policy
        0 outbound packets with no SA available
        0 invalid outbound packets
        0 outbound packets failed due to insufficient memory
        0 outbound packets with no route
        0 SPD cache lookups
        0 SPD cache misses
        0 inbound packets violated process security policy
        0 outbound packets violated process security policy
        147 outbound packets with no SA available
        0 outbound packets failed due to insufficient memory
        0 outbound packets with no route available
        0 invalid outbound packets
        0 outbound packets with bundled SAs
        0 mbufs coalesced during clone
        0 clusters coalesced during clone
        0 clusters copied during clone
        0 mbufs inserted during makespace
ah:
        0 packets shorter than header shows
        0 packets dropped; protocol family not supported
        0 packets dropped; no TDB
        0 packets dropped; bad KCR
        0 packets dropped; queue full
        0 packets dropped; no transform
        0 replay counter wraps
        0 packets dropped; bad authentication detected
        0 packets dropped; bad authentication length
        0 possible replay packets detected
        0 packets in
        0 packets out
        0 packets dropped; invalid TDB
        0 bytes in
        0 bytes out
        0 packets dropped; larger than IP_MAXPACKET
        0 packets blocked due to policy
        0 crypto processing failures
        0 tunnel sanity check failures
        AH output histogram:
                hmac-sha1: 27356
esp:
        0 packets shorter than header shows
        0 packets dropped; protocol family not supported
        167 packets dropped; no TDB
        0 packets dropped; bad KCR
        0 packets dropped; queue full
        0 packets dropped; no transform
        0 packets dropped; bad ilen
        0 replay counter wraps
        0 packets dropped; bad encryption detected
        0 packets dropped; bad authentication detected
        0 possible replay packets detected
        27523 packets in
        0 packets out
        0 packets dropped; invalid TDB
        2188680 bytes in
        0 bytes out
        0 packets dropped; larger than IP_MAXPACKET
        0 packets blocked due to policy
        0 crypto processing failures
        0 tunnel sanity check failures
        ESP output histogram:
                3des-cbc: 27045
                rijndael-cbc: 311
ipcomp:
        0 packets shorter than header shows
        0 packets dropped; protocol family not supported
        0 packets dropped; no TDB
        0 packets dropped; bad KCR
        0 packets dropped; queue full
        0 packets dropped; no transform
        0 replay counter wraps
        0 packets in
        0 packets out
        0 packets dropped; invalid TDB
        0 bytes in
        0 bytes out
        0 packets dropped; larger than IP_MAXPACKET
        0 packets blocked due to policy
        0 crypto processing failures
        0 packets sent uncompressed; size < compr. algo. threshold
        0 packets sent uncompressed; compression was useless
arp:
        193 ARP requests sent
        2 ARP replies sent
        148252 ARP requests received
        220 ARP replies received
        148485 ARP packets received
        0 total packets dropped due to no ARP entry
        172 ARP entrys timed out
        0 Duplicate IPs seen
ip6:
        0 total packets received
        0 with size smaller than minimum
        0 with data size < data length
        0 with bad options
        0 with incorrect version number
        0 fragments received
        0 fragments dropped (dup or out of space)
        0 fragments dropped after timeout
        0 fragments that exceeded limit
        0 packets reassembled ok
        0 packets for this host
        0 packets forwarded
        0 packets not forwardable
        0 redirects sent
        95 packets sent from this host
        0 packets sent with fabricated ip header
        0 output packets dropped due to no bufs, etc.
        0 output packets discarded due to no route
        0 output datagrams fragmented
        0 fragments created
        0 datagrams that can't be fragmented
        0 packets that violated scope rules
        0 multicast packets which we don't join
        Mbuf statistics:
                0 one mbuf
                2249 one ext mbuf
                0 two or more ext mbuf
        0 packets whose headers are not contiguous
        0 tunneling packets that can't find gif
        0 packets discarded because of too many headers
        0 failures of source address selection
        Source addresses selection rule applied:
icmp6:
        0 calls to icmp6_error
        0 errors not generated in response to an icmp6 message
        0 errors not generated because of rate limitation
        Output histogram:
                neighbor solicitation: 23
                MLDv2 listener report: 4
        0 messages with bad code fields
        0 messages < minimum length
        0 bad checksums
        0 messages with bad length
        Histogram of error messages to be generated:
                0 no route
                0 administratively prohibited
                0 beyond scope
                0 address unreachable
                0 port unreachable
                0 packet too big
                0 time exceed transit
                0 time exceed reassembly
                0 erroneous header field
                0 unrecognized next header
                0 unrecognized option
                0 redirect
                0 unknown
        0 message responses generated
        0 messages with too many ND options
        0 messages with bad ND options
        0 bad neighbor solicitation messages
        0 bad neighbor advertisement messages
        0 bad router solicitation messages
        0 bad router advertisement messages
        0 bad redirect messages
        0 path MTU changes
ipsec6:
        0 inbound packets processed successfully
        0 inbound packets violated process security policy
        0 inbound packets with no SA available
        0 invalid inbound packets
        0 inbound packets failed due to insufficient memory
        0 inbound packets failed getting SPI
        0 inbound packets failed on AH replay check
        0 inbound packets failed on ESP replay check
        0 inbound packets considered authentic
        0 inbound packets failed on authentication
        0 outbound packets processed successfully
        0 outbound packets violated process security policy
        0 outbound packets with no SA available
        0 invalid outbound packets
        0 outbound packets failed due to insufficient memory
        0 outbound packets with no route
        0 SPD cache lookups
        0 SPD cache misses
        0 inbound packets violated process security policy
        0 outbound packets violated process security policy
        0 outbound packets with no SA available
        0 outbound packets failed due to insufficient memory
        0 outbound packets with no route available
        0 invalid outbound packets
        0 outbound packets with bundled SAs
        0 mbufs coalesced during clone
        0 clusters coalesced during clone
        0 clusters copied during clone
        0 mbufs inserted during makespace
rip6:
        0 messages received
        0 checksum calculations on inbound
        0 messages with bad checksum
        0 messages dropped due to no socket
        0 multicast messages dropped due to no socket
        0 messages dropped due to full socket buffers
        0 delivered
        0 datagrams output
pfkey:
        949 requests sent from userland
        108016 bytes sent from userland
        histogram by message type:
                getspi: 126
                update: 120
                add: 120
                delete: 93
                acquire: 1
                register: 111
                flush: 17
                dump: 120
                x_spdupdate: 182
                x_spdadd: 2
                x_spddelete: 38
                x_spddump: 17
                x_spdflush: 2
        0 messages with invalid length field
        0 messages with invalid version field
        0 messages with invalid message type field
        0 messages too short
        0 messages with memory allocation failure
        0 messages with duplicate extension
        0 messages with invalid extension type
        0 messages with invalid sa type
        0 messages with invalid address extension
        1394 requests sent to userland
        251016 bytes sent to userland
        histogram by message type:
                getspi: 126
                update: 120
                add: 120
                delete: 93
                acquire: 27
                register: 111
                expire: 82
                flush: 17
                dump: 442
                x_spdupdate: 182
                x_spdadd: 2
                x_spddelete: 38
                x_spddump: 28
                x_spdflush: 2
                x_spdexpire: 4
        442 messages toward single socket
        1 message toward all sockets
        173 messages toward registered sockets
        0 messages with memory allocation failure
 
Back
Top