Apr 14 18:36:51 chocolatepudding clear-log[7218]: logfile cleared Apr 14 18:37:00 18:37:00.662058:CID-0:RT:<45.27.139.181/156->172.21.2.2/1;1,0x0> matched filter filter3: Apr 14 18:37:00 18:37:00.662058:CID-0:RT:packet [60] ipid = 28387, @0x43e467c8 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 1, common flag 0x0, mbuf 0x43e46580, rtbl_idx = 0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow process pak, mbuf 0x43e46580, ifl 0, ctxt_type 1 inq type 6 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: in_ifp Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_process_pkt_exception: setting rtt in lpak to 0x5e4ea960 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:host inq check inq_type 0x6 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:tifp NULL Apr 14 18:37:00 18:37:00.662058:CID-0:RT:pkt out of tunnel.Proceed normally Apr 14 18:37:00 18:37:00.662058:CID-0:RT: ge-0/0/0.0:45.27.139.181->172.21.2.2, icmp, (8/0) Apr 14 18:37:00 18:37:00.662058:CID-0:RT: find flow: table 0x52fa14b0, hash 32799(0xffff), sa 45.27.139.181, da 172.21.2.2, sp 156, dp 1, proto 1, tok 6, conn-tag 0x00000000 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: no session found, start first path. in_tunnel - 0x5540e238, from_cp_flag - 0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: flow_first_create_session Apr 14 18:37:00 18:37:00.662058:CID-0:RT:Save init hash spu id 0 to nsp and nsp2! Apr 14 18:37:00 18:37:00.662058:CID-0:RT:Installing pending sess (11737) in ager Apr 14 18:37:00 18:37:00.662058:CID-0:RT:First path alloc and instl pending session, natp=0x5554b7d8, id=11737 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:First path alloc and instl pending session, natp=0x5554b7d8, id=11737 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: flow_first_in_dst_nat: in , out dst_adr 172.21.2.2, sp 156, dp 1 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: chose interface ge-0/0/0.0 as incoming nat if. Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_rule_dst_xlate: DST no-xlate: 0.0.0.0(0) to 172.21.2.2(1) Apr 14 18:37:00 18:37:00.662058:CID-0:RT:-jsf : Alloc sess plugin info for session 4294979033 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:[JSF] Do ingress interest check. regd ingress plugins(1) Apr 14 18:37:00 18:37:00.662058:CID-0:RT:[JSF][0]plugins(0x0) enabled for session = 4294979033 implicit mask(0x0), service request(0x0) Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_routing: vr_id 0, call flow_route_lookup(): src_ip 45.27.139.181, x_dst_ip 172.21.2.2, in ifp ge-0/0/0.0, out ifp N/A sp 156, dp 1, ip_proto 1, tos 0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:Doing DESTINATION addr route-lookup Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_ipv4_rt_lkup success 172.21.2.2, iifl 0x4b, oifl 0x4b Apr 14 18:37:00 18:37:00.662058:CID-0:RT: routed (x_dst_ip 172.21.2.2) from Untrust (ge-0/0/0.0 in 0) to ge-0/0/0.0, Next-hop: 45.27.153.57 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_policy_search: policy search from zone Untrust-> zone Untrust (0x0,0x9c0001,0x1) Apr 14 18:37:00 18:37:00.662058:CID-0:RT:Policy lkup: vsys 0 zone(6:Untrust) -> zone(6:Untrust) scope:0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: 45.27.139.181/2048 -> 172.21.2.2/19647 proto 1 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: app 0, timeout 60s, curr ageout 60s Apr 14 18:37:00 18:37:00.662058:CID-0:RT: permitted by policy Untrust_To_Untrust(13) Apr 14 18:37:00 18:37:00.662058:CID-0:RT: packet passed, Permitted by policy. Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_src_xlate: nat_src_xlated: False, nat_src_xlate_failed: False Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_src_xlate: incoming src port is : 156. Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False. Apr 14 18:37:00 18:37:00.662058:CID-0:RT: dip id = 0/0, 45.27.139.181/156->45.27.139.181/156 protocol 0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: choose interface ge-0/0/0.0(P2P) as outgoing phy if Apr 14 18:37:00 18:37:00.662058:CID-0:RT:is_loop_pak: No loop: on ifp: ge-0/0/0.0, addr: 172.21.2.2, rtt_idx:0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:[JSF]Normal interest check. regd plugins 31, enabled impl mask 0x0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:+++++++++++jsf_test_plugin_data_evh: 3 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:[JSF]Plugins(0x0, count 0) enabled for session = 4294979033, impli mask(0x0), post_nat cnt 0 svc req(0x56fbf028) Apr 14 18:37:00 18:37:00.662058:CID-0:RT:-jsf : no plugin interested for session 4294979033, free sess plugin info Apr 14 18:37:00 18:37:00.662058:CID-0:RT:[JSF]Releasing plugin info blocks Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_service_lookup(): natp(0x5554b7d8): app_id, 0(0). Apr 14 18:37:00 18:37:00.662058:CID-0:RT: service lookup identified service 0. Apr 14 18:37:00 18:37:00.662058:CID-0:RT: flow_first_final_check: in , out Apr 14 18:37:00 18:37:00.662058:CID-0:RT:In flow_first_complete_session Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_first_complete_session, pak_ptr: 0x50e24ec0, nsp: 0x5554b7d8, in_tunnel: 0x5540e238 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:construct v4 vector for nsp2 and nsp Apr 14 18:37:00 18:37:00.662058:CID-0:RT: existing vector list 0x204-0x4b10ecd0. Apr 14 18:37:00 18:37:00.662058:CID-0:RT: existing vector list 0x204-0x4b10ecd0. Apr 14 18:37:00 18:37:00.662058:CID-0:RT: Session (id:11737) created for first pak 204 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:first pak processing successful Apr 14 18:37:00 18:37:00.662058:CID-0:RT: flow_first_install_session======> 0x5554b7d8 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: nsp 0x5554b7d8, nsp2 0x5554b868 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: make_nsp_ready_no_resolve() Apr 14 18:37:00 18:37:00.662058:CID-0:RT: reverse route is optional Apr 14 18:37:00 18:37:00.662058:CID-0:RT:nsp_set_pmtu: tunnel_nsp out_ifp ge-0/0/0.0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: tunnel pmtu is already calculated, tunneloperating pmtu 1430 nsp ifp(ge-0/0/0.0) pmtu 1500 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:get NULL sess plugin info 0x5554b7d8 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:avt_get_app_name(): Getting appid failed. Apr 14 18:37:00 18:37:00.662058:CID-0:RT:get NULL sess plugin info 0x5554b7d8 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:no need update ha Apr 14 18:37:00 18:37:00.662058:CID-0:RT:Installing s2c NP session wing Apr 14 18:37:00 18:37:00.662058:CID-0:RT:updating pending sess (11737) in ager Apr 14 18:37:00 18:37:00.662058:CID-0:RT:first path session installation succeeded Apr 14 18:37:00 18:37:00.662058:CID-0:RT: flow got session. Apr 14 18:37:00 18:37:00.662058:CID-0:RT: flow session id 11737 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: vector bits 0x204 vector 0x4b10ecd0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:skip pre-frag: is_tunnel_if- 0, is_if_mtu_configured- 0 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: encap vector Apr 14 18:37:00 18:37:00.662058:CID-0:RT: no more encapping needed Apr 14 18:37:00 18:37:00.662058:CID-0:RT:mbuf 0x43e46580, exit nh 0x130010 Apr 14 18:37:00 18:37:00.662058:CID-0:RT:flow_process_pkt_exception: Freeing lpak 0x50e24ec0 associated with mbuf 0x43e46580 Apr 14 18:37:00 18:37:00.662058:CID-0:RT: ----- flow_process_pkt rc 0x0 (fp rc 0) Apr 14 18:37:05 18:37:05.172649:CID-0:RT:<45.27.139.181/157->172.21.2.2/1;1,0x0> matched filter filter3: Apr 14 18:37:05 18:37:05.172649:CID-0:RT:packet [60] ipid = 28388, @0x43e588c8 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 1, common flag 0x0, mbuf 0x43e58680, rtbl_idx = 0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow process pak, mbuf 0x43e58680, ifl 0, ctxt_type 1 inq type 6 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: in_ifp Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_process_pkt_exception: setting rtt in lpak to 0x5e4ea960 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:host inq check inq_type 0x6 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:tifp NULL Apr 14 18:37:05 18:37:05.172649:CID-0:RT:pkt out of tunnel.Proceed normally Apr 14 18:37:05 18:37:05.172649:CID-0:RT: ge-0/0/0.0:45.27.139.181->172.21.2.2, icmp, (8/0) Apr 14 18:37:05 18:37:05.172649:CID-0:RT: find flow: table 0x52fa14b0, hash 25455(0xffff), sa 45.27.139.181, da 172.21.2.2, sp 157, dp 1, proto 1, tok 6, conn-tag 0x00000000 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: no session found, start first path. in_tunnel - 0x5540e238, from_cp_flag - 0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: flow_first_create_session Apr 14 18:37:05 18:37:05.172649:CID-0:RT:Save init hash spu id 0 to nsp and nsp2! Apr 14 18:37:05 18:37:05.172649:CID-0:RT:Installing pending sess (11746) in ager Apr 14 18:37:05 18:37:05.172649:CID-0:RT:First path alloc and instl pending session, natp=0x5554c948, id=11746 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:First path alloc and instl pending session, natp=0x5554c948, id=11746 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: flow_first_in_dst_nat: in , out dst_adr 172.21.2.2, sp 157, dp 1 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: chose interface ge-0/0/0.0 as incoming nat if. Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_rule_dst_xlate: DST no-xlate: 0.0.0.0(0) to 172.21.2.2(1) Apr 14 18:37:05 18:37:05.172649:CID-0:RT:-jsf : Alloc sess plugin info for session 4294979042 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:[JSF] Do ingress interest check. regd ingress plugins(1) Apr 14 18:37:05 18:37:05.172649:CID-0:RT:[JSF][0]plugins(0x0) enabled for session = 4294979042 implicit mask(0x0), service request(0x0) Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_routing: vr_id 0, call flow_route_lookup(): src_ip 45.27.139.181, x_dst_ip 172.21.2.2, in ifp ge-0/0/0.0, out ifp N/A sp 157, dp 1, ip_proto 1, tos 0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:Doing DESTINATION addr route-lookup Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_ipv4_rt_lkup success 172.21.2.2, iifl 0x4b, oifl 0x4b Apr 14 18:37:05 18:37:05.172649:CID-0:RT: routed (x_dst_ip 172.21.2.2) from Untrust (ge-0/0/0.0 in 0) to ge-0/0/0.0, Next-hop: 45.27.153.57 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_policy_search: policy search from zone Untrust-> zone Untrust (0x0,0x9d0001,0x1) Apr 14 18:37:05 18:37:05.172649:CID-0:RT:Policy lkup: vsys 0 zone(6:Untrust) -> zone(6:Untrust) scope:0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: 45.27.139.181/2048 -> 172.21.2.2/19646 proto 1 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: app 0, timeout 60s, curr ageout 60s Apr 14 18:37:05 18:37:05.172649:CID-0:RT: permitted by policy Untrust_To_Untrust(13) Apr 14 18:37:05 18:37:05.172649:CID-0:RT: packet passed, Permitted by policy. Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_src_xlate: nat_src_xlated: False, nat_src_xlate_failed: False Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_src_xlate: incoming src port is : 157. Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False. Apr 14 18:37:05 18:37:05.172649:CID-0:RT: dip id = 0/0, 45.27.139.181/157->45.27.139.181/157 protocol 0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: choose interface ge-0/0/0.0(P2P) as outgoing phy if Apr 14 18:37:05 18:37:05.172649:CID-0:RT:is_loop_pak: No loop: on ifp: ge-0/0/0.0, addr: 172.21.2.2, rtt_idx:0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:[JSF]Normal interest check. regd plugins 31, enabled impl mask 0x0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:+++++++++++jsf_test_plugin_data_evh: 3 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:[JSF]Plugins(0x0, count 0) enabled for session = 4294979042, impli mask(0x0), post_nat cnt 0 svc req(0x56fbf028) Apr 14 18:37:05 18:37:05.172649:CID-0:RT:-jsf : no plugin interested for session 4294979042, free sess plugin info Apr 14 18:37:05 18:37:05.172649:CID-0:RT:[JSF]Releasing plugin info blocks Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_service_lookup(): natp(0x5554c948): app_id, 0(0). Apr 14 18:37:05 18:37:05.172649:CID-0:RT: service lookup identified service 0. Apr 14 18:37:05 18:37:05.172649:CID-0:RT: flow_first_final_check: in , out Apr 14 18:37:05 18:37:05.172649:CID-0:RT:In flow_first_complete_session Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_first_complete_session, pak_ptr: 0x50e24ec0, nsp: 0x5554c948, in_tunnel: 0x5540e238 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:construct v4 vector for nsp2 and nsp Apr 14 18:37:05 18:37:05.172649:CID-0:RT: existing vector list 0x204-0x4b10ecd0. Apr 14 18:37:05 18:37:05.172649:CID-0:RT: existing vector list 0x204-0x4b10ecd0. Apr 14 18:37:05 18:37:05.172649:CID-0:RT: Session (id:11746) created for first pak 204 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:first pak processing successful Apr 14 18:37:05 18:37:05.172649:CID-0:RT: flow_first_install_session======> 0x5554c948 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: nsp 0x5554c948, nsp2 0x5554c9d8 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: make_nsp_ready_no_resolve() Apr 14 18:37:05 18:37:05.172649:CID-0:RT: reverse route is optional Apr 14 18:37:05 18:37:05.172649:CID-0:RT:nsp_set_pmtu: tunnel_nsp out_ifp ge-0/0/0.0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: tunnel pmtu is already calculated, tunneloperating pmtu 1430 nsp ifp(ge-0/0/0.0) pmtu 1500 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:get NULL sess plugin info 0x5554c948 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:avt_get_app_name(): Getting appid failed. Apr 14 18:37:05 18:37:05.172649:CID-0:RT:get NULL sess plugin info 0x5554c948 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:no need update ha Apr 14 18:37:05 18:37:05.172649:CID-0:RT:Installing s2c NP session wing Apr 14 18:37:05 18:37:05.172649:CID-0:RT:updating pending sess (11746) in ager Apr 14 18:37:05 18:37:05.172649:CID-0:RT:first path session installation succeeded Apr 14 18:37:05 18:37:05.172649:CID-0:RT: flow got session. Apr 14 18:37:05 18:37:05.172649:CID-0:RT: flow session id 11746 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: vector bits 0x204 vector 0x4b10ecd0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:skip pre-frag: is_tunnel_if- 0, is_if_mtu_configured- 0 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: encap vector Apr 14 18:37:05 18:37:05.172649:CID-0:RT: no more encapping needed Apr 14 18:37:05 18:37:05.172649:CID-0:RT:mbuf 0x43e58680, exit nh 0x130010 Apr 14 18:37:05 18:37:05.172649:CID-0:RT:flow_process_pkt_exception: Freeing lpak 0x50e24ec0 associated with mbuf 0x43e58680 Apr 14 18:37:05 18:37:05.172649:CID-0:RT: ----- flow_process_pkt rc 0x0 (fp rc 0) Apr 14 18:37:10 18:37:10.197511:CID-0:RT:<45.27.139.181/158->172.21.2.2/1;1,0x0> matched filter filter3: Apr 14 18:37:15 18:37:10.197511:CID-0:RT:packet [60] ipid = 28389, @0x43e8dac8 Apr 14 18:37:15 18:37:10.197511:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 1, common flag 0x0, mbuf 0x43e8d880, rtbl_idx = 0 Apr 14 18:37:15 18:37:10.197511:CID-0:RT:flow process pak, mbuf 0x43e8d880, ifl 0, ctxt_type 1 inq type 6 Apr 14 18:37:15 18:37:10.197511:CID-0:RT: in_ifp Apr 14 18:37:15 18:37:10.197511:CID-0:RT:flow_process_pkt_exception: setting rtt in lpak to 0x5e4ea960 Apr 14 18:37:15 18:37:10.197511:CID-0:RT:host inq check inq_type 0x6 Apr 14 18:37:15 18:37:10.197511:CID-0:RT:tifp NULL Apr 14 18:37:15 18:37:10.197511:CID-0:RT:pkt out of tunnel.Proceed normally Apr 14 18:37:15 18:37:10.197511:CID-0:RT: ge-0/0/0.0:45.27.139.181->172.21.2.2, icmp, (8/0) Apr 14 18:37:15 18:37:10.197511:CID-0:RT: find flow: table 0x52fa14b0, hash 17023(0xffff), sa 45.27.139.181, da 172.21.2.2, sp 158, dp 1, proto 1, tok 6, conn-tag 0x00000000 Apr 14 18:37:15 18:37:10.197511:CID-0:RT: no session found, start first path. in_tunnel - 0x5540e238, from_cp_flag - 0 Apr 14 18:37:15 18:37:10.197511:CID-0:RT: flow_first_create_session Apr 14 18:37:15 18:37:10.197511:CID-0:RT:Save init hash spu id 0 to nsp and nsp2! Apr 14 18:37:15 18:37:10.197511:CID-0:RT:Installing pending sess (11753) in ager Apr 14 18:37:15 18:37:10.197511:CID-0:RT:First path alloc and instl pending session, natp=0x5554d6d8, id=11753 Apr 14 18:37:15 18:37:10.197511:CID-0:RT:First path alloc and instl pending session, natp=0x5554d6d8, id=11753