Loading...

Type: Bug
Resolution: Duplicate
Priority: Normal
Fix Version/s: None
Affects Version/s: 4.15.0
Component/s: Networking / ptp
Labels:

Regression:
No
Blocked:
False
Blocked Reason:

Hide

None

Show
None
Latest Status Summary:

Hide
4/18: Work in progress ; still failing
4/4: Currently resolving issues with the pipeline, will close these issues once the pipeline is green again.

Show
4/18: Work in progress ; still failing 4/4: Currently resolving issues with the pipeline, will close these issues once the pipeline is green again.
Target Version:

4.16.0

SFDC Cases Counter:
SFDC Cases Links:

TC [It] [oc-parallel] Event based tests PTP Slave Clock Sync fails intermittently.

The frequency of this issue occurring is LOW.

https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/test-platform-results/pr-logs/pull/openshift_release/48859/rehearse-48859-periodic-ci-openshift-release-master-nightly-4.16-e2e-telco5g-ptp/1758977310674915328/artifacts/e2e-telco5g-ptp/telco5g-ptp-tests/artifacts/test_results_all.html

Observed in 4.13 CI too.
https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/test-platform-results/logs/periodic-ci-openshift-release-master-nightly-4.13-e2e-telco5g-ptp/1765875143835389952/artifacts/e2e-telco5g-ptp/telco5g-ptp-tests/artifacts/test_results_all.html

