root@S4> show log vpnflow.log | no-more Dec 24 06:53:13 S4 clear-log[4117]: logfile cleared Dec 24 06:53:21 06:53:21.546855:CID-0:RT:<10.10.23.2/26735->10.10.34.4/57888;50> : Dec 24 06:53:21 06:53:21.546879:CID-0:RT:packet [172] ipid = 631, @0x4a8263d2 Dec 24 06:53:21 06:53:21.546886:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 15, common flag 0x0, mbuf 0x4a826180, rtbl_idx = 0 Dec 24 06:53:21 06:53:21.546905:CID-0:RT: flow process pak fast ifl 71 in_ifp ge-0/0/0.100 Dec 24 06:53:21 06:53:21.546917:CID-0:RT: ge-0/0/0.100:10.10.23.2->10.10.34.4, 50 Dec 24 06:53:21 06:53:21.546922:CID-0:RT: find flow: table 0x5734df00, hash 24845(0xffff), sa 10.10.23.2, da 10.10.34.4, sp 26735, dp 57888, proto 50, tok 7 Dec 24 06:53:21 06:53:21.546935:CID-0:RT:Found: session id 0x2af. sess tok 7 Dec 24 06:53:21 06:53:21.546938:CID-0:RT: flow got session. Dec 24 06:53:21 06:53:21.546938:CID-0:RT: flow session id 687 Dec 24 06:53:21 06:53:21.546944:CID-0:RT: flow_decrypt: tun 0x59644720(flag 0x82), iif 71 Dec 24 06:53:21 06:53:21.546955:CID-0:RT:lpak_init: lpak 0x5761c4e0, paksize 172, machdr 0x0, iphdr 0x4a8263d2 Dec 24 06:53:21 06:53:21.547074:CID-0:RT:<10.10.23.2/26735->10.10.34.4/57888;50> : Dec 24 06:53:21 06:53:21.547076:CID-0:RT:packet [172] ipid = 631, @0x4a8263d2 Dec 24 06:53:21 06:53:21.547077:CID-0:RT: ----- flow_process_pkt rc 0x11 (fp rc 0) Dec 24 06:53:21 06:53:21.547155:CID-0:RT:<100.100.100.250/28119->10.10.10.102/87;1> : Dec 24 06:53:21 06:53:21.547158:CID-0:RT:packet [100] ipid = 701, @0x4a8263fe Dec 24 06:53:21 06:53:21.547159:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 1, common flag 0x0, mbuf 0x4a826180, rtbl_idx = 0 Dec 24 06:53:21 06:53:21.547160:CID-0:RT:flow process pak, mbuf 0x4a826180, ifl 70, ctxt_type 1 inq type 6 Dec 24 06:53:21 06:53:21.547164:CID-0:RT: in_ifp Dec 24 06:53:21 06:53:21.547165:CID-0:RT:flow_process_pkt_exception: setting rtt in lpak to 0x5d1c8530 Dec 24 06:53:21 06:53:21.547170:CID-0:RT:host inq check inq_type 0x6 Dec 24 06:53:21 06:53:21.547172:CID-0:RT:tifp st0.2 Dec 24 06:53:21 06:53:21.547175:CID-0:RT:pkt out of tunnel.Proceed normally Dec 24 06:53:21 06:53:21.547176:CID-0:RT: st0.2:100.100.100.250->10.10.10.102, icmp, (8/0) Dec 24 06:53:21 06:53:21.547178:CID-0:RT: find flow: table 0x5734df00, hash 21731(0xffff), sa 100.100.100.250, da 10.10.10.102, sp 28119, dp 87, proto 1, tok 8 Dec 24 06:53:21 06:53:21.547182:CID-0:RT: no session found, start first path. in_tunnel - 0x59644720, from_cp_flag - 0 Dec 24 06:53:21 06:53:21.547202:CID-0:RT: Found ts-pair, matching packet's incoming nsp_tunnel (tid 268173316). Doing traffic-selector lookup for 10.10.10.102 -> 100.100.100.250 Dec 24 06:53:21 06:53:21.547217:CID-0:RT: IPSec Traffic-selector permit check success. Returning EOK Dec 24 06:53:21 06:53:21.547229:CID-0:RT: flow_first_create_session Dec 24 06:53:21 06:53:21.547245:CID-0:RT:First path alloc and instl pending session, natp=0x59651470, id=795 Dec 24 06:53:21 06:53:21.547248:CID-0:RT: flow_first_in_dst_nat: in , out dst_adr 10.10.10.102, sp 28119, dp 87 Dec 24 06:53:21 06:53:21.547252:CID-0:RT: chose interface st0.2 as incoming nat if. Dec 24 06:53:21 06:53:21.547257:CID-0:RT:flow_first_rule_dst_xlate: DST no-xlate: 0.0.0.0(0) to 10.10.10.102(87) Dec 24 06:53:21 06:53:21.547260:CID-0:RT:flow_first_routing: vr_id 0, call flow_route_lookup(): src_ip 100.100.100.250, x_dst_ip 10.10.10.102, in ifp st0.2, out ifp N/A sp 28119, dp 87, ip_proto 1, tos 0 Dec 24 06:53:21 06:53:21.547263:CID-0:RT:Doing DESTINATION addr route-lookup Dec 24 06:53:21 06:53:21.547839:CID-0:RT:flow_ipv4_rt_lkup success 10.10.10.102, iifl 0x46, oifl 0x49 Dec 24 06:53:21 06:53:21.547846:CID-0:RT: routed (x_dst_ip 10.10.10.102) from VPN1 (st0.2 in 0) to ge-0/0/1.0, Next-hop: 10.10.45.5 Dec 24 06:53:21 06:53:21.547850:CID-0:RT:flow_first_policy_search: policy search from zone VPN1-> zone INSIDE (0x0,0x6dd70057,0x57) Dec 24 06:53:21 06:53:21.547861:CID-0:RT:Policy lkup: vsys 0 zone(8:VPN1) -> zone(6:INSIDE) scope:0 Dec 24 06:53:21 06:53:21.547863:CID-0:RT: 100.100.100.250/2048 -> 10.10.10.102/29480 proto 1 Dec 24 06:53:21 06:53:21.548020:CID-0:RT: policy has timeout 30 Dec 24 06:53:21 06:53:21.548021:CID-0:RT: app 0, timeout 60s, curr ageout 60s Dec 24 06:53:21 06:53:21.548023:CID-0:RT: permitted by policy VPN_NAT(5) Dec 24 06:53:21 06:53:21.548024:CID-0:RT: packet passed, Permitted by policy. Dec 24 06:53:21 06:53:21.548029:CID-0:RT:flow_first_src_xlate: nat_src_xlated: False, nat_src_xlate_failed: False Dec 24 06:53:21 06:53:21.548033:CID-0:RT:flow_first_src_xlate: incoming src port is : 55149. Dec 24 06:53:21 06:53:21.548035:CID-0:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False. Dec 24 06:53:21 06:53:21.548036:CID-0:RT: dip id = 0/0, 100.100.100.250/28119->100.100.100.250/28119 protocol 0 Dec 24 06:53:21 06:53:21.548039:CID-0:RT: choose interface ge-0/0/1.0(P2P) as outgoing phy if Dec 24 06:53:21 06:53:21.548047:CID-0:RT:is_loop_pak: No loop: on ifp: ge-0/0/1.0, addr: 10.10.10.102, rtt_idx:0 Dec 24 06:53:21 06:53:21.548058:CID-0:RT:-jsf : Alloc sess plugin info for session 795 Dec 24 06:53:21 06:53:21.548063:CID-0:RT:[JSF]Normal interest check. regd plugins 19, enabled impl mask 0x0 Dec 24 06:53:21 06:53:21.548158:CID-0:RT:+++++++++++jsf_test_plugin_data_evh: 3 Dec 24 06:53:21 06:53:21.548188:CID-0:RT:[JSF]Plugins(0x0, count 0) enabled for session = 3414499000320, impli mask(0x0), post_nat cnt 0 svc req(0x0) Dec 24 06:53:21 06:53:21.548190:CID-0:RT:-jsf : no plugin interested for session 795, free sess plugin info Dec 24 06:53:21 06:53:21.548194:CID-0:RT:flow_first_service_lookup(): natp(0x59651470): app_id, 0(0). Dec 24 06:53:21 06:53:21.548195:CID-0:RT: service lookup identified service 0. Dec 24 06:53:21 06:53:21.548196:CID-0:RT: flow_first_final_check: in , out Dec 24 06:53:21 06:53:21.548198:CID-0:RT:In flow_first_complete_session Dec 24 06:53:21 06:53:21.548200:CID-0:RT:flow_first_complete_session, pak_ptr: 0xbf97d728, nsp: 0x59651470, in_tunnel: 0x59644720 Dec 24 06:53:21 06:53:21.548201:CID-0:RT:construct v4 vector for nsp2 Dec 24 06:53:21 06:53:21.548203:CID-0:RT: existing vector list 0x204-0x53f59938. Dec 24 06:53:21 06:53:21.548207:CID-0:RT: Session (id:795) created for first pak 204 Dec 24 06:53:21 06:53:21.548208:CID-0:RT:first pak processing successful Dec 24 06:53:21 06:53:21.548211:CID-0:RT: flow_first_install_session======> 0x59651470 Dec 24 06:53:21 06:53:21.548212:CID-0:RT: nsp 0x59651470, nsp2 0x59651500 Dec 24 06:53:21 06:53:21.548215:CID-0:RT: make_nsp_ready_no_resolve() Dec 24 06:53:21 06:53:21.548219:CID-0:RT:flow_ipv4_rt_lkup success 100.100.100.250, iifl 0x46, oifl 0x45 Dec 24 06:53:21 06:53:21.548224:CID-0:RT: route lookup: dest-ip 100.100.100.250 orig ifp st0.2 output_ifp st0.1 orig-zone 8 out-zone 8 vsd 0 Dec 24 06:53:21 06:53:21.548226:CID-0:RT: reroute handling for tunnel 2ffc0004 Dec 24 06:53:21 06:53:21.548228:CID-0:RT: Doing IPSec traffic-selector match for 10.10.10.102 -> 100.100.100.250 Dec 24 06:53:21 06:53:21.548231:CID-0:RT: Error occured while finding nsp_tunnel for st0-ifp st0.1 Dec 24 06:53:21 06:53:21.548232:CID-0:RT: get_nsp_tunnel - Tunnel not found. if st0.1, nexthop ip 0xfa646464, policy id 0 Dec 24 06:53:21 06:53:21.548233:CID-0:RT: dynamic route to tunnel if st0.1, but tunnel is not ready. reject route, but using ifp Dec 24 06:53:21 06:53:21.548237:CID-0:RT: existing vector list 0x204-0x53f59938. Dec 24 06:53:21 06:53:21.548238:CID-0:RT: setting tunnel vector since the routed interface is st0.1 Dec 24 06:53:21 06:53:21.548238:CID-0:RT: route to 100.100.100.250 Dec 24 06:53:21 06:53:21.548248:CID-0:RT:no need update ha Dec 24 06:53:21 06:53:21.548249:CID-0:RT:Installing c2s NP session wing Dec 24 06:53:21 06:53:21.548252:CID-0:RT:Installing s2c NP session wing Dec 24 06:53:21 06:53:21.548256:CID-0:RT:first path session installation succeeded Dec 24 06:53:21 06:53:21.548257:CID-0:RT: flow got session. Dec 24 06:53:21 06:53:21.548257:CID-0:RT: flow session id 795 Dec 24 06:53:21 06:53:21.548304:CID-0:RT: vector bits 0x204 vector 0x53f59938 Dec 24 06:53:21 06:53:21.548307:CID-0:RT:skip pre-frag: is_tunnel_if- 0, is_if_mtu_configured- 0 Dec 24 06:53:21 06:53:21.548308:CID-0:RT: encap vector Dec 24 06:53:21 06:53:21.548309:CID-0:RT: no more encapping needed Dec 24 06:53:21 06:53:21.548310:CID-0:RT:mbuf 0x4a826180, exit nh 0xe0010 Dec 24 06:53:21 06:53:21.548311:CID-0:RT:flow_process_pkt_exception: Freeing lpak 0xbf97d728 associated with mbuf 0x4a826180 Dec 24 06:53:21 06:53:21.548312:CID-0:RT: ----- flow_process_pkt rc 0x0 (fp rc 0) Dec 24 06:53:21 06:53:21.554705:CID-0:RT:<10.10.10.102/87->100.100.100.250/28119;1> : Dec 24 06:53:21 06:53:21.554713:CID-0:RT:packet [100] ipid = 701, @0x4a750ace Dec 24 06:53:21 06:53:21.554714:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 15, common flag 0x0, mbuf 0x4a750880, rtbl_idx = 0 Dec 24 06:53:21 06:53:21.554717:CID-0:RT: flow process pak fast ifl 73 in_ifp ge-0/0/1.0 Dec 24 06:53:21 06:53:21.554719:CID-0:RT: ge-0/0/1.0:10.10.10.102->100.100.100.250, icmp, (0/0) Dec 24 06:53:21 06:53:21.554722:CID-0:RT: find flow: table 0x5734df00, hash 29397(0xffff), sa 10.10.10.102, da 100.100.100.250, sp 87, dp 28119, proto 1, tok 6 Dec 24 06:53:21 06:53:21.554728:CID-0:RT:Found: session id 0x31b. sess tok 6 Dec 24 06:53:21 06:53:21.554729:CID-0:RT: flow got session. Dec 24 06:53:21 06:53:21.554730:CID-0:RT: flow session id 795 Dec 24 06:53:21 06:53:21.554742:CID-0:RT:flow_ipv4_rt_lkup success 100.100.100.250, iifl 0x0, oifl 0x45 Dec 24 06:53:21 06:53:21.554744:CID-0:RT: handle reroute for tunnel 0 Dec 24 06:53:21 06:53:21.554747:CID-0:RT: Doing IPSec traffic-selector match for 100.100.100.250 -> 10.10.10.102 Dec 24 06:53:21 06:53:21.554752:CID-0:RT: Error occured while finding nsp_tunnel for st0-ifp st0.1 Dec 24 06:53:21 06:53:21.554753:CID-0:RT: get_nsp_tunnel - Tunnel not found. if st0.1, nexthop ip 0xfa646464, policy id 0 Dec 24 06:53:21 06:53:21.554754:CID-0:RT: dynamic route to tunnel if st0.1, but tunnel is not ready. Dec 24 06:53:21 06:53:21.554757:CID-0:RT: packet dropped, pak dropped since re-route failed Dec 24 06:53:21 06:53:21.554761:CID-0:RT: ----- flow_process_pkt rc 0x7 (fp rc -1) Dec 24 06:53:22 06:53:22.650024:CID-0:RT:jsf sess close notify Dec 24 06:53:22 06:53:22.650028:CID-0:RT:flow_ipv4_del_flow: sess 795, in hash 32 Dec 24 06:53:22 06:53:22.650030:CID-0:RT:flow_ipv4_del_flow: sess 795, in hash 32