Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Antrea Network Policy Audit Logging Deduplication and Unit Tests #2294

Merged
merged 9 commits into from Aug 11, 2021

Conversation

qiyueyao
Copy link
Contributor

@qiyueyao qiyueyao commented Jun 22, 2021

Added log deduplication for Antrea Network Policy Audit Logging.

  • Directly log if disposition is Allow, use 1 sec buffer otherwise.
  • For each log, create an entry in the global map, which includes a 1 sec timer and counter.
  • Increase count upon receiving a duplication log.
  • Write to new log when timer stops, include [count, duration] for the log additionally.
    example: 2021/06/24 23:56:41.346165 AntreaPolicyIngressRule AntreaNetworkPolicy:default/test-anp2 Drop 44900 SRC: 10.10.2.5 DEST: 10.10.1.10 84 ICMP [2 packets in 1.011379442s]

Changed Controller structure.

  • Removed loggingEnabled, which was set to always equal to antreaPolicyEnabled.
  • Added AntreaPolicyLogger, used for audit logging.

Added unit tests for Antrea Network Policy Audit Logging.

  • Allow: directly log once.
  • Drop: log once, no additional log info.
  • DedupDrop: log once, include duplicate log info.
  • Multi DedupDrop: two different logs, includes duplicate log info.

Testing:
ping -i 0.2 <ip-address>

@codecov-commenter
Copy link

codecov-commenter commented Jun 22, 2021

Codecov Report

Merging #2294 (72d9769) into main (fe4457f) will increase coverage by 4.95%.
The diff coverage is 90.90%.

Impacted file tree graph

@@            Coverage Diff             @@
##             main    #2294      +/-   ##
==========================================
+ Coverage   60.09%   65.04%   +4.95%     
==========================================
  Files         281      282       +1     
  Lines       22243    25545    +3302     
==========================================
+ Hits        13366    16617    +3251     
+ Misses       7467     7393      -74     
- Partials     1410     1535     +125     
Flag Coverage Δ
e2e-tests 55.85% <78.78%> (?)
kind-e2e-tests 47.07% <84.48%> (+0.16%) ⬆️
unit-tests 42.56% <50.00%> (+0.07%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files Coverage Δ
pkg/agent/controller/networkpolicy/packetin.go 71.42% <60.00%> (-1.26%) ⬇️
...kg/agent/controller/networkpolicy/audit_logging.go 96.22% <96.22%> (ø)
...ntroller/networkpolicy/networkpolicy_controller.go 70.89% <100.00%> (+1.43%) ⬆️
pkg/controller/egress/ipallocator/allocator.go 67.82% <0.00%> (-15.16%) ⬇️
pkg/controller/networkpolicy/endpoint_querier.go 77.64% <0.00%> (-13.79%) ⬇️
pkg/apis/controlplane/v1beta1/conversion.go 72.44% <0.00%> (-11.89%) ⬇️
pkg/legacyapis/core/v1alpha2/register.go 69.23% <0.00%> (-10.77%) ⬇️
pkg/controller/egress/controller.go 76.76% <0.00%> (-10.44%) ⬇️
pkg/apis/stats/register.go 71.42% <0.00%> (-10.39%) ⬇️
pkg/legacyapis/stats/register.go 71.42% <0.00%> (-10.39%) ⬇️
... and 269 more

Copy link
Contributor

@Dyanngg Dyanngg left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM overall

pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
@qiyueyao qiyueyao force-pushed the LogDedup branch 2 times, most recently from 8628df6 to 7fbbd19 Compare June 25, 2021 18:00
abhiraut
abhiraut previously approved these changes Jun 25, 2021
Copy link
Contributor

@abhiraut abhiraut left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm

pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
Copy link
Contributor

@antoninbas antoninbas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

now that we have deduplication support and we are making the logging logic more complex, we should have unit tests for this. It should be possible to pass a log.Logger object which captures log message for testing purposes.

pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
@qiyueyao qiyueyao changed the title Antrea Network Policy Log Deduplication [Work in progress]Antrea Network Policy Log Deduplication Jun 29, 2021
@qiyueyao qiyueyao force-pushed the LogDedup branch 3 times, most recently from 23ced17 to 903e38d Compare July 6, 2021 20:42
@qiyueyao qiyueyao changed the title [Work in progress]Antrea Network Policy Log Deduplication Antrea Network Policy Audit Logging Deduplication and Unit Tests Jul 6, 2021
Copy link
Contributor

@antoninbas antoninbas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@qiyueyao @Dyanngg since this is not an urgent PR, I recommend postponing it to 1.3

pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/packetin.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/packetin_test.go Outdated Show resolved Hide resolved
@antoninbas antoninbas added this to the Antrea v1.3 release milestone Jul 9, 2021
@qiyueyao qiyueyao force-pushed the LogDedup branch 2 times, most recently from f017a21 to 34eb14e Compare July 13, 2021 23:46
@qiyueyao
Copy link
Contributor Author

qiyueyao commented Aug 6, 2021

/test-all

antoninbas
antoninbas previously approved these changes Aug 6, 2021
Copy link
Contributor

@antoninbas antoninbas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@qiyueyao qiyueyao requested a review from Dyanngg August 6, 2021 17:46
abhiraut
abhiraut previously approved these changes Aug 10, 2021
Copy link
Contributor

@abhiraut abhiraut left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

minor nits but otherwise lgtm

pkg/agent/controller/networkpolicy/audit_logging.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/audit_logging.go Outdated Show resolved Hide resolved
pkg/agent/controller/networkpolicy/audit_logging_test.go Outdated Show resolved Hide resolved
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
Signed-off-by: Qiyue Yao <yaoq@vmware.com>
@antoninbas
Copy link
Contributor

/test-all

cmd/antrea-agent/agent.go Show resolved Hide resolved
anpLogger: log.New(logOutput, "", log.Ldate|log.Lmicroseconds),
logDeduplication: logRecordDedupMap{logMap: make(map[string]*logDedupRecord)},
}
klog.V(2).Infof("Initialized Antrea-native Policy Logger for audit logging with log file '%s'", logFile)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you are going to make a change, better to change this logging to structured logging too.