ft10.2: �[36mINFO   �[0m[Feb 18 01:05:50.219][ptptestconfig.go: 101] PTP Test Config: {GlobalConfig:{MinOffset:-100 MaxOffset:100} SoakTestConfig:{DisableSoakTest:false FailureThreshold:1 Duration:10 EventOutputFile:/logs/artifacts/event_log_oc.csv SlaveClockSyncConfig:{TestSpec:{Enable:true FailureThreshold:1 Duration:5} Description:The test measures number of PTP time sync faults, and fails if > failure_threshold} CpuUtilization:{CpuTestSpec:{TestSpec:{Enable:true FailureThreshold:3 Duration:5} CustomParams:{PromTimeWindow:70s Node:{CpuUsageThreshold:100} Pod:[{PodType:ptp-operator Container:<nil> CpuUsageThreshold:30} {PodType:linuxptp-daemon Container:<nil> CpuUsageThreshold:80} {PodType:linuxptp-daemon Container:cloud-event-proxy CpuUsageThreshold:30} {PodType:linuxptp-daemon Container:linuxptp-daemon-container CpuUsageThreshold:40}]}} Description:The test measures PTP CPU usage and fails if >15mcores}}} 
�[37mDEBUG  �[0m[Feb 18 01:06:50.240][ptp.go: 71] fullConfig=PtpModeDesired= OC, PtpModeDiscovered= OC, Status= discoverySuccess, DiscoveredClockUnderTestPtpConfig= test-slave1, DiscoveredClockUnderTestSecondaryPtpConfig= nil, DiscoveredGrandMasterPtpConfig= test-grandmaster, DiscoveredSlave1PtpConfig= nil, DiscoveredSlave2PtpConfig= nil, PtpEventsIsSidecarReady= true, DiscoveredClockUnderTestPodName=linuxptp-daemon-dln98, DiscoveredClockUnderTestNodeName=cnfdf30.telco5gran.eng.rdu2.redhat.com 
�[37mDEBUG  �[0m[Feb 18 01:06:50.241][ptp.go: 93] sync test fullConfig=PtpModeDesired= OC, PtpModeDiscovered= OC, Status= discoverySuccess, DiscoveredClockUnderTestPtpConfig= test-slave1, DiscoveredClockUnderTestSecondaryPtpConfig= nil, DiscoveredGrandMasterPtpConfig= test-grandmaster, DiscoveredSlave1PtpConfig= nil, DiscoveredSlave2PtpConfig= nil, PtpEventsIsSidecarReady= true, DiscoveredClockUnderTestPodName=linuxptp-daemon-dln98, DiscoveredClockUnderTestNodeName=cnfdf30.telco5gran.eng.rdu2.redhat.com 
�[36mINFO   �[0m[Feb 18 01:06:50.241][ptp.go: 109] Test description The test measures number of PTP time sync faults, and fails if > failure_threshold 
�[36mINFO   �[0m[Feb 18 01:06:50.241][ptp.go: 119] Failure threshold = 1                        
�[36mINFO   �[0m[Feb 18 01:06:50.241][ptp.go: 291] {Enable:true FailureThreshold:1 Duration:5}  
�[37mDEBUG  �[0m[Feb 18 01:06:50.241][pubsublib.go: 31] lock Subscribe event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:50.241][pubsublib.go: 37] unlock Subscribe event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:50.676][event.go: 433]   id: e7e06cd1-358e-495f-99ce-985fc54c4984
  type: event.sync.ptp-status.ptp-clock-class-change
  time: 2024-02-18T01:09:04.548014294Z
  data: 
  version: v1
  values: 
  value type : decimal64.3
  data type : metric
  value : 248
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/ens4fx/master/CLOCK_CLASS
 
�[37mDEBUG  �[0m[Feb 18 01:06:50.676][event.go: 440] Latency for the event: -133871 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:50.676][event.go: 433]   id: 3821943d-615a-4740-85bd-d67802453490
  type: event.sync.ptp-status.ptp-state-change
  time: 2024-02-18T01:09:04.549811666Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/ens4fx/master
  value type : decimal64.3
  data type : metric
  value : -14362
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/ens4fx/master
 
�[37mDEBUG  �[0m[Feb 18 01:06:50.676][event.go: 440] Latency for the event: -133872 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][event.go: 433]   id: 1b1d6ee3-d86c-4fbe-a430-503d731e822b
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:04.550669488Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : -270
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][event.go: 440] Latency for the event: -133873 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:04.550669488Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:-270 notification:FREERUN]] 
�[37mDEBUG  �[0m[Feb 18 01:06:50.677][ptp.go: 345] clockOffset=-270.000000                      
�[37mDEBUG  �[0m[Feb 18 01:06:51.081][event.go: 433]   id: 81496008-2916-48f0-a45a-bfbf53bc0497
  type: event.sync.ptp-status.ptp-state-change
  time: 2024-02-18T01:09:04.982761506Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/ens4fx/master
  value type : decimal64.3
  data type : metric
  value : -79
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/ens4fx/master
 
�[37mDEBUG  �[0m[Feb 18 01:06:51.081][event.go: 440] Latency for the event: -133901 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:51.081][pubsublib.go: 42] lock Publish event.sync.ptp-status.ptp-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:51.081][pubsublib.go: 57] unlock Publish event.sync.ptp-status.ptp-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:05.459541793Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : 4
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][event.go: 440] Latency for the event: -133933 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:05.459541793Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:4 notification:LOCKED]] 
�[37mDEBUG  �[0m[Feb 18 01:06:51.526][ptp.go: 345] clockOffset=4.000000                         
�[36mINFO   �[0m[Feb 18 01:06:51.526][ptp.go: 353] Clock is locked, starting to monitor status now 
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:05.525509461Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : 174
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][event.go: 440] Latency for the event: -133938 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:05.525509461Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:174 notification:FREERUN]] 
�[37mDEBUG  �[0m[Feb 18 01:06:51.587][ptp.go: 345] clockOffset=174.000000                       
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:06.960758315Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : 43
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][event.go: 440] Latency for the event: -134034 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:06.960758315Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:43 notification:LOCKED]] 
�[37mDEBUG  �[0m[Feb 18 01:06:52.926][ptp.go: 345] clockOffset=43.000000                        
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:07.09148449Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : -155
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][event.go: 440] Latency for the event: -134043 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:07.09148449Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:-155 notification:FREERUN]] 
�[37mDEBUG  �[0m[Feb 18 01:06:53.048][ptp.go: 345] clockOffset=-155.000000                      
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:08.45488516Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : -33
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][event.go: 440] Latency for the event: -134134 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:08.45488516Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:-33 notification:LOCKED]] 
�[37mDEBUG  �[0m[Feb 18 01:06:54.320][ptp.go: 345] clockOffset=-33.000000                       
�[37mDEBUG  �[0m[Feb 18 01:06:54.441][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:08.585066056Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : 108
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:54.441][event.go: 440] Latency for the event: -134143 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:54.441][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:54.441][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:54.441][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:54.441][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:54.442][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:08.585066056Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:108 notification:FREERUN]] 
�[37mDEBUG  �[0m[Feb 18 01:06:54.442][ptp.go: 345] clockOffset=108.000000                       
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:09.872067232Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : 70
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][event.go: 440] Latency for the event: -134229 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:09.872067232Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:70 notification:LOCKED]] 
�[37mDEBUG  �[0m[Feb 18 01:06:55.642][ptp.go: 345] clockOffset=70.000000                        
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:10.198706528Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : -119
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][event.go: 440] Latency for the event: -134252 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:10.198706528Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:-119 notification:FREERUN]] 
�[37mDEBUG  �[0m[Feb 18 01:06:55.946][ptp.go: 345] clockOffset=-119.000000                      
�[37mDEBUG  �[0m[Feb 18 01:06:56.964][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:11.290575845Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : -81
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:56.964][event.go: 440] Latency for the event: -134325 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:56.964][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:56.964][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:56.964][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:56.964][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:56.965][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:11.290575845Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:-81 notification:LOCKED]] 
�[37mDEBUG  �[0m[Feb 18 01:06:56.965][ptp.go: 345] clockOffset=-81.000000                       
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:11.817770625Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : 120
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][event.go: 440] Latency for the event: -134360 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:11.817770625Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:120 notification:FREERUN]] 
�[37mDEBUG  �[0m[Feb 18 01:06:57.457][ptp.go: 345] clockOffset=120.000000                       
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:12.663293508Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : 72
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][event.go: 440] Latency for the event: -134416 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:12.663293508Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:72 notification:LOCKED]] 
�[37mDEBUG  �[0m[Feb 18 01:06:58.246][ptp.go: 345] clockOffset=72.000000                        
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:13.722922116Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : FREERUN
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : -102
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][event.go: 440] Latency for the event: -134488 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:13.722922116Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:-102 notification:FREERUN]] 
�[37mDEBUG  �[0m[Feb 18 01:06:59.234][ptp.go: 345] clockOffset=-102.000000                      
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][event.go: 433]   id: f372e367-cebc-45d2-b83f-dcd076e6f588
  type: event.sync.sync-status.os-clock-sync-state-change
  time: 2024-02-18T01:09:13.788860416Z
  data: 
  version: v1
  values: 
  value type : enumeration
  data type : notification
  value : LOCKED
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
  value type : decimal64.3
  data type : metric
  value : -90
  resource: /cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/CLOCK_REALTIME
 
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][event.go: 440] Latency for the event: -134494 ms            
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][pubsublib.go: 42] lock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][pubsublib.go: 54] Publish topic=event.sync.sync-status.os-clock-sync-state-change channel len=0, capacity=100 
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][pubsublib.go: 57] unlock Publish event.sync.sync-status.os-clock-sync-state-change 
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][ptp.go: 336] Received a new OsClockSyncStateChange event  
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][ptp.go: 337] got map[eventsource:/cluster/node/cnfdf30.telco5gran.eng.rdu2.redhat.com/sync/sync-status/os-clock-sync-state eventtimestamp:2024-02-18T01:09:13.788860416Z eventtype:event.sync.sync-status.os-clock-sync-state-change eventvalues:map[metric:-90 notification:LOCKED]] 
�[37mDEBUG  �[0m[Feb 18 01:06:59.294][ptp.go: 345] clockOffset=-90.000000                       
�[36mINFO   �[0m[Feb 18 01:11:50.242][ptp.go: 326] Clock Sync failed 6 times.                   
�[36mINFO   �[0m[Feb 18 01:11:50.242][ptp.go: 327] Collected sync events during soak test period= 2024-02-18T01:09:05.459541793Z,event.sync.sync-status.os-clock-sync-state-change,4.000000,LOCKED,6
2024-02-18T01:09:05.525509461Z,event.sync.sync-status.os-clock-sync-state-change,174.000000,FREERUN,4
2024-02-18T01:09:06.960758315Z,event.sync.sync-status.os-clock-sync-state-change,43.000000,LOCKED,6
2024-02-18T01:09:07.09148449Z,event.sync.sync-status.os-clock-sync-state-change,-155.000000,FREERUN,4
2024-02-18T01:09:08.45488516Z,event.sync.sync-status.os-clock-sync-state-change,-33.000000,LOCKED,6
2024-02-18T01:09:08.585066056Z,event.sync.sync-status.os-clock-sync-state-change,108.000000,FREERUN,4
2024-02-18T01:09:09.872067232Z,event.sync.sync-status.os-clock-sync-state-change,70.000000,LOCKED,6
2024-02-18T01:09:10.198706528Z,event.sync.sync-status.os-clock-sync-state-change,-119.000000,FREERUN,4
2024-02-18T01:09:11.290575845Z,event.sync.sync-status.os-clock-sync-state-change,-81.000000,LOCKED,6
2024-02-18T01:09:11.817770625Z,event.sync.sync-status.os-clock-sync-state-change,120.000000,FREERUN,4
2024-02-18T01:09:12.663293508Z,event.sync.sync-status.os-clock-sync-state-change,72.000000,LOCKED,6
2024-02-18T01:09:13.722922116Z,event.sync.sync-status.os-clock-sync-state-change,-102.000000,FREERUN,4
2024-02-18T01:09:13.788860416Z,event.sync.sync-status.os-clock-sync-state-change,-90.000000,LOCKED,6 
�[36mINFO   �[0m[Feb 18 01:12:26.477][event.go: 350] received term signal, exiting MonitorPodLogsRegex 
�[37mDEBUG  �[0m[Feb 18 01:12:26.477][pubsublib.go: 78] lock Unsubscribe                             
�[37mDEBUG  �[0m[Feb 18 01:12:26.477][pubsublib.go: 89] unlock Unsubscribe                           
> Enter [BeforeEach] [oc-parallel] - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/pkg/execute/ginkgo.go:9 @ 02/18/24 01:05:50.219
< Exit [BeforeEach] [oc-parallel] - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/pkg/execute/ginkgo.go:9 @ 02/18/24 01:06:50.224 (1m0.005s)
> Enter [BeforeEach] Event based tests - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:66 @ 02/18/24 01:06:50.224
< Exit [BeforeEach] Event based tests - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:66 @ 02/18/24 01:06:50.24 (16ms)
> Enter [It] PTP Slave Clock Sync - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:77 @ 02/18/24 01:06:50.241
2024-02-18T01:09:05.459541793Z,event.sync.sync-status.os-clock-sync-state-change,4.000000,LOCKED,6
2024-02-18T01:09:05.525509461Z,event.sync.sync-status.os-clock-sync-state-change,174.000000,FREERUN,4
2024-02-18T01:09:06.960758315Z,event.sync.sync-status.os-clock-sync-state-change,43.000000,LOCKED,6
2024-02-18T01:09:07.09148449Z,event.sync.sync-status.os-clock-sync-state-change,-155.000000,FREERUN,4
2024-02-18T01:09:08.45488516Z,event.sync.sync-status.os-clock-sync-state-change,-33.000000,LOCKED,6
2024-02-18T01:09:08.585066056Z,event.sync.sync-status.os-clock-sync-state-change,108.000000,FREERUN,4
2024-02-18T01:09:09.872067232Z,event.sync.sync-status.os-clock-sync-state-change,70.000000,LOCKED,6
2024-02-18T01:09:10.198706528Z,event.sync.sync-status.os-clock-sync-state-change,-119.000000,FREERUN,4
2024-02-18T01:09:11.290575845Z,event.sync.sync-status.os-clock-sync-state-change,-81.000000,LOCKED,6
2024-02-18T01:09:11.817770625Z,event.sync.sync-status.os-clock-sync-state-change,120.000000,FREERUN,4
2024-02-18T01:09:12.663293508Z,event.sync.sync-status.os-clock-sync-state-change,72.000000,LOCKED,6
2024-02-18T01:09:13.722922116Z,event.sync.sync-status.os-clock-sync-state-change,-102.000000,FREERUN,4
2024-02-18T01:09:13.788860416Z,event.sync.sync-status.os-clock-sync-state-change,-90.000000,LOCKED,6
 - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:323 @ 02/18/24 01:11:50.242
[FAILED] Failure threshold (1) reached
Expected
    <int>: 6
to be <
    <int>: 1
In [It] at: /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:331 @ 02/18/24 01:12:26.477
< Exit [It] PTP Slave Clock Sync - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:77 @ 02/18/24 01:12:26.477 (5m36.236s)
> Enter [AfterEach] Event based tests - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:82 @ 02/18/24 01:12:26.477
< Exit [AfterEach] Event based tests - /tmp/cnf-CCRNQ/ptp-operator-conformance-test/test/conformance/parallel/ptp.go:82 @ 02/18/24 01:12:26.477 (0s)

Details

Description

Attachments

Activity

People

Dates