[R4.1-84]- SLO: unnecessary sessions getting logged without logged bytes/pkts for all the sessions which are not logged because of SLO rate

Bug #1744914 reported by alok kumar
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Juniper Openstack
Status tracked in Trunk
R4.1
Fix Committed
High
Madhusudan Bhat
R5.0
Fix Committed
High
Madhusudan Bhat
Trunk
Fix Committed
High
Madhusudan Bhat

Bug Description

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.

Tags: vrouter
alok kumar (kalok)
description: updated
summary: - [R4.1-84]- SLO: sessions get logged without logged bytes/pkts for all
- the sessions which are not logged because of SLO rate
+ [R4.1-84]- SLO: unnecessary sessions getting logged without logged
+ bytes/pkts for all the sessions which are not logged because of SLO rate
Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : [Review update] R4.1

Review in progress for https://review.opencontrail.org/40124
Submitter: Madhusudan Bhat (<email address hidden>)

Revision history for this message
Hari Prasad Killi (haripk) wrote :
Revision history for this message
OpenContrail Admin (ci-admin-f) wrote :

Review in progress for https://review.opencontrail.org/40533
Submitter: Madhusudan Bhat (<email address hidden>)

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : [Review update] R5.0

Review in progress for https://review.opencontrail.org/41668
Submitter: Madhusudan Bhat (<email address hidden>)

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : A change has been merged

Reviewed: https://review.opencontrail.org/41668
Committed: http://github.com/Juniper/contrail-controller/commit/af50b7e2c41548d845dfcbf017c8e0b026476939
Submitter: Zuul v3 CI (<email address hidden>)
Branch: R5.0

commit af50b7e2c41548d845dfcbf017c8e0b026476939
Author: bmadhu <email address hidden>
Date: Mon Mar 12 15:55:29 2018 +0530

Unnecessary sessions getting logged with out SLO rate check

Idle sessions for which stats are not changed can be logged with SLO rate match
is not a bug.

This fix has below change:
With this change, all tear down sessions will not be logged.
Tear down sessions which are logged earlier at least once will be logged immidiately
with out checking rate, otherwise it will be considered as normal session and will be
reported only after matching the SLO rate.

Change-Id: I0f1ae5e4239fec9eebe57c8b34b6f20c3431403a
Closes-Bug: 1744914

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : [Review update] master

Review in progress for https://review.opencontrail.org/41853
Submitter: Madhusudan Bhat (<email address hidden>)

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : A change has been merged

Reviewed: https://review.opencontrail.org/40533
Committed: http://github.com/Juniper/contrail-controller/commit/884ab3ac9b3354f9b8451f631f1db77035a1c7a7
Submitter: Zuul (<email address hidden>)
Branch: R4.1

commit 884ab3ac9b3354f9b8451f631f1db77035a1c7a7
Author: bmadhu <email address hidden>
Date: Mon Mar 12 15:55:29 2018 +0530

Unnecessary sessions getting logged with out SLO rate check

Idle sessions for which stats are not changed can be logged with SLO rate match
is not a bug.

This fix has below change:
With this change, all tear down sessions will not be logged.
Tear down sessions which are logged earlier at least once will be logged immidiately
with out checking rate, otherwise it will be considered as normal session and will be
reported only after matching the SLO rate.

Change-Id: I0f1ae5e4239fec9eebe57c8b34b6f20c3431403a
Closes-Bug: 1744914

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote :

Reviewed: https://review.opencontrail.org/41853
Committed: http://github.com/Juniper/contrail-controller/commit/d196bc80eafd3d7ebb0400da39e9088bb7bd9786
Submitter: Zuul v3 CI (<email address hidden>)
Branch: master

commit d196bc80eafd3d7ebb0400da39e9088bb7bd9786
Author: bmadhu <email address hidden>
Date: Mon Mar 12 15:55:29 2018 +0530

Unnecessary sessions getting logged with out SLO rate check

Idle sessions for which stats are not changed can be logged with SLO rate match
is not a bug.

This fix has below change:
With this change, all tear down sessions will not be logged.
Tear down sessions which are logged earlier at least once will be logged immidiately
with out checking rate, otherwise it will be considered as normal session and will be
reported only after matching the SLO rate.

Change-Id: I0f1ae5e4239fec9eebe57c8b34b6f20c3431403a
Closes-Bug: 1744914
(cherry picked from commit af50b7e2c41548d845dfcbf017c8e0b026476939)

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.