root@SRX3400-DC> show log flow_debug Apr 10 11:28:00 11:26:16.993466:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Doing DESTINATION addr route-lookup Apr 10 11:28:00 11:26:16.993491:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: routed (x_dst_ip 10.100.10.17) from junos-host (.local..0 in 0) to ae0.10, Next-hop: 10.100.10.17 Apr 10 11:28:00 11:26:16.993528:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_policy_search: policy search from zone junos-host-> zone MGMT (0x0,0x3d1419,0x1419) Apr 10 11:28:00 11:26:16.993550:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Policy lkup: vsys 0 zone(2:junos-host) -> zone(6:MGMT) scope:0 Apr 10 11:28:00 11:26:16.993564:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: 10.100.10.20/2048 -> 10.100.10.17/12635 proto 1 Apr 10 11:28:00 11:26:16.993603:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: app 0, timeout 60s, curr ageout 60s Apr 10 11:28:00 11:26:16.993614:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: permitted by policy self-traffic-policy(1) Apr 10 11:28:00 11:26:16.993625:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: packet passed, Permitted by policy. Apr 10 11:28:00 11:26:16.993636:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_src_xlate: nat_src_xlated: False, nat_src_xlate_failed: False Apr 10 11:28:00 11:26:16.993651:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False. Apr 10 11:28:01 11:26:16.993668:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: dip id = 0/0, 10.100.10.20/61->10.100.10.20/61 protocol 0 Apr 10 11:28:01 11:26:16.993701:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: choose interface ae0.10 as outgoing phy if Apr 10 11:28:01 11:26:16.993714:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:is_loop_pak: No loop: on ifp: ae0.10, addr: 10.100.10.17, rtt_idx:0 Apr 10 11:28:01 11:26:16.993741:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf : Alloc sess plugin info for session 224 Apr 10 11:28:01 11:26:16.993751:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:[JSF]Normal interest check. regd plugins 21, enabled impl mask 0x0 Apr 10 11:28:01 11:26:16.993771:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 2, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993786:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 3, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993805:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 5, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993821:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 6, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993838:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 7, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993854:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 8, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993869:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 10, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993884:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 12, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993900:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 13, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993913:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 14, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993932:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 15, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993948:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 16, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993961:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:+++++++++++jsf_test_plugin_data_evh: 3 Apr 10 11:28:01 11:26:16.993971:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 17, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.993986:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 25, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.994001:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 26, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:01 11:26:16.994014:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 27, svc_req 0x0, impl mask 0x0. rc 2 Apr 10 11:28:01 11:26:16.994027:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:[JSF]Plugins(0x0, count 0) enabled for session = 224, impli mask(0x0), post_nat cnt 0 svc req(0x0) Apr 10 11:28:01 11:26:16.994045:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf : no plugin interested for session 224, free sess plugin info Apr 10 11:28:01 11:26:16.994059:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_service_lookup(): natp(0x6836e528): app_id, 0(0). Apr 10 11:28:01 11:26:16.994072:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: service lookup identified service 0. Apr 10 11:28:01 11:26:16.994084:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow_first_final_check: in <.local..0>, out Apr 10 11:28:01 11:26:16.994101:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_complete_session, pak_ptr: 0xde3f17c0, nsp: 0x6836e528, in_tunnel: 0x0 Apr 10 11:28:01 11:26:16.994118:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:construct v4 vector for nsp2 Apr 10 11:28:01 11:26:16.994125:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: existing vector list 0x200-0x32649c00. Apr 10 11:28:01 11:26:16.994136:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: Session (id:224) created for first pak 200 Apr 10 11:28:01 11:26:16.994147:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow_first_install_session======> 0x6836e528 Apr 10 11:28:01 11:26:16.994158:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: nsp 0x6836e528, nsp2 0x6836e5d0 Apr 10 11:28:01 11:26:16.994170:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: make_nsp_ready_no_resolve() Apr 10 11:28:01 11:26:16.994194:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: route lookup: dest-ip 10.100.10.20 orig ifp .local..0 output_ifp .local..0 orig-zone 2 out-zone 2 vsd 0 Apr 10 11:28:01 11:26:16.994224:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: route to 10.100.10.20 Apr 10 11:28:01 11:26:16.994247:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_save_lpak_info_to_mbuf_common: setting flow_ctxt->iif to:0 based on keybuf iif. Apr 10 11:28:01 11:26:16.994280:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:SPU send install sess to CP cp_sess_id=00000151, spu_sess_id=000000e0, natp=0x6836e528 Apr 10 11:28:01 11:26:16.994304:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow found or created a pending session. Apr 10 11:28:01 11:26:16.994314:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_process_pkt_exception: Freeing lpak 0xde3f17c0 associated with mbuf 0x26777000 Apr 10 11:28:01 11:26:16.994330:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: ----- flow_process_pkt rc 0x11 (fp rc 0) Apr 10 11:28:01 11:26:16.994508:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:SPU received an event,type 112, common:0 Apr 10 11:28:01 11:26:16.994522:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:01 11:26:16.994531:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:SPU processing spu_flushed_pak, flag: 0x2, mbuf:0x0x26777000 Apr 10 11:28:01 11:26:16.994564:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:<10.100.10.20/61->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:01 11:26:16.994597:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:packet [84] ipid = 34047, @0xfa120136 Apr 10 11:28:01 11:26:16.994608:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:---- flow_process_pkt: (thd 27): flow_ctxt type 21, common flag 0x800, mbuf 0x26777000, rtbl_idx = 0 Apr 10 11:28:01 11:26:16.994630:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT: in_ifp Apr 10 11:28:01 11:26:16.994643:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:setting rtt to:0xa7ad15c8 based on VR ID:0 carried over in flow ctxt, proto 2(ipv4) Apr 10 11:28:01 11:26:16.994658:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:flow_process_pkt_exception: setting in_ifp to:.local..0 based on VR ID:0 Apr 10 11:28:01 11:26:16.994671:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:flow_process_pkt_exception: setting rtt in lpak to 0xa7ad15c8 Apr 10 11:28:01 11:26:16.994688:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT: flow session id 224 Apr 10 11:28:01 11:26:16.994699:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT: vector bits 0x200 vector 0x32649c00 Apr 10 11:28:01 11:26:16.994714:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:mbuf 0x26777000, exit nh 0x8468302 Apr 10 11:28:01 11:26:16.994724:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT:flow_process_pkt_exception: Freeing lpak 0xdd3e97d0 associated with mbuf 0x26777000 Apr 10 11:28:01 11:26:16.994740:CID-00:FPC-05:PIC-00:THREAD_ID-27:RT: ----- flow_process_pkt rc 0x0 (fp rc 0) Apr 10 11:28:01 11:26:16.994389:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:SPU received an event,type 97, common:0 Apr 10 11:28:01 11:26:16.994401:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:01 11:26:16.994411:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:SPU processing install_flow_ack, spu_sess_id=000000e0, natp=0x6836e528 Apr 10 11:28:01 11:26:16.994434:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:no need update ha Apr 10 11:28:01 11:26:16.994441:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:Installing c2s NP session wing Apr 10 11:28:01 11:26:16.994451:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:Installing s2c NP session wing Apr 10 11:28:01 11:26:16.994465:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:SPU flow flush 1 paks for natp (0x6836e528), lock:1 Apr 10 11:28:01 11:26:16.994481:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:01 11:26:16.994491:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:SPU flush pkt Apr 10 11:28:01 11:26:16.994502:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:Got CP ack for session 224. P->V success Apr 10 11:28:01 11:26:15.931823:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP received install sess event, sess id 337 Apr 10 11:28:01 11:26:15.931834:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP process msg SESS_MSG_INSTALL_FLOW Apr 10 11:28:01 11:26:15.931842:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP install sess, cp_sess_id=337, spu_sess_id=224 Apr 10 11:28:01 11:26:15.931856:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP flow search session, hash=1508085772 Apr 10 11:28:01 11:26:15.931871:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP ack session install to SPU 5, spu_sess_id=224 Apr 10 11:28:01 11:26:15.932583:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:<10.100.10.17/5145->10.100.10.20/61;1> matched filter MatchTraffic: Apr 10 11:28:01 11:26:15.932619:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:packet [84] ipid = 22945, @0xfa1db8f6 Apr 10 11:28:01 11:26:15.932629:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP flow starts, mbuf=0x26780600, ifl_idx=67, ctxt_type=0xf Apr 10 11:28:01 11:26:15.932644:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT: cp_flow_fast_lookup Apr 10 11:28:01 11:26:15.932653:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP flow search session, hash=1508085772 Apr 10 11:28:01 11:26:15.932665:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP found session 337, flag=0x2001 Apr 10 11:28:01 11:26:15.932675:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:01 11:26:15.932690:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP fwd pkt to SPU ==*5*==, iif: 73, flag: 0x00000000 Apr 10 11:28:01 11:26:15.930229:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:<10.100.10.20/61->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:01 11:26:15.930267:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:packet [84] ipid = 34047, @0xf6081cd4 Apr 10 11:28:01 11:26:15.930278:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:CP flow starts, mbuf=0x26d8fe00, ifl_idx=0, ctxt_type=0x0 Apr 10 11:28:01 11:26:15.930295:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:CP recvd host pkt. src ip 10.100.10.20, dest ip 10.100.10.17, proto 1 Apr 10 11:28:01 11:26:15.930332:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:Using vr id from pfe_tag with value= 0 Apr 10 11:28:01 11:26:15.930341:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:Changing lpak->in_ifp from:.local..0 -> to:.local..0 Apr 10 11:28:01 11:26:15.930352:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:Over-riding lpak->vsys with 0 Apr 10 11:28:01 11:26:15.930361:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT: cp_flow_fast_lookup Apr 10 11:28:01 11:26:15.930371:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:CP flow search session, hash=-1359069337 Apr 10 11:28:01 11:26:15.930384:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT: cp_flow_first_sanity_check: in <.local..0>, out Apr 10 11:28:01 11:26:15.930398:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT: cp_flow_first_create_session Apr 10 11:28:01 11:26:15.930408:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:CP flow search session, hash=-1359069337 Apr 10 11:28:01 11:26:15.930421:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:CP allocates a CP session, id 337 Apr 10 11:28:01 11:26:15.930431:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:CP couldn't find session, creates a pending session 151, 00000151 Apr 10 11:28:01 11:26:15.930458:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:01 11:26:15.930467:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:cp2spu fwd, cp sess id 337 (00000151), id bits 27, gen bits 5, id mask 07ffffff, gen mask f8000000 Apr 10 11:28:01 11:26:15.930489:CID-00:FPC-03:PIC-00:THREAD_ID-28:RT:CP fwd pkt to SPU ==*5*==, iif: 0, flag: 0x00000000 Apr 10 11:28:01 11:26:17.169618:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:SPU sent del-sess to CP for cp_sess 00000117, spu_sess 000000b9 Apr 10 11:28:01 11:26:17.169636:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:jsf sess close notify Apr 10 11:28:01 11:26:17.169645:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:flow_ipv4_del_flow: sess 185, in hash 32 Apr 10 11:28:01 11:26:17.169657:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:flow_ipv4_del_flow: sess 185, in hash 32 Apr 10 11:28:01 11:26:17.169696:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:SPU received an event,type 99, common:0 Apr 10 11:28:01 11:26:17.169707:CID-00:FPC-05:PIC-00:THREAD_ID-31:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:01 11:26:16.107135:CID-00:FPC-03:PIC-00:THREAD_ID-08:RT:CP received delete sess event, sess id 279 Apr 10 11:28:01 11:26:16.107145:CID-00:FPC-03:PIC-00:THREAD_ID-08:RT:CP process msg SESS_MSG_DELETE_FLOW Apr 10 11:28:01 11:26:16.107160:CID-00:FPC-03:PIC-00:THREAD_ID-08:RT:set_cp_session_invalid_with_reason--CP Session:279 state 3 Apr 10 11:28:01 11:26:16.107179:CID-00:FPC-03:PIC-00:THREAD_ID-08:RT:CP ack session invalidate to SPU, spu_sess_id=185, spu_id=5 Apr 10 11:28:01 11:26:16.689369:CID-00:FPC-03:PIC-00:THREAD_ID-15:RT:CP received delete sess event, sess id 278 Apr 10 11:28:01 11:26:16.689380:CID-00:FPC-03:PIC-00:THREAD_ID-15:RT:CP process msg SESS_MSG_DELETE_FLOW Apr 10 11:28:01 11:26:16.689394:CID-00:FPC-03:PIC-00:THREAD_ID-15:RT:set_cp_session_invalid_with_reason--CP Session:278 state 3 Apr 10 11:28:01 11:26:16.689411:CID-00:FPC-03:PIC-00:THREAD_ID-15:RT:CP ack session invalidate to SPU, spu_sess_id=92, spu_id=3 Apr 10 11:28:01 11:26:16.689362:CID-00:FPC-03:PIC-00:THREAD_ID-18:RT:SPU sent del-sess to CP for cp_sess 00000116, spu_sess 0000005c Apr 10 11:28:01 11:26:16.689386:CID-00:FPC-03:PIC-00:THREAD_ID-18:RT:jsf sess close notify Apr 10 11:28:01 11:26:16.689394:CID-00:FPC-03:PIC-00:THREAD_ID-18:RT:flow_ipv4_del_flow: sess 92, in hash 32 Apr 10 11:28:01 11:26:16.689407:CID-00:FPC-03:PIC-00:THREAD_ID-18:RT:flow_ipv4_del_flow: sess 92, in hash 32 Apr 10 11:28:01 11:26:16.689438:CID-00:FPC-03:PIC-00:THREAD_ID-23:RT:SPU received an event,type 99, common:0 Apr 10 11:28:01 11:26:16.689450:CID-00:FPC-03:PIC-00:THREAD_ID-23:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.933742:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:<10.100.10.17/5145->10.100.10.20/62;1> matched filter MatchTraffic: Apr 10 11:28:02 11:26:16.933777:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:packet [84] ipid = 23446, @0xfa1ed0f6 Apr 10 11:28:02 11:26:16.933788:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP flow starts, mbuf=0x26781400, ifl_idx=67, ctxt_type=0xf Apr 10 11:28:02 11:26:16.933803:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT: cp_flow_fast_lookup Apr 10 11:28:02 11:26:16.933811:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP flow search session, hash=1508085773 Apr 10 11:28:02 11:26:16.933823:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP found session 338, flag=0x2001 Apr 10 11:28:02 11:26:16.933834:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.933845:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP fwd pkt to SPU ==*3*==, iif: 73, flag: 0x00000000 Apr 10 11:28:02 11:26:16.932903:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP received install sess event, sess id 338 Apr 10 11:28:02 11:26:16.932913:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP process msg SESS_MSG_INSTALL_FLOW Apr 10 11:28:02 11:26:16.932921:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP install sess, cp_sess_id=338, spu_sess_id=112 Apr 10 11:28:02 11:26:16.932937:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP flow search session, hash=1508085773 Apr 10 11:28:02 11:26:16.932951:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP ack session install to SPU 3, spu_sess_id=112 Apr 10 11:28:02 11:26:16.931258:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:<10.100.10.20/62->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:02 11:26:16.931295:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:packet [84] ipid = 34050, @0xf60820d4 Apr 10 11:28:02 11:26:16.931306:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:CP flow starts, mbuf=0x26d90000, ifl_idx=0, ctxt_type=0x0 Apr 10 11:28:02 11:26:16.931323:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:CP recvd host pkt. src ip 10.100.10.20, dest ip 10.100.10.17, proto 1 Apr 10 11:28:02 11:26:16.931359:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:Using vr id from pfe_tag with value= 0 Apr 10 11:28:02 11:26:16.931368:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:Changing lpak->in_ifp from:.local..0 -> to:.local..0 Apr 10 11:28:02 11:26:16.931379:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:Over-riding lpak->vsys with 0 Apr 10 11:28:02 11:26:16.931388:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT: cp_flow_fast_lookup Apr 10 11:28:02 11:26:16.931398:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:CP flow search session, hash=-1359045545 Apr 10 11:28:02 11:26:16.931411:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT: cp_flow_first_sanity_check: in <.local..0>, out Apr 10 11:28:02 11:26:16.931428:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT: cp_flow_first_create_session Apr 10 11:28:02 11:26:16.931438:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:CP flow search session, hash=-1359045545 Apr 10 11:28:02 11:26:16.931450:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:CP allocates a CP session, id 338 Apr 10 11:28:02 11:26:16.931460:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:CP couldn't find session, creates a pending session 152, 00000152 Apr 10 11:28:02 11:26:16.931485:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.931494:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:cp2spu fwd, cp sess id 338 (00000152), id bits 27, gen bits 5, id mask 07ffffff, gen mask f8000000 Apr 10 11:28:02 11:26:16.931516:CID-00:FPC-03:PIC-00:THREAD_ID-16:RT:CP fwd pkt to SPU ==*3*==, iif: 0, flag: 0x00000000 Apr 10 11:28:02 11:26:16.931551:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:SPU received an event,type 80, common:0 Apr 10 11:28:02 11:26:16.931562:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.931572:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:SPU received pak with event message from CP, source spu: 0cp_sess_id=338 flag 12a Apr 10 11:28:02 11:26:16.931617:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:<10.100.10.20/62->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:02 11:26:16.931653:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:packet [84] ipid = 34050, @0xfa1e5936 Apr 10 11:28:02 11:26:16.931665:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:---- flow_process_pkt: (thd 20): flow_ctxt type 19, common flag 0x0, mbuf 0x26780e00, rtbl_idx = 0 Apr 10 11:28:02 11:26:16.931689:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: in_ifp Apr 10 11:28:02 11:26:16.931701:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_process_pkt_exception: setting rtt in lpak to 0x9cc7fa48 Apr 10 11:28:02 11:26:16.931722:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:Using vr id from pfe_tag with value= 0 Apr 10 11:28:02 11:26:16.931730:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:Changing lpak->in_ifp from:.local..0 -> to:.local..0 Apr 10 11:28:02 11:26:16.931741:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:Over-riding lpak->vsys with 0 Apr 10 11:28:02 11:26:16.931753:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_process_pkt_exception: local_flag: 0x00000100 Apr 10 11:28:02 11:26:16.931773:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: find flow: table 0x4f218230, hash 433239(0x7ffff), sa 10.100.10.20, da 10.100.10.17, sp 62, dp 5145, proto 1, tok 2 Apr 10 11:28:02 11:26:16.931817:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: no session found, start first path. in_tunnel - 0x0, from_cp_flag - 2048 Apr 10 11:28:02 11:26:16.931838:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: flow_first_create_session Apr 10 11:28:02 11:26:16.931854:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:(flow_first_create_session) usp_tagged set session as mng session Apr 10 11:28:02 11:26:16.931874:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: flow_first_in_dst_nat: in <.local..0>, out dst_adr 10.100.10.17, sp 62, dp 5145 Apr 10 11:28:02 11:26:16.931899:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: chose interface .local..0 as incoming nat if. Apr 10 11:28:02 11:26:16.931912:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_first_rule_dst_xlate: packet 10.100.10.20->10.100.10.17 nsp2 0.0.0.0->10.100.10.17. Apr 10 11:28:02 11:26:16.931962:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_first_routing: vr_id 0, call flow_route_lookup(): src_ip 10.100.10.20, x_dst_ip 10.100.10.17, in ifp .local..0, out ifp N/A sp 62, dp 5145, ip_proto 1, tos 0 Apr 10 11:28:02 11:26:16.932006:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:Doing DESTINATION addr route-lookup Apr 10 11:28:02 11:26:16.932036:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: routed (x_dst_ip 10.100.10.17) from junos-host (.local..0 in 0) to ae0.10, Next-hop: 10.100.10.17 Apr 10 11:28:02 11:26:16.932073:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_first_policy_search: policy search from zone junos-host-> zone MGMT (0x0,0x3e1419,0x1419) Apr 10 11:28:02 11:26:16.932098:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:Policy lkup: vsys 0 zone(2:junos-host) -> zone(6:MGMT) scope:0 Apr 10 11:28:02 11:26:16.932113:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: 10.100.10.20/2048 -> 10.100.10.17/11634 proto 1 Apr 10 11:28:02 11:26:16.932151:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: app 0, timeout 60s, curr ageout 60s Apr 10 11:28:02 11:26:16.932162:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: permitted by policy self-traffic-policy(1) Apr 10 11:28:02 11:26:16.932173:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: packet passed, Permitted by policy. Apr 10 11:28:02 11:26:16.932187:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_first_src_xlate: nat_src_xlated: False, nat_src_xlate_failed: False Apr 10 11:28:02 11:26:16.932203:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False. Apr 10 11:28:02 11:26:16.932222:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: dip id = 0/0, 10.100.10.20/62->10.100.10.20/62 protocol 0 Apr 10 11:28:02 11:26:16.932257:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: choose interface ae0.10 as outgoing phy if Apr 10 11:28:02 11:26:16.932273:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:is_loop_pak: No loop: on ifp: ae0.10, addr: 10.100.10.17, rtt_idx:0 Apr 10 11:28:02 11:26:16.932301:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf : Alloc sess plugin info for session 112 Apr 10 11:28:02 11:26:16.932312:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:[JSF]Normal interest check. regd plugins 21, enabled impl mask 0x0 Apr 10 11:28:02 11:26:16.932333:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 2, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932349:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 3, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932371:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 5, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932388:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 6, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932405:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 7, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932422:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 8, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932438:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 10, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932453:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 12, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932469:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 13, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932484:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 14, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932503:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 15, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932521:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 16, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932535:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:+++++++++++jsf_test_plugin_data_evh: 3 Apr 10 11:28:02 11:26:16.932546:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 17, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932563:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 25, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932577:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 26, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:16.932591:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf int check: plugin id 27, svc_req 0x0, impl mask 0x0. rc 2 Apr 10 11:28:02 11:26:16.932604:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:[JSF]Plugins(0x0, count 0) enabled for session = 112, impli mask(0x0), post_nat cnt 0 svc req(0x0) Apr 10 11:28:02 11:26:16.932623:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:-jsf : no plugin interested for session 112, free sess plugin info Apr 10 11:28:02 11:26:16.932637:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_first_service_lookup(): natp(0x65fed710): app_id, 0(0). Apr 10 11:28:02 11:26:16.932651:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: service lookup identified service 0. Apr 10 11:28:02 11:26:16.932660:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: flow_first_final_check: in <.local..0>, out Apr 10 11:28:02 11:26:16.932680:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_first_complete_session, pak_ptr: 0xde1f07c0, nsp: 0x65fed710, in_tunnel: 0x0 Apr 10 11:28:02 11:26:16.932697:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:construct v4 vector for nsp2 Apr 10 11:28:02 11:26:16.932705:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: existing vector list 0x200-0x31e44700. Apr 10 11:28:02 11:26:16.932720:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: Session (id:112) created for first pak 200 Apr 10 11:28:02 11:26:16.932732:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: flow_first_install_session======> 0x65fed710 Apr 10 11:28:02 11:26:16.932743:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: nsp 0x65fed710, nsp2 0x65fed7b8 Apr 10 11:28:02 11:26:16.932755:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: make_nsp_ready_no_resolve() Apr 10 11:28:02 11:26:16.932780:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: route lookup: dest-ip 10.100.10.20 orig ifp .local..0 output_ifp .local..0 orig-zone 2 out-zone 2 vsd 0 Apr 10 11:28:02 11:26:16.932811:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: route to 10.100.10.20 Apr 10 11:28:02 11:26:16.932836:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_save_lpak_info_to_mbuf_common: setting flow_ctxt->iif to:0 based on keybuf iif. Apr 10 11:28:02 11:26:16.932870:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:SPU send install sess to CP cp_sess_id=00000152, spu_sess_id=00000070, natp=0x65fed710 Apr 10 11:28:02 11:26:16.932893:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: flow found or created a pending session. Apr 10 11:28:02 11:26:16.932905:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT:flow_process_pkt_exception: Freeing lpak 0xde1f07c0 associated with mbuf 0x26780e00 Apr 10 11:28:02 11:26:16.932921:CID-00:FPC-03:PIC-00:THREAD_ID-20:RT: ----- flow_process_pkt rc 0x11 (fp rc 0) Apr 10 11:28:02 11:26:16.933881:CID-00:FPC-03:PIC-00:THREAD_ID-25:RT:SPU received an event,type 81, common:0 Apr 10 11:28:02 11:26:16.933893:CID-00:FPC-03:PIC-00:THREAD_ID-25:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.933902:CID-00:FPC-03:PIC-00:THREAD_ID-25:RT:SPU received pak with event message from CP, source spu: 0cp_sess_id=338 flag c Apr 10 11:28:02 11:26:16.932977:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:SPU received an event,type 97, common:0 Apr 10 11:28:02 11:26:16.932990:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.932999:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:SPU processing install_flow_ack, spu_sess_id=00000070, natp=0x65fed710 Apr 10 11:28:02 11:26:16.933021:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:no need update ha Apr 10 11:28:02 11:26:16.933028:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:Installing c2s NP session wing Apr 10 11:28:02 11:26:16.933038:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:Installing s2c NP session wing Apr 10 11:28:02 11:26:16.933054:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:SPU flow flush 1 paks for natp (0x65fed710), lock:1 Apr 10 11:28:02 11:26:16.933070:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.933080:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:SPU flush pkt Apr 10 11:28:02 11:26:16.933094:CID-00:FPC-03:PIC-00:THREAD_ID-26:RT:Got CP ack for session 112. P->V success Apr 10 11:28:02 11:26:16.933099:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:SPU received an event,type 112, common:0 Apr 10 11:28:02 11:26:16.933112:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:16.933121:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:SPU processing spu_flushed_pak, flag: 0x2, mbuf:0x0x26780e00 Apr 10 11:28:02 11:26:16.933156:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:<10.100.10.20/62->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:02 11:26:16.933190:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:packet [84] ipid = 34050, @0xfa1e5936 Apr 10 11:28:02 11:26:16.933201:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:---- flow_process_pkt: (thd 30): flow_ctxt type 21, common flag 0x800, mbuf 0x26780e00, rtbl_idx = 0 Apr 10 11:28:02 11:26:16.933224:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT: in_ifp Apr 10 11:28:02 11:26:16.933238:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:setting rtt to:0x9cc7fa48 based on VR ID:0 carried over in flow ctxt, proto 2(ipv4) Apr 10 11:28:02 11:26:16.933254:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:flow_process_pkt_exception: setting in_ifp to:.local..0 based on VR ID:0 Apr 10 11:28:02 11:26:16.933267:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:flow_process_pkt_exception: setting rtt in lpak to 0x9cc7fa48 Apr 10 11:28:02 11:26:16.933285:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT: flow session id 112 Apr 10 11:28:02 11:26:16.933299:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT: vector bits 0x200 vector 0x31e44700 Apr 10 11:28:02 11:26:16.933316:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:mbuf 0x26780e00, exit nh 0x846a302 Apr 10 11:28:02 11:26:16.933327:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT:flow_process_pkt_exception: Freeing lpak 0xdcde67d0 associated with mbuf 0x26780e00 Apr 10 11:28:02 11:26:16.933344:CID-00:FPC-03:PIC-00:THREAD_ID-30:RT: ----- flow_process_pkt rc 0x0 (fp rc 0) Apr 10 11:28:02 11:26:18.996575:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:SPU received an event,type 97, common:0 Apr 10 11:28:02 11:26:18.996588:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:18.996597:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:SPU processing install_flow_ack, spu_sess_id=000000e1, natp=0x6836e7a8 Apr 10 11:28:02 11:26:18.996619:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:no need update ha Apr 10 11:28:02 11:26:18.996626:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Installing c2s NP session wing Apr 10 11:28:02 11:26:18.996635:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Installing s2c NP session wing Apr 10 11:28:02 11:26:18.996651:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:SPU flow flush 1 paks for natp (0x6836e7a8), lock:1 Apr 10 11:28:02 11:26:18.996667:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:18.996676:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:SPU flush pkt Apr 10 11:28:02 11:26:18.996690:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Got CP ack for session 225. P->V success Apr 10 11:28:02 11:26:18.995147:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:SPU received an event,type 80, common:0 Apr 10 11:28:02 11:26:18.995161:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:02 11:26:18.995170:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:SPU received pak with event message from CP, source spu: 0cp_sess_id=339 flag 12a Apr 10 11:28:02 11:26:18.995221:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:<10.100.10.20/63->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:02 11:26:18.995255:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:packet [84] ipid = 34055, @0xfa12a136 Apr 10 11:28:02 11:26:18.995267:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:---- flow_process_pkt: (thd 19): flow_ctxt type 19, common flag 0x0, mbuf 0x26777800, rtbl_idx = 0 Apr 10 11:28:02 11:26:18.995291:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: in_ifp Apr 10 11:28:02 11:26:18.995302:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_process_pkt_exception: setting rtt in lpak to 0xa7ad15c8 Apr 10 11:28:02 11:26:18.995323:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Using vr id from pfe_tag with value= 0 Apr 10 11:28:02 11:26:18.995331:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Changing lpak->in_ifp from:.local..0 -> to:.local..0 Apr 10 11:28:02 11:26:18.995342:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Over-riding lpak->vsys with 0 Apr 10 11:28:02 11:26:18.995354:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_process_pkt_exception: local_flag: 0x00000100 Apr 10 11:28:02 11:26:18.995375:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: find flow: table 0x587f1ad8, hash 32071(0x7ffff), sa 10.100.10.20, da 10.100.10.17, sp 63, dp 5145, proto 1, tok 2 Apr 10 11:28:02 11:26:18.995418:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: no session found, start first path. in_tunnel - 0x0, from_cp_flag - 2048 Apr 10 11:28:02 11:26:18.995439:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow_first_create_session Apr 10 11:28:02 11:26:18.995464:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:(flow_first_create_session) usp_tagged set session as mng session Apr 10 11:28:02 11:26:18.995484:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow_first_in_dst_nat: in <.local..0>, out dst_adr 10.100.10.17, sp 63, dp 5145 Apr 10 11:28:02 11:26:18.995510:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: chose interface .local..0 as incoming nat if. Apr 10 11:28:02 11:26:18.995523:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_rule_dst_xlate: packet 10.100.10.20->10.100.10.17 nsp2 0.0.0.0->10.100.10.17. Apr 10 11:28:02 11:26:18.995573:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_routing: vr_id 0, call flow_route_lookup(): src_ip 10.100.10.20, x_dst_ip 10.100.10.17, in ifp .local..0, out ifp N/A sp 63, dp 5145, ip_proto 1, tos 0 Apr 10 11:28:02 11:26:18.995616:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Doing DESTINATION addr route-lookup Apr 10 11:28:02 11:26:18.995645:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: routed (x_dst_ip 10.100.10.17) from junos-host (.local..0 in 0) to ae0.10, Next-hop: 10.100.10.17 Apr 10 11:28:02 11:26:18.995682:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_policy_search: policy search from zone junos-host-> zone MGMT (0x0,0x3f1419,0x1419) Apr 10 11:28:02 11:26:18.995706:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:Policy lkup: vsys 0 zone(2:junos-host) -> zone(6:MGMT) scope:0 Apr 10 11:28:02 11:26:18.995720:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: 10.100.10.20/2048 -> 10.100.10.17/10635 proto 1 Apr 10 11:28:02 11:26:18.995758:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: app 0, timeout 60s, curr ageout 60s Apr 10 11:28:02 11:26:18.995769:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: permitted by policy self-traffic-policy(1) Apr 10 11:28:02 11:26:18.995780:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: packet passed, Permitted by policy. Apr 10 11:28:02 11:26:18.995793:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_src_xlate: nat_src_xlated: False, nat_src_xlate_failed: False Apr 10 11:28:02 11:26:18.995809:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False. Apr 10 11:28:02 11:26:18.995825:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: dip id = 0/0, 10.100.10.20/63->10.100.10.20/63 protocol 0 Apr 10 11:28:02 11:26:18.995858:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: choose interface ae0.10 as outgoing phy if Apr 10 11:28:02 11:26:18.995874:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:is_loop_pak: No loop: on ifp: ae0.10, addr: 10.100.10.17, rtt_idx:0 Apr 10 11:28:02 11:26:18.995902:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf : Alloc sess plugin info for session 225 Apr 10 11:28:02 11:26:18.995912:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:[JSF]Normal interest check. regd plugins 21, enabled impl mask 0x0 Apr 10 11:28:02 11:26:18.995933:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 2, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.995948:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 3, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.995973:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 5, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.995990:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 6, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996006:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 7, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996023:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 8, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996038:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 10, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996054:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 12, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996069:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 13, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996083:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 14, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996102:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 15, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996117:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 16, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996132:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:+++++++++++jsf_test_plugin_data_evh: 3 Apr 10 11:28:02 11:26:18.996143:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 17, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996158:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 25, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996173:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 26, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:02 11:26:18.996187:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf int check: plugin id 27, svc_req 0x0, impl mask 0x0. rc 2 Apr 10 11:28:02 11:26:18.996201:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:[JSF]Plugins(0x0, count 0) enabled for session = 225, impli mask(0x0), post_nat cnt 0 svc req(0x0) Apr 10 11:28:02 11:26:18.996218:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:-jsf : no plugin interested for session 225, free sess plugin info Apr 10 11:28:02 11:26:18.996232:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_service_lookup(): natp(0x6836e7a8): app_id, 0(0). Apr 10 11:28:02 11:26:18.996246:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: service lookup identified service 0. Apr 10 11:28:02 11:26:18.996256:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow_first_final_check: in <.local..0>, out Apr 10 11:28:02 11:26:18.996275:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_first_complete_session, pak_ptr: 0xde3f17c0, nsp: 0x6836e7a8, in_tunnel: 0x0 Apr 10 11:28:02 11:26:18.996292:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:construct v4 vector for nsp2 Apr 10 11:28:02 11:26:18.996300:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: existing vector list 0x200-0x32649c00. Apr 10 11:28:02 11:26:18.996312:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: Session (id:225) created for first pak 200 Apr 10 11:28:02 11:26:18.996324:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow_first_install_session======> 0x6836e7a8 Apr 10 11:28:02 11:26:18.996334:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: nsp 0x6836e7a8, nsp2 0x6836e850 Apr 10 11:28:02 11:26:18.996347:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: make_nsp_ready_no_resolve() Apr 10 11:28:02 11:26:18.996372:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: route lookup: dest-ip 10.100.10.20 orig ifp .local..0 output_ifp .local..0 orig-zone 2 out-zone 2 vsd 0 Apr 10 11:28:02 11:26:18.996402:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: route to 10.100.10.20 Apr 10 11:28:02 11:26:18.996426:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_save_lpak_info_to_mbuf_common: setting flow_ctxt->iif to:0 based on keybuf iif. Apr 10 11:28:02 11:26:18.996464:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:SPU send install sess to CP cp_sess_id=00000153, spu_sess_id=000000e1, natp=0x6836e7a8 Apr 10 11:28:03 11:26:18.996488:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: flow found or created a pending session. Apr 10 11:28:03 11:26:18.996499:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT:flow_process_pkt_exception: Freeing lpak 0xde3f17c0 associated with mbuf 0x26777800 Apr 10 11:28:03 11:26:18.996516:CID-00:FPC-05:PIC-00:THREAD_ID-19:RT: ----- flow_process_pkt rc 0x11 (fp rc 0) Apr 10 11:28:03 11:26:18.997472:CID-00:FPC-05:PIC-00:THREAD_ID-20:RT:SPU received an event,type 81, common:0 Apr 10 11:28:03 11:26:18.997485:CID-00:FPC-05:PIC-00:THREAD_ID-20:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:03 11:26:18.997494:CID-00:FPC-05:PIC-00:THREAD_ID-20:RT:SPU received pak with event message from CP, source spu: 0cp_sess_id=339 flag c Apr 10 11:28:03 11:26:18.996696:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:SPU received an event,type 112, common:0 Apr 10 11:28:03 11:26:18.996709:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:03 11:26:18.996718:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:SPU processing spu_flushed_pak, flag: 0x2, mbuf:0x0x26777800 Apr 10 11:28:03 11:26:18.996752:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:<10.100.10.20/63->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:03 11:26:18.996789:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:packet [84] ipid = 34055, @0xfa12a136 Apr 10 11:28:03 11:26:18.996800:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:---- flow_process_pkt: (thd 26): flow_ctxt type 21, common flag 0x800, mbuf 0x26777800, rtbl_idx = 0 Apr 10 11:28:03 11:26:18.996822:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT: in_ifp Apr 10 11:28:03 11:26:18.996835:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:setting rtt to:0xa7ad15c8 based on VR ID:0 carried over in flow ctxt, proto 2(ipv4) Apr 10 11:28:03 11:26:18.996851:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:flow_process_pkt_exception: setting in_ifp to:.local..0 based on VR ID:0 Apr 10 11:28:03 11:26:18.996865:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:flow_process_pkt_exception: setting rtt in lpak to 0xa7ad15c8 Apr 10 11:28:03 11:26:18.996882:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT: flow session id 225 Apr 10 11:28:03 11:26:18.996894:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT: vector bits 0x200 vector 0x32649c00 Apr 10 11:28:03 11:26:18.996910:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:mbuf 0x26777800, exit nh 0x8468302 Apr 10 11:28:03 11:26:18.996920:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT:flow_process_pkt_exception: Freeing lpak 0xdd5ea7d0 associated with mbuf 0x26777800 Apr 10 11:28:03 11:26:18.996936:CID-00:FPC-05:PIC-00:THREAD_ID-26:RT: ----- flow_process_pkt rc 0x0 (fp rc 0) Apr 10 11:28:03 11:26:17.933985:CID-00:FPC-03:PIC-00:THREAD_ID-09:RT:CP received install sess event, sess id 339 Apr 10 11:28:03 11:26:17.933997:CID-00:FPC-03:PIC-00:THREAD_ID-09:RT:CP process msg SESS_MSG_INSTALL_FLOW Apr 10 11:28:03 11:26:17.934005:CID-00:FPC-03:PIC-00:THREAD_ID-09:RT:CP install sess, cp_sess_id=339, spu_sess_id=225 Apr 10 11:28:03 11:26:17.934021:CID-00:FPC-03:PIC-00:THREAD_ID-09:RT:CP flow search session, hash=1508085770 Apr 10 11:28:03 11:26:17.934036:CID-00:FPC-03:PIC-00:THREAD_ID-09:RT:CP ack session install to SPU 5, spu_sess_id=225 Apr 10 11:28:03 11:26:17.934820:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:<10.100.10.17/5145->10.100.10.20/63;1> matched filter MatchTraffic: Apr 10 11:28:03 11:26:17.934854:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:packet [84] ipid = 24102, @0xfa1f48f6 Apr 10 11:28:03 11:26:17.934865:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP flow starts, mbuf=0x26781a00, ifl_idx=67, ctxt_type=0xf Apr 10 11:28:03 11:26:17.934880:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT: cp_flow_fast_lookup Apr 10 11:28:03 11:26:17.934888:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP flow search session, hash=1508085770 Apr 10 11:28:03 11:26:17.934900:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP found session 339, flag=0x2001 Apr 10 11:28:03 11:26:17.934911:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:03 11:26:17.934922:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP fwd pkt to SPU ==*5*==, iif: 73, flag: 0x00000000 Apr 10 11:28:03 11:26:17.932325:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:<10.100.10.20/63->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:03 11:26:17.932370:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:packet [84] ipid = 34055, @0xf60824d4 Apr 10 11:28:03 11:26:17.932380:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:CP flow starts, mbuf=0x26d90200, ifl_idx=0, ctxt_type=0x0 Apr 10 11:28:03 11:26:17.932399:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:CP recvd host pkt. src ip 10.100.10.20, dest ip 10.100.10.17, proto 1 Apr 10 11:28:03 11:26:17.932436:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:Using vr id from pfe_tag with value= 0 Apr 10 11:28:03 11:26:17.932446:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:Changing lpak->in_ifp from:.local..0 -> to:.local..0 Apr 10 11:28:03 11:26:17.932457:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:Over-riding lpak->vsys with 0 Apr 10 11:28:03 11:26:17.932466:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT: cp_flow_fast_lookup Apr 10 11:28:03 11:26:17.932476:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:CP flow search session, hash=-1359446713 Apr 10 11:28:03 11:26:17.932489:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT: cp_flow_first_sanity_check: in <.local..0>, out Apr 10 11:28:03 11:26:17.932503:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT: cp_flow_first_create_session Apr 10 11:28:03 11:26:17.932513:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:CP flow search session, hash=-1359446713 Apr 10 11:28:03 11:26:17.932526:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:CP allocates a CP session, id 339 Apr 10 11:28:03 11:26:17.932535:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:CP couldn't find session, creates a pending session 153, 00000153 Apr 10 11:28:03 11:26:17.932563:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:Fwd packet with rtbl idx 0, cos 0 Apr 10 11:28:03 11:26:17.932572:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:cp2spu fwd, cp sess id 339 (00000153), id bits 27, gen bits 5, id mask 07ffffff, gen mask f8000000 Apr 10 11:28:03 11:26:17.932594:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:CP fwd pkt to SPU ==*5*==, iif: 0, flag: 0x00000000 Apr 10 11:28:03 11:26:19.168996:CID-00:FPC-05:PIC-00:THREAD_ID-23:RT:SPU received an event,type 99, common:0 Apr 10 11:28:03 11:26:19.169007:CID-00:FPC-05:PIC-00:THREAD_ID-23:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:03 11:26:19.168916:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:SPU sent del-sess to CP for cp_sess 00000118, spu_sess 000000ba Apr 10 11:28:03 11:26:19.168936:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:jsf sess close notify Apr 10 11:28:03 11:26:19.168944:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:flow_ipv4_del_flow: sess 186, in hash 32 Apr 10 11:28:03 11:26:19.168955:CID-00:FPC-05:PIC-00:THREAD_ID-30:RT:flow_ipv4_del_flow: sess 186, in hash 32 Apr 10 11:28:03 11:26:18.106412:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP received delete sess event, sess id 280 Apr 10 11:28:03 11:26:18.106423:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP process msg SESS_MSG_DELETE_FLOW Apr 10 11:28:03 11:26:18.106438:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:set_cp_session_invalid_with_reason--CP Session:280 state 3 Apr 10 11:28:03 11:26:18.106456:CID-00:FPC-03:PIC-00:THREAD_ID-14:RT:CP ack session invalidate to SPU, spu_sess_id=186, spu_id=5 Apr 10 11:28:03 11:26:18.688683:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP received delete sess event, sess id 281 Apr 10 11:28:03 11:26:18.688694:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP process msg SESS_MSG_DELETE_FLOW Apr 10 11:28:03 11:26:18.688705:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:set_cp_session_invalid_with_reason--CP Session:281 state 3 Apr 10 11:28:03 11:26:18.688722:CID-00:FPC-03:PIC-00:THREAD_ID-13:RT:CP ack session invalidate to SPU, spu_sess_id=93, spu_id=3 Apr 10 11:28:03 11:26:18.688748:CID-00:FPC-03:PIC-00:THREAD_ID-17:RT:SPU received an event,type 99, common:0 Apr 10 11:28:03 11:26:18.688760:CID-00:FPC-03:PIC-00:THREAD_ID-17:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:03 11:26:18.688675:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:SPU sent del-sess to CP for cp_sess 00000119, spu_sess 0000005d Apr 10 11:28:03 11:26:18.688696:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:jsf sess close notify Apr 10 11:28:03 11:26:18.688704:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:flow_ipv4_del_flow: sess 93, in hash 32 Apr 10 11:28:03 11:26:18.688715:CID-00:FPC-03:PIC-00:THREAD_ID-24:RT:flow_ipv4_del_flow: sess 93, in hash 32 Apr 10 11:28:03 11:26:19.996098:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:SPU received an event,type 80, common:0 Apr 10 11:28:03 11:26:19.996112:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Rcv packet with rtbl idx 0, cos 0 Apr 10 11:28:03 11:26:19.996122:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:SPU received pak with event message from CP, source spu: 0cp_sess_id=340 flag 12a Apr 10 11:28:03 11:26:19.996172:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:<10.100.10.20/64->10.100.10.17/5145;1> matched filter MatchTraffic: Apr 10 11:28:03 11:26:19.996208:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:packet [84] ipid = 34056, @0xfa134136 Apr 10 11:28:03 11:26:19.996219:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:---- flow_process_pkt: (thd 11): flow_ctxt type 19, common flag 0x0, mbuf 0x26778000, rtbl_idx = 0 Apr 10 11:28:03 11:26:19.996243:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: in_ifp Apr 10 11:28:03 11:26:19.996254:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_process_pkt_exception: setting rtt in lpak to 0xa7ad15c8 Apr 10 11:28:03 11:26:19.996273:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Using vr id from pfe_tag with value= 0 Apr 10 11:28:03 11:26:19.996282:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Changing lpak->in_ifp from:.local..0 -> to:.local..0 Apr 10 11:28:03 11:26:19.996293:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Over-riding lpak->vsys with 0 Apr 10 11:28:03 11:26:19.996304:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_process_pkt_exception: local_flag: 0x00000100 Apr 10 11:28:03 11:26:19.996326:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: find flow: table 0x587f1ad8, hash 311351(0x7ffff), sa 10.100.10.20, da 10.100.10.17, sp 64, dp 5145, proto 1, tok 2 Apr 10 11:28:03 11:26:19.996371:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: no session found, start first path. in_tunnel - 0x0, from_cp_flag - 2048 Apr 10 11:28:03 11:26:19.996391:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: flow_first_create_session Apr 10 11:28:03 11:26:19.996407:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:(flow_first_create_session) usp_tagged set session as mng session Apr 10 11:28:03 11:26:19.996426:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: flow_first_in_dst_nat: in <.local..0>, out dst_adr 10.100.10.17, sp 64, dp 5145 Apr 10 11:28:03 11:26:19.996452:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: chose interface .local..0 as incoming nat if. Apr 10 11:28:03 11:26:19.996465:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_first_rule_dst_xlate: packet 10.100.10.20->10.100.10.17 nsp2 0.0.0.0->10.100.10.17. Apr 10 11:28:03 11:26:19.996516:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_first_routing: vr_id 0, call flow_route_lookup(): src_ip 10.100.10.20, x_dst_ip 10.100.10.17, in ifp .local..0, out ifp N/A sp 64, dp 5145, ip_proto 1, tos 0 Apr 10 11:28:03 11:26:19.996559:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Doing DESTINATION addr route-lookup Apr 10 11:28:03 11:26:19.996585:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: routed (x_dst_ip 10.100.10.17) from junos-host (.local..0 in 0) to ae0.10, Next-hop: 10.100.10.17 Apr 10 11:28:03 11:26:19.996627:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_first_policy_search: policy search from zone junos-host-> zone MGMT (0x0,0x401419,0x1419) Apr 10 11:28:03 11:26:19.996649:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:Policy lkup: vsys 0 zone(2:junos-host) -> zone(6:MGMT) scope:0 Apr 10 11:28:03 11:26:19.996663:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: 10.100.10.20/2048 -> 10.100.10.17/9628 proto 1 Apr 10 11:28:03 11:26:19.996700:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: app 0, timeout 60s, curr ageout 60s Apr 10 11:28:03 11:26:19.996712:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: permitted by policy self-traffic-policy(1) Apr 10 11:28:03 11:26:19.996722:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: packet passed, Permitted by policy. Apr 10 11:28:03 11:26:19.996735:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_first_src_xlate: nat_src_xlated: False, nat_src_xlate_failed: False Apr 10 11:28:03 11:26:19.996751:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False. Apr 10 11:28:03 11:26:19.996767:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: dip id = 0/0, 10.100.10.20/64->10.100.10.20/64 protocol 0 Apr 10 11:28:03 11:26:19.996801:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: choose interface ae0.10 as outgoing phy if Apr 10 11:28:03 11:26:19.996816:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:is_loop_pak: No loop: on ifp: ae0.10, addr: 10.100.10.17, rtt_idx:0 Apr 10 11:28:03 11:26:19.996843:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf : Alloc sess plugin info for session 226 Apr 10 11:28:03 11:26:19.996854:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:[JSF]Normal interest check. regd plugins 21, enabled impl mask 0x0 Apr 10 11:28:03 11:26:19.996873:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 2, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.996889:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 3, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.996910:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 5, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.996926:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 6, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.996942:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 7, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.996958:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 8, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.996973:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 10, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.996989:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 12, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997004:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 13, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997019:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 14, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997038:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 15, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997055:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 16, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997068:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:+++++++++++jsf_test_plugin_data_evh: 3 Apr 10 11:28:03 11:26:19.997078:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 17, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997093:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 25, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997111:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 26, svc_req 0x0, impl mask 0x0. rc 4 Apr 10 11:28:03 11:26:19.997126:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf int check: plugin id 27, svc_req 0x0, impl mask 0x0. rc 2 Apr 10 11:28:03 11:26:19.997139:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:[JSF]Plugins(0x0, count 0) enabled for session = 226, impli mask(0x0), post_nat cnt 0 svc req(0x0) Apr 10 11:28:03 11:26:19.997157:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:-jsf : no plugin interested for session 226, free sess plugin info Apr 10 11:28:03 11:26:19.997170:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_first_service_lookup(): natp(0x6836ea28): app_id, 0(0). Apr 10 11:28:03 11:26:19.997184:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: service lookup identified service 0. Apr 10 11:28:03 11:26:19.997193:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT: flow_first_final_check: in <.local..0>, out Apr 10 11:28:03 11:26:19.997211:CID-00:FPC-05:PIC-00:THREAD_ID-11:RT:flow_first_complete_sessioD_ID-11:RT: route to 10.100.10.20