actual := <-mockAnpLogger.logged
assert.Contains(t, actual, expectedLogWithCount(expected, 9))
actual = <-mockAnpLogger.logged
assert.Contains(t, actual, expected)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The test requires the clock and go routine scheduling works precisely. I think it may be flaky when the testbed is overloaded, could you try go test -count 100 to see if it's stable?

@antoninbas
Copy link
Contributor

Unrelated Kind test failure (in TestFlowAggregator/IPv4/IntraNodeFlows).

2021-08-10T23:47:34.2926529Z === RUN   TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:34.3964111Z     flowaggregator_test.go:832: Network Policies are realized.
2021-08-10T23:47:50.9426848Z     flowaggregator_test.go:724: 
2021-08-10T23:47:50.9428279Z         	Error Trace:	flowaggregator_test.go:724
2021-08-10T23:47:50.9429132Z         	            				flowaggregator_test.go:542
2021-08-10T23:47:50.9429822Z         	            				flowaggregator_test.go:213
2021-08-10T23:47:50.9448246Z         	Error:      	"\r\n  version: 10,  Message Length: 467\r\n  Exported Time: 1628639259 (2021-08-10 23:47:39 +0000 UTC)\r\n  Sequence No.: 4,  Observation Domain ID: 3406168056\r\nDATA SET:\r\n  DATA RECORD-0:\r\n    flowStartSeconds: 1628639255 \r\n    flowEndSeconds: 1628639256 \r\n    flowEndReason: 1 \r\n    sourceTransportPort: 41448 \r\n    destinationTransportPort: 5201 \r\n    protocolIdentifier: 6 \r\n    packetTotalCount: 0 \r\n    octetTotalCount: 0 \r\n    packetDeltaCount: 0 \r\n    octetDeltaCount: 0 \r\n    sourceIPv4Address: 10.10.0.9 \r\n    destinationIPv4Address: 10.10.0.10 \r\n    reversePacketTotalCount: 0 \r\n    reverseOctetTotalCount: 0 \r\n    reversePacketDeltaCount: 0 \r\n    reverseOctetDeltaCount: 0 \r\n    sourcePodName: perftest-a \r\n    sourcePodNamespace: antrea-test \r\n    sourceNodeName: kind-control-plane \r\n    destinationPodName: perftest-b \r\n    destinationPodNamespace: antrea-test \r\n    destinationNodeName: kind-control-plane \r\n    destinationServicePort: 0 \r\n    destinationServicePortName:  \r\n    ingressNetworkPolicyName: test-flow-aggregator-networkpolicy-ingress-allow \r\n    ingressNetworkPolicyNamespace: antrea-test \r\n    ingressNetworkPolicyType: 1 \r\n    ingressNetworkPolicyRuleName:  \r\n    ingressNetworkPolicyRuleAction: 1 \r\n    egressNetworkPolicyName: test-flow-aggregator-networkpolicy-egress-allow \r\n    egressNetworkPolicyNamespace: antrea-test \r\n    egressNetworkPolicyType: 1 \r\n    egressNetworkPolicyRuleName:  \r\n    egressNetworkPolicyRuleAction: 1 \r\n    tcpState: ESTABLISHED \r\n    flowType: 1 \r\n    destinationClusterIPv4: 0.0.0.0 \r\n    octetDeltaCountFromSourceNode: 0 \r\n    octetTotalCountFromSourceNode: 0 \r\n    packetDeltaCountFromSourceNode: 0 \r\n    packetTotalCountFromSourceNode: 0 \r\n    reverseOctetDeltaCountFromSourceNode: 0 \r\n    reverseOctetTotalCountFromSourceNode: 0 \r\n    reversePacketDeltaCountFromSourceNode: 0 \r\n    reversePacketTotalCountFromSourceNode: 0 \r\n    octetDeltaCountFromDestinationNode: 0 \r\n    octetTotalCountFromDestinationNode: 0 \r\n    packetDeltaCountFromDestinationNode: 0 \r\n    packetTotalCountFromDestinationNode: 0 \r\n    reverseOctetDeltaCountFromDestinationNode: 0 \r\n    reverseOctetTotalCountFromDestinationNode: 0 \r\n    reversePacketDeltaCountFromDestinationNode: 0 \r\n    reversePacketTotalCountFromDestinationNode: 0 \r\n    sourcePodLabels:  \r\n    destinationPodLabels:  \r\nI0810 23:47:50.837175       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837248       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837344       1 collector.go:88] \r\n" does not contain "{\"antrea-e2e\":\"perftest-a\",\"app\":\"perftool\"}"
2021-08-10T23:47:50.9469420Z         	Test:       	TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:50.9470327Z         	Messages:   	Record does not have correct label for source Pod
2021-08-10T23:47:50.9471093Z     flowaggregator_test.go:725: 
2021-08-10T23:47:50.9471803Z         	Error Trace:	flowaggregator_test.go:725
2021-08-10T23:47:50.9472661Z         	            				flowaggregator_test.go:542
2021-08-10T23:47:50.9473590Z         	            				flowaggregator_test.go:213
2021-08-10T23:47:50.9523930Z         	Error:      	"\r\n  version: 10,  Message Length: 467\r\n  Exported Time: 1628639259 (2021-08-10 23:47:39 +0000 UTC)\r\n  Sequence No.: 4,  Observation Domain ID: 3406168056\r\nDATA SET:\r\n  DATA RECORD-0:\r\n    flowStartSeconds: 1628639255 \r\n    flowEndSeconds: 1628639256 \r\n    flowEndReason: 1 \r\n    sourceTransportPort: 41448 \r\n    destinationTransportPort: 5201 \r\n    protocolIdentifier: 6 \r\n    packetTotalCount: 0 \r\n    octetTotalCount: 0 \r\n    packetDeltaCount: 0 \r\n    octetDeltaCount: 0 \r\n    sourceIPv4Address: 10.10.0.9 \r\n    destinationIPv4Address: 10.10.0.10 \r\n    reversePacketTotalCount: 0 \r\n    reverseOctetTotalCount: 0 \r\n    reversePacketDeltaCount: 0 \r\n    reverseOctetDeltaCount: 0 \r\n    sourcePodName: perftest-a \r\n    sourcePodNamespace: antrea-test \r\n    sourceNodeName: kind-control-plane \r\n    destinationPodName: perftest-b \r\n    destinationPodNamespace: antrea-test \r\n    destinationNodeName: kind-control-plane \r\n    destinationServicePort: 0 \r\n    destinationServicePortName:  \r\n    ingressNetworkPolicyName: test-flow-aggregator-networkpolicy-ingress-allow \r\n    ingressNetworkPolicyNamespace: antrea-test \r\n    ingressNetworkPolicyType: 1 \r\n    ingressNetworkPolicyRuleName:  \r\n    ingressNetworkPolicyRuleAction: 1 \r\n    egressNetworkPolicyName: test-flow-aggregator-networkpolicy-egress-allow \r\n    egressNetworkPolicyNamespace: antrea-test \r\n    egressNetworkPolicyType: 1 \r\n    egressNetworkPolicyRuleName:  \r\n    egressNetworkPolicyRuleAction: 1 \r\n    tcpState: ESTABLISHED \r\n    flowType: 1 \r\n    destinationClusterIPv4: 0.0.0.0 \r\n    octetDeltaCountFromSourceNode: 0 \r\n    octetTotalCountFromSourceNode: 0 \r\n    packetDeltaCountFromSourceNode: 0 \r\n    packetTotalCountFromSourceNode: 0 \r\n    reverseOctetDeltaCountFromSourceNode: 0 \r\n    reverseOctetTotalCountFromSourceNode: 0 \r\n    reversePacketDeltaCountFromSourceNode: 0 \r\n    reversePacketTotalCountFromSourceNode: 0 \r\n    octetDeltaCountFromDestinationNode: 0 \r\n    octetTotalCountFromDestinationNode: 0 \r\n    packetDeltaCountFromDestinationNode: 0 \r\n    packetTotalCountFromDestinationNode: 0 \r\n    reverseOctetDeltaCountFromDestinationNode: 0 \r\n    reverseOctetTotalCountFromDestinationNode: 0 \r\n    reversePacketDeltaCountFromDestinationNode: 0 \r\n    reversePacketTotalCountFromDestinationNode: 0 \r\n    sourcePodLabels:  \r\n    destinationPodLabels:  \r\nI0810 23:47:50.837175       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837248       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837344       1 collector.go:88] \r\n" does not contain "{\"antrea-e2e\":\"perftest-b\",\"app\":\"perftool\"}"
2021-08-10T23:47:50.9556377Z         	Test:       	TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:50.9557165Z         	Messages:   	Record does not have correct label for destination Pod

