when SLO rate is 0 or any other value greater than 1, we get session logs without logged bytes/pkts for sessions which are not logged earlier.
one sample of the problematic log(this log is not needed actually):
2018-01-23 Tue 15:32:58:142.503 IST nodec62 [Thread 140554875680512, Pid 31405]: [SYS_INFO]: SessionEndpointObject: session_data= [ [ [ vmi = default-domain:admin:2ade55df-4eb9-4d2d-80db-47b77f5b4aa6 vn = default-domain:admin:vn2-alok security_policy_rule = 00000000-0000-0000-0000-000000000001 remote_vn = default-domain:admin:vn1-alok is_client_session = 0 is_si = 0 vrouter_ip = 10.204.217.102 sess_agg_info= [ [ [ local_ip = 2.2.2.3 service_port = 10000 protocol = 17 ] [ logged_forward_bytes = 0 logged_forward_pkts = 0 logged_reverse_bytes = 0 logged_reverse_pkts = 0 sessionMap= [ [ [ ip = 1.1.1.4 port = 1180 ] [ forward_flow_info= [ flow_uuid = 71b24fb4-95e2-430c-8e2a-ac55ad55ac39 setup_time = 1516701775805768 action = pass sg_rule_uuid = 78df1ec8-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 ] reverse_flow_info= [ flow_uuid = 53ebb126-04ee-4f14-9a90-e51cb9834358 setup_time = 1516701775805768 action = pass sg_rule_uuid = 78e70dcc-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 ] vm = f2665eed-cc1f-4aab-b039-82ddf3281436 other_vrouter_ip = 10.204.217.102 underlay_proto = 0 ], ] ] ], ] ] ], ] ]
this happens for all the flows matching the SLO which were not logged earlier.
In current case, SLO policy rule specific rate is 3.(SLO rate was 100)
created 3 set of flows as below, destination ports were 10000, 10001, 10002.
root@nodec62:~# flow -l
Flow table(size 80609280, entries 629760)
Entries: Created 111 Added 111 Deleted 212 Changed 212 Processed 111 Used Overflow entries 0
(Created Flows/CPU: 41 29 6 35)(oflows 0)
Action:F=Forward, D=Drop N=NAT(S=SNAT, D=DNAT, Ps=SPAT, Pd=DPAT, L=Link Local Port)
Other:K(nh)=Key_Nexthop, S(nh)=RPF_Nexthop
Flags:E=Evicted, Ec=Evict Candidate, N=New Flow, M=Modified Dm=Delete Marked
TCP(r=reverse):S=SYN, F=FIN, R=RST, C=HalfClose, E=Established, D=Dead
Index Source:Port/Destination:Port Proto(V)
-----------------------------------------------------------------------------------
108416<=>284720 1.1.1.4:1180 17 (3)
2.2.2.3:10000
(Gen: 2, K(nh):26, Action:F, Flags:, QOS:-1, S(nh):26, Stats:1/42, SPort 63661,
TTL 0, Sinfo 4.0.0.0)
143912<=>430868 1.1.1.4:1181 17 (3)
2.2.2.3:10001
(Gen: 4, K(nh):26, Action:F, Flags:, QOS:-1, S(nh):26, Stats:1/42, SPort 51492,
TTL 0, Sinfo 4.0.0.0)
284720<=>108416 2.2.2.3:10000 17 (2)
1.1.1.4:1180
(Gen: 3, K(nh):30, Action:F, Flags:, QOS:-1, S(nh):30, Stats:1/70, SPort 64036,
TTL 0, Sinfo 5.0.0.0)
430868<=>143912 2.2.2.3:10001 17 (2)
1.1.1.4:1181
(Gen: 2, K(nh):30, Action:F, Flags:, QOS:-1, S(nh):30, Stats:1/70, SPort 50275,
TTL 0, Sinfo 5.0.0.0)
470048<=>508976 2.2.2.3:10002 17 (2)
1.1.1.4:1182
(Gen: 3, K(nh):30, Action:F, Flags:, QOS:-1, S(nh):30, Stats:1/70, SPort 56452,
TTL 0, Sinfo 5.0.0.0)
508976<=>470048 1.1.1.4:1182 17 (3)
2.2.2.3:10002
(Gen: 2, K(nh):26, Action:F, Flags:, QOS:-1, S(nh):26, Stats:1/42, SPort 63922,
TTL 0, Sinfo 4.0.0.0)
For this below sessions were logged in agent file:
root@nodec62:~# grep -a SessionEndpointObject /var/log/contrail/contrail-vrouter-agent.log
2018-01-23 Tue 15:32:56:142.682 IST nodec62 [Thread 140554879878912, Pid 31405]: [SYS_INFO]: SessionEndpointObject: session_data= [ [ [ vmi = default-domain:admin:2ade55df-4eb9-4d2d-80db-47b77f5b4aa6 vn = default-domain:admin:vn2-alok security_policy_rule = 00000000-0000-0000-0000-000000000001 remote_vn = default-domain:admin:vn1-alok is_client_session = 0 is_si = 0 vrouter_ip = 10.204.217.102 sess_agg_info= [ [ [ local_ip = 2.2.2.3 service_port = 10001 protocol = 17 ] [ logged_forward_bytes = 70 logged_forward_pkts = 1 logged_reverse_bytes = 42 logged_reverse_pkts = 1 sessionMap= [ [ [ ip = 1.1.1.4 port = 1181 ] [ forward_flow_info= [ logged_bytes = 70 logged_pkts = 1 flow_uuid = c2101df7-f0fb-41ac-9306-090413a8702e tcp_flags = 0 setup_time = 1516701775806015 action = pass sg_rule_uuid = 78df1ec8-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 50275 ] reverse_flow_info= [ logged_bytes = 42 logged_pkts = 1 flow_uuid = 1c7b69f8-5b0c-4573-b57c-6b2cc09225c6 tcp_flags = 0 setup_time = 1516701775806015 action = pass sg_rule_uuid = 78e70dcc-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 51492 ] vm = f2665eed-cc1f-4aab-b039-82ddf3281436 other_vrouter_ip = 10.204.217.102 underlay_proto = 0 ], ] ] ], [ local_ip = 2.2.2.3 service_port = 10002 protocol = 17 ] [ logged_forward_bytes = 70 logged_forward_pkts = 1 logged_reverse_bytes = 42 logged_reverse_pkts = 1 sessionMap= [ [ [ ip = 1.1.1.4 port = 1182 ] [ forward_flow_info= [ logged_bytes = 70 logged_pkts = 1 flow_uuid = 22a9e500-2756-406b-ba10-22cf0d19064c tcp_flags = 0 setup_time = 1516701775806060 action = pass sg_rule_uuid = 78df1ec8-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 56452 ] reverse_flow_info= [ logged_bytes = 42 logged_pkts = 1 flow_uuid = 25b08a16-b473-46f9-9315-6191f98f4fe2 tcp_flags = 0 setup_time = 1516701775806060 action = pass sg_rule_uuid = 78e70dcc-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 63922 ] vm = f2665eed-cc1f-4aab-b039-82ddf3281436 other_vrouter_ip = 10.204.217.102 underlay_proto = 0 ], ] ] ], ] ] ], [ vmi = default-domain:admin:d0b67b89-37d8-4869-8f88-1ea905ae4e50 vn = default-domain:admin:vn1-alok security_policy_rule = 00000000-0000-0000-0000-000000000001 remote_vn = default-domain:admin:vn2-alok is_client_session = 1 is_si = 0 vrouter_ip = 10.204.217.102 sess_agg_info= [ [ [ local_ip = 1.1.1.4 service_port = 10001 protocol = 17 ] [ logged_forward_bytes = 42 logged_forward_pkts = 1 logged_reverse_bytes = 70 logged_reverse_pkts = 1 sessionMap= [ [ [ ip = 2.2.2.3 port = 1181 ] [ forward_flow_info= [ logged_bytes = 42 logged_pkts = 1 flow_uuid = 1c7b69f8-5b0c-4573-b57c-6b2cc09225c6 tcp_flags = 0 setup_time = 1516701775806037 action = pass sg_rule_uuid = 78e70dcc-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 51492 ] reverse_flow_info= [ logged_bytes = 70 logged_pkts = 1 flow_uuid = c2101df7-f0fb-41ac-9306-090413a8702e tcp_flags = 0 setup_time = 1516701775806037 action = pass sg_rule_uuid = 78df1ec8-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 50275 ] vm = 54a80d63-be1f-4297-9d7f-1db151cf70bb other_vrouter_ip = 10.204.217.102 underlay_proto = 0 ], ] ] ], [ local_ip = 1.1.1.4 service_port = 10002 protocol = 17 ] [ logged_forward_bytes = 42 logged_forward_pkts = 1 logged_reverse_bytes = 70 logged_reverse_pkts = 1 sessionMap= [ [ [ ip = 2.2.2.3 port = 1182 ] [ forward_flow_info= [ logged_bytes = 42 logged_pkts = 1 flow_uuid = 25b08a16-b473-46f9-9315-6191f98f4fe2 tcp_flags = 0 setup_time = 1516701775806076 action = pass sg_rule_uuid = 78e70dcc-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 63922 ] reverse_flow_info= [ logged_bytes = 70 logged_pkts = 1 flow_uuid = 22a9e500-2756-406b-ba10-22cf0d19064c tcp_flags = 0 setup_time = 1516701775806076 action = pass sg_rule_uuid = 78df1ec8-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 underlay_source_port = 56452 ] vm = 54a80d63-be1f-4297-9d7f-1db151cf70bb other_vrouter_ip = 10.204.217.102 underlay_proto = 0 ], ] ] ], ] ] ], ] ]
2018-01-23 Tue 15:32:57:142.445 IST nodec62 [Thread 140554875680512, Pid 31405]: [SYS_INFO]: SessionEndpointObject: session_data= [ [ [ vmi = default-domain:admin:d0b67b89-37d8-4869-8f88-1ea905ae4e50 vn = default-domain:admin:vn1-alok security_policy_rule = 00000000-0000-0000-0000-000000000001 remote_vn = default-domain:admin:vn2-alok is_client_session = 1 is_si = 0 vrouter_ip = 10.204.217.102 sess_agg_info= [ [ [ local_ip = 1.1.1.4 service_port = 10000 protocol = 17 ] [ logged_forward_bytes = 0 logged_forward_pkts = 0 logged_reverse_bytes = 0 logged_reverse_pkts = 0 sessionMap= [ [ [ ip = 2.2.2.3 port = 1180 ] [ forward_flow_info= [ flow_uuid = 53ebb126-04ee-4f14-9a90-e51cb9834358 setup_time = 1516701775805969 action = pass sg_rule_uuid = 78e70dcc-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 ] reverse_flow_info= [ flow_uuid = 71b24fb4-95e2-430c-8e2a-ac55ad55ac39 setup_time = 1516701775805969 action = pass sg_rule_uuid = 78df1ec8-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 ] vm = 54a80d63-be1f-4297-9d7f-1db151cf70bb other_vrouter_ip = 10.204.217.102 underlay_proto = 0 ], ] ] ], ] ] ], ] ]
2018-01-23 Tue 15:32:58:142.503 IST nodec62 [Thread 140554875680512, Pid 31405]: [SYS_INFO]: SessionEndpointObject: session_data= [ [ [ vmi = default-domain:admin:2ade55df-4eb9-4d2d-80db-47b77f5b4aa6 vn = default-domain:admin:vn2-alok security_policy_rule = 00000000-0000-0000-0000-000000000001 remote_vn = default-domain:admin:vn1-alok is_client_session = 0 is_si = 0 vrouter_ip = 10.204.217.102 sess_agg_info= [ [ [ local_ip = 2.2.2.3 service_port = 10000 protocol = 17 ] [ logged_forward_bytes = 0 logged_forward_pkts = 0 logged_reverse_bytes = 0 logged_reverse_pkts = 0 sessionMap= [ [ [ ip = 1.1.1.4 port = 1180 ] [ forward_flow_info= [ flow_uuid = 71b24fb4-95e2-430c-8e2a-ac55ad55ac39 setup_time = 1516701775805768 action = pass sg_rule_uuid = 78df1ec8-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 ] reverse_flow_info= [ flow_uuid = 53ebb126-04ee-4f14-9a90-e51cb9834358 setup_time = 1516701775805768 action = pass sg_rule_uuid = 78e70dcc-ff69-11e7-866c-0242ac110003 nw_ace_uuid = 0cd59d41-692a-4ce9-b922-f4c1769fbcd7 ] vm = f2665eed-cc1f-4aab-b039-82ddf3281436 other_vrouter_ip = 10.204.217.102 underlay_proto = 0 ], ] ] ], ] ] ], ] ]
here last 2 sessions are logged for destination port 10000, which were not logged in first session log.
Review in progress for https:/ /review. opencontrail. org/40124
Submitter: Madhusudan Bhat (<email address hidden>)