@srikartati FYI

@antoninbas antoninbas merged commit cd72bc6 into antrea-io:main Aug 11, 2021
@antoninbas
Copy link
Contributor

@tnqn I'm very sorry, I missed that you left a review for this...

@qiyueyao could you please open a follow-up PR asap to address Quan's comments?

@srikartati
Copy link
Member

Unrelated Kind test failure (in TestFlowAggregator/IPv4/IntraNodeFlows).

2021-08-10T23:47:34.2926529Z === RUN   TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:34.3964111Z     flowaggregator_test.go:832: Network Policies are realized.
2021-08-10T23:47:50.9426848Z     flowaggregator_test.go:724: 
2021-08-10T23:47:50.9428279Z         	Error Trace:	flowaggregator_test.go:724
2021-08-10T23:47:50.9429132Z         	            				flowaggregator_test.go:542
2021-08-10T23:47:50.9429822Z         	            				flowaggregator_test.go:213
2021-08-10T23:47:50.9448246Z         	Error:      	"\r\n  version: 10,  Message Length: 467\r\n  Exported Time: 1628639259 (2021-08-10 23:47:39 +0000 UTC)\r\n  Sequence No.: 4,  Observation Domain ID: 3406168056\r\nDATA SET:\r\n  DATA RECORD-0:\r\n    flowStartSeconds: 1628639255 \r\n    flowEndSeconds: 1628639256 \r\n    flowEndReason: 1 \r\n    sourceTransportPort: 41448 \r\n    destinationTransportPort: 5201 \r\n    protocolIdentifier: 6 \r\n    packetTotalCount: 0 \r\n    octetTotalCount: 0 \r\n    packetDeltaCount: 0 \r\n    octetDeltaCount: 0 \r\n    sourceIPv4Address: 10.10.0.9 \r\n    destinationIPv4Address: 10.10.0.10 \r\n    reversePacketTotalCount: 0 \r\n    reverseOctetTotalCount: 0 \r\n    reversePacketDeltaCount: 0 \r\n    reverseOctetDeltaCount: 0 \r\n    sourcePodName: perftest-a \r\n    sourcePodNamespace: antrea-test \r\n    sourceNodeName: kind-control-plane \r\n    destinationPodName: perftest-b \r\n    destinationPodNamespace: antrea-test \r\n    destinationNodeName: kind-control-plane \r\n    destinationServicePort: 0 \r\n    destinationServicePortName:  \r\n    ingressNetworkPolicyName: test-flow-aggregator-networkpolicy-ingress-allow \r\n    ingressNetworkPolicyNamespace: antrea-test \r\n    ingressNetworkPolicyType: 1 \r\n    ingressNetworkPolicyRuleName:  \r\n    ingressNetworkPolicyRuleAction: 1 \r\n    egressNetworkPolicyName: test-flow-aggregator-networkpolicy-egress-allow \r\n    egressNetworkPolicyNamespace: antrea-test \r\n    egressNetworkPolicyType: 1 \r\n    egressNetworkPolicyRuleName:  \r\n    egressNetworkPolicyRuleAction: 1 \r\n    tcpState: ESTABLISHED \r\n    flowType: 1 \r\n    destinationClusterIPv4: 0.0.0.0 \r\n    octetDeltaCountFromSourceNode: 0 \r\n    octetTotalCountFromSourceNode: 0 \r\n    packetDeltaCountFromSourceNode: 0 \r\n    packetTotalCountFromSourceNode: 0 \r\n    reverseOctetDeltaCountFromSourceNode: 0 \r\n    reverseOctetTotalCountFromSourceNode: 0 \r\n    reversePacketDeltaCountFromSourceNode: 0 \r\n    reversePacketTotalCountFromSourceNode: 0 \r\n    octetDeltaCountFromDestinationNode: 0 \r\n    octetTotalCountFromDestinationNode: 0 \r\n    packetDeltaCountFromDestinationNode: 0 \r\n    packetTotalCountFromDestinationNode: 0 \r\n    reverseOctetDeltaCountFromDestinationNode: 0 \r\n    reverseOctetTotalCountFromDestinationNode: 0 \r\n    reversePacketDeltaCountFromDestinationNode: 0 \r\n    reversePacketTotalCountFromDestinationNode: 0 \r\n    sourcePodLabels:  \r\n    destinationPodLabels:  \r\nI0810 23:47:50.837175       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837248       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837344       1 collector.go:88] \r\n" does not contain "{\"antrea-e2e\":\"perftest-a\",\"app\":\"perftool\"}"
2021-08-10T23:47:50.9469420Z         	Test:       	TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:50.9470327Z         	Messages:   	Record does not have correct label for source Pod
2021-08-10T23:47:50.9471093Z     flowaggregator_test.go:725: 
2021-08-10T23:47:50.9471803Z         	Error Trace:	flowaggregator_test.go:725
2021-08-10T23:47:50.9472661Z         	            				flowaggregator_test.go:542
2021-08-10T23:47:50.9473590Z         	            				flowaggregator_test.go:213
2021-08-10T23:47:50.9523930Z         	Error:      	"\r\n  version: 10,  Message Length: 467\r\n  Exported Time: 1628639259 (2021-08-10 23:47:39 +0000 UTC)\r\n  Sequence No.: 4,  Observation Domain ID: 3406168056\r\nDATA SET:\r\n  DATA RECORD-0:\r\n    flowStartSeconds: 1628639255 \r\n    flowEndSeconds: 1628639256 \r\n    flowEndReason: 1 \r\n    sourceTransportPort: 41448 \r\n    destinationTransportPort: 5201 \r\n    protocolIdentifier: 6 \r\n    packetTotalCount: 0 \r\n    octetTotalCount: 0 \r\n    packetDeltaCount: 0 \r\n    octetDeltaCount: 0 \r\n    sourceIPv4Address: 10.10.0.9 \r\n    destinationIPv4Address: 10.10.0.10 \r\n    reversePacketTotalCount: 0 \r\n    reverseOctetTotalCount: 0 \r\n    reversePacketDeltaCount: 0 \r\n    reverseOctetDeltaCount: 0 \r\n    sourcePodName: perftest-a \r\n    sourcePodNamespace: antrea-test \r\n    sourceNodeName: kind-control-plane \r\n    destinationPodName: perftest-b \r\n    destinationPodNamespace: antrea-test \r\n    destinationNodeName: kind-control-plane \r\n    destinationServicePort: 0 \r\n    destinationServicePortName:  \r\n    ingressNetworkPolicyName: test-flow-aggregator-networkpolicy-ingress-allow \r\n    ingressNetworkPolicyNamespace: antrea-test \r\n    ingressNetworkPolicyType: 1 \r\n    ingressNetworkPolicyRuleName:  \r\n    ingressNetworkPolicyRuleAction: 1 \r\n    egressNetworkPolicyName: test-flow-aggregator-networkpolicy-egress-allow \r\n    egressNetworkPolicyNamespace: antrea-test \r\n    egressNetworkPolicyType: 1 \r\n    egressNetworkPolicyRuleName:  \r\n    egressNetworkPolicyRuleAction: 1 \r\n    tcpState: ESTABLISHED \r\n    flowType: 1 \r\n    destinationClusterIPv4: 0.0.0.0 \r\n    octetDeltaCountFromSourceNode: 0 \r\n    octetTotalCountFromSourceNode: 0 \r\n    packetDeltaCountFromSourceNode: 0 \r\n    packetTotalCountFromSourceNode: 0 \r\n    reverseOctetDeltaCountFromSourceNode: 0 \r\n    reverseOctetTotalCountFromSourceNode: 0 \r\n    reversePacketDeltaCountFromSourceNode: 0 \r\n    reversePacketTotalCountFromSourceNode: 0 \r\n    octetDeltaCountFromDestinationNode: 0 \r\n    octetTotalCountFromDestinationNode: 0 \r\n    packetDeltaCountFromDestinationNode: 0 \r\n    packetTotalCountFromDestinationNode: 0 \r\n    reverseOctetDeltaCountFromDestinationNode: 0 \r\n    reverseOctetTotalCountFromDestinationNode: 0 \r\n    reversePacketDeltaCountFromDestinationNode: 0 \r\n    reversePacketTotalCountFromDestinationNode: 0 \r\n    sourcePodLabels:  \r\n    destinationPodLabels:  \r\nI0810 23:47:50.837175       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837248       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837344       1 collector.go:88] \r\n" does not contain "{\"antrea-e2e\":\"perftest-b\",\"app\":\"perftool\"}"
2021-08-10T23:47:50.9556377Z         	Test:       	TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:50.9557165Z         	Messages:   	Record does not have correct label for destination Pod

@srikartati FYI

@dreamtalen added the pod label test. Could you take a look at this?

@dreamtalen
Copy link
Contributor

dreamtalen commented Aug 11, 2021

Unrelated Kind test failure (in TestFlowAggregator/IPv4/IntraNodeFlows).

2021-08-10T23:47:34.2926529Z === RUN   TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:34.3964111Z     flowaggregator_test.go:832: Network Policies are realized.
2021-08-10T23:47:50.9426848Z     flowaggregator_test.go:724: 
2021-08-10T23:47:50.9428279Z         	Error Trace:	flowaggregator_test.go:724
2021-08-10T23:47:50.9429132Z         	            				flowaggregator_test.go:542
2021-08-10T23:47:50.9429822Z         	            				flowaggregator_test.go:213
2021-08-10T23:47:50.9448246Z         	Error:      	"\r\n  version: 10,  Message Length: 467\r\n  Exported Time: 1628639259 (2021-08-10 23:47:39 +0000 UTC)\r\n  Sequence No.: 4,  Observation Domain ID: 3406168056\r\nDATA SET:\r\n  DATA RECORD-0:\r\n    flowStartSeconds: 1628639255 \r\n    flowEndSeconds: 1628639256 \r\n    flowEndReason: 1 \r\n    sourceTransportPort: 41448 \r\n    destinationTransportPort: 5201 \r\n    protocolIdentifier: 6 \r\n    packetTotalCount: 0 \r\n    octetTotalCount: 0 \r\n    packetDeltaCount: 0 \r\n    octetDeltaCount: 0 \r\n    sourceIPv4Address: 10.10.0.9 \r\n    destinationIPv4Address: 10.10.0.10 \r\n    reversePacketTotalCount: 0 \r\n    reverseOctetTotalCount: 0 \r\n    reversePacketDeltaCount: 0 \r\n    reverseOctetDeltaCount: 0 \r\n    sourcePodName: perftest-a \r\n    sourcePodNamespace: antrea-test \r\n    sourceNodeName: kind-control-plane \r\n    destinationPodName: perftest-b \r\n    destinationPodNamespace: antrea-test \r\n    destinationNodeName: kind-control-plane \r\n    destinationServicePort: 0 \r\n    destinationServicePortName:  \r\n    ingressNetworkPolicyName: test-flow-aggregator-networkpolicy-ingress-allow \r\n    ingressNetworkPolicyNamespace: antrea-test \r\n    ingressNetworkPolicyType: 1 \r\n    ingressNetworkPolicyRuleName:  \r\n    ingressNetworkPolicyRuleAction: 1 \r\n    egressNetworkPolicyName: test-flow-aggregator-networkpolicy-egress-allow \r\n    egressNetworkPolicyNamespace: antrea-test \r\n    egressNetworkPolicyType: 1 \r\n    egressNetworkPolicyRuleName:  \r\n    egressNetworkPolicyRuleAction: 1 \r\n    tcpState: ESTABLISHED \r\n    flowType: 1 \r\n    destinationClusterIPv4: 0.0.0.0 \r\n    octetDeltaCountFromSourceNode: 0 \r\n    octetTotalCountFromSourceNode: 0 \r\n    packetDeltaCountFromSourceNode: 0 \r\n    packetTotalCountFromSourceNode: 0 \r\n    reverseOctetDeltaCountFromSourceNode: 0 \r\n    reverseOctetTotalCountFromSourceNode: 0 \r\n    reversePacketDeltaCountFromSourceNode: 0 \r\n    reversePacketTotalCountFromSourceNode: 0 \r\n    octetDeltaCountFromDestinationNode: 0 \r\n    octetTotalCountFromDestinationNode: 0 \r\n    packetDeltaCountFromDestinationNode: 0 \r\n    packetTotalCountFromDestinationNode: 0 \r\n    reverseOctetDeltaCountFromDestinationNode: 0 \r\n    reverseOctetTotalCountFromDestinationNode: 0 \r\n    reversePacketDeltaCountFromDestinationNode: 0 \r\n    reversePacketTotalCountFromDestinationNode: 0 \r\n    sourcePodLabels:  \r\n    destinationPodLabels:  \r\nI0810 23:47:50.837175       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837248       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837344       1 collector.go:88] \r\n" does not contain "{\"antrea-e2e\":\"perftest-a\",\"app\":\"perftool\"}"
2021-08-10T23:47:50.9469420Z         	Test:       	TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:50.9470327Z         	Messages:   	Record does not have correct label for source Pod
2021-08-10T23:47:50.9471093Z     flowaggregator_test.go:725: 
2021-08-10T23:47:50.9471803Z         	Error Trace:	flowaggregator_test.go:725
2021-08-10T23:47:50.9472661Z         	            				flowaggregator_test.go:542
2021-08-10T23:47:50.9473590Z         	            				flowaggregator_test.go:213
2021-08-10T23:47:50.9523930Z         	Error:      	"\r\n  version: 10,  Message Length: 467\r\n  Exported Time: 1628639259 (2021-08-10 23:47:39 +0000 UTC)\r\n  Sequence No.: 4,  Observation Domain ID: 3406168056\r\nDATA SET:\r\n  DATA RECORD-0:\r\n    flowStartSeconds: 1628639255 \r\n    flowEndSeconds: 1628639256 \r\n    flowEndReason: 1 \r\n    sourceTransportPort: 41448 \r\n    destinationTransportPort: 5201 \r\n    protocolIdentifier: 6 \r\n    packetTotalCount: 0 \r\n    octetTotalCount: 0 \r\n    packetDeltaCount: 0 \r\n    octetDeltaCount: 0 \r\n    sourceIPv4Address: 10.10.0.9 \r\n    destinationIPv4Address: 10.10.0.10 \r\n    reversePacketTotalCount: 0 \r\n    reverseOctetTotalCount: 0 \r\n    reversePacketDeltaCount: 0 \r\n    reverseOctetDeltaCount: 0 \r\n    sourcePodName: perftest-a \r\n    sourcePodNamespace: antrea-test \r\n    sourceNodeName: kind-control-plane \r\n    destinationPodName: perftest-b \r\n    destinationPodNamespace: antrea-test \r\n    destinationNodeName: kind-control-plane \r\n    destinationServicePort: 0 \r\n    destinationServicePortName:  \r\n    ingressNetworkPolicyName: test-flow-aggregator-networkpolicy-ingress-allow \r\n    ingressNetworkPolicyNamespace: antrea-test \r\n    ingressNetworkPolicyType: 1 \r\n    ingressNetworkPolicyRuleName:  \r\n    ingressNetworkPolicyRuleAction: 1 \r\n    egressNetworkPolicyName: test-flow-aggregator-networkpolicy-egress-allow \r\n    egressNetworkPolicyNamespace: antrea-test \r\n    egressNetworkPolicyType: 1 \r\n    egressNetworkPolicyRuleName:  \r\n    egressNetworkPolicyRuleAction: 1 \r\n    tcpState: ESTABLISHED \r\n    flowType: 1 \r\n    destinationClusterIPv4: 0.0.0.0 \r\n    octetDeltaCountFromSourceNode: 0 \r\n    octetTotalCountFromSourceNode: 0 \r\n    packetDeltaCountFromSourceNode: 0 \r\n    packetTotalCountFromSourceNode: 0 \r\n    reverseOctetDeltaCountFromSourceNode: 0 \r\n    reverseOctetTotalCountFromSourceNode: 0 \r\n    reversePacketDeltaCountFromSourceNode: 0 \r\n    reversePacketTotalCountFromSourceNode: 0 \r\n    octetDeltaCountFromDestinationNode: 0 \r\n    octetTotalCountFromDestinationNode: 0 \r\n    packetDeltaCountFromDestinationNode: 0 \r\n    packetTotalCountFromDestinationNode: 0 \r\n    reverseOctetDeltaCountFromDestinationNode: 0 \r\n    reverseOctetTotalCountFromDestinationNode: 0 \r\n    reversePacketDeltaCountFromDestinationNode: 0 \r\n    reversePacketTotalCountFromDestinationNode: 0 \r\n    sourcePodLabels:  \r\n    destinationPodLabels:  \r\nI0810 23:47:50.837175       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837248       1 collector.go:130] Processing IPFIX message\r\nI0810 23:47:50.837344       1 collector.go:88] \r\n" does not contain "{\"antrea-e2e\":\"perftest-b\",\"app\":\"perftool\"}"
2021-08-10T23:47:50.9556377Z         	Test:       	TestFlowAggregator/IPv4/IntraNodeFlows
2021-08-10T23:47:50.9557165Z         	Messages:   	Record does not have correct label for destination Pod

@srikartati FYI

@dreamtalen added the pod label test. Could you take a look at this?

Sure, I'm trying to reproduce it locally.
Update: I haven’t reproduce it successfully locally (tried vagrant cluster and kind cluster, run test ~20 times each environment). From the test failure log, I could see it’s because the labels info is not filled successfully on the Flow Aggregator side, so the Pod lables field remains empty and causes test failed, since I can’t access the logs of Flow Aggregator in that run, I don’t know it failed at which line exactly.

annakhm pushed a commit to annakhm/antrea that referenced this pull request Aug 16, 2021
…rea-io#2294)

Added log deduplication for Antrea Network Policy Audit Logging.
- Directly log if disposition is Allow, use 1 sec buffer otherwise.
- For each log, create an entry in the global map, which includes a 1 sec timer and counter.
- Increase count upon receiving a duplication log.
- Write to new log when timer stops, include [count, duration] for the log additionally.
example: `2021/06/24 23:56:41.346165 AntreaPolicyIngressRule AntreaNetworkPolicy:default/test-anp2 Drop 44900 SRC: 10.10.2.5 DEST: 10.10.1.10 84 ICMP [2 packets in 1.011379442s]`

Changed Controller structure.
- Removed `loggingEnabled`, which was set to always equal to `antreaPolicyEnabled`.
- Added `AntreaPolicyLogger`, used for audit logging.

Added unit tests for Antrea Network Policy Audit Logging.
- Allow: directly log once.
- Drop: log once, no additional log info.
- DedupDrop: log once, include duplicate log info.
- Multi DedupDrop: two different logs, includes duplicate log info.
antoninbas pushed a commit that referenced this pull request Aug 20, 2021
…t Tests (#2578)

This is a follow up PR for [Antrea Network Policy Audit Logging Deduplication and Unit Tests](#2294) to address comments.

- Converted back to include both `antreaPolicyEnabled` and `loggingEnabled` for extensible usage.
- Changed `AntreaPolicyLogger` method naming.
- Moved `bufferLength` to a member of `AntreaPolicyLogger` to avoid confusion.

Signed-off-by: Qiyue Yao <yaoq@vmware.com>
@qiyueyao qiyueyao deleted the LogDedup branch August 20, 2021 20:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

9 participants