Description | By running the A&C Ack tests Test_003, Err_004 and Err_005, I had some issue for Err_005 failure indicating Bad*AlreadyAcked.
After some investigations, I observed that the AlarmCollector might dispatch the same event in the SingleLoop function to several tests in case TestCompleted was called.
In my case, Err_004 was calling the TestCompleted function which changes the state to the next TestCase at same time and then the SingleLoop call the TestEvent function of Err_005 on the same event instance.
Err_004 does not check that the AckedState (which in this case was false) is set when received but only that new Acknowledge call will fail with BadAlreadyAcked which succeeds and complete the test.
This is not working for next test case because Err_005 considers the event AckedState is false whereas it is actually true after Err_004, thus the new acknowledgement (first of Err_005) fails with BadAlreadyAcked.
This behavior makes extremely hard to understand what is going on and script issue is actually shared between several tests, I would advise to avoid dispatching the same event to several test cases since the alarm condition is expected to do a cycle it is possible to wait for the next event for starting the next test. I suspect that this kind of issues occur in several A&C test cases since I observed instability when running the A&C tests making hard to reproduce failures in general,
I attached a fix proposal to do so, could you consider it to increase stability of the tests ? |
---|
Steps To Reproduce | By running the A&C Ack tests Test_003, Err_004 and Err_005,
I uncommented the line 289 of AlarmCollector module: this.DebugPrint( key + " CanRunTest " + testName + " = " + canRunTest + " Current State " + stateHolder.State );
I also added a print of eventFields in both TestEvent function of Err_004 and Err_005.
Here follows an extract of the Script output console that shows the same event is dispatched to both tests leading to the described issue:
SelectFields
EventId 0
EventType 1
SourceNode 2
SourceName 3
Time 4
ReceiveTime 5
LocalTime 6
Message 7
Severity 8
ConditionClassId 9
ConditionClassName 10
ConditionSubClassId 11
ConditionSubClassName 12
ConditionName 13
BranchId 14
Retain 15
SupportsFilteredRetain 16
EnabledState 17
Quality 18
LastSeverity 19
Comment 20
ClientUserId 21
EnabledState.Id 22
EnabledState.TransitionTime 23
EnabledState.EffectiveTransitionTime 24
EnabledState.TrueState 25
EnabledState.FalseState 26
Quality.SourceTimestamp 27
LastSeverity.SourceTimestamp 28
Comment.SourceTimestamp 29
DialogState 30
Prompt 31
ResponseOptionSet 32
DefaultResponse 33
OkResponse 34
CancelResponse 35
LastResponse 36
DialogState.Id 37
DialogState.TransitionTime 38
DialogState.TrueState 39
DialogState.FalseState 40
AckedState 41
ConfirmedState 42
AckedState.Id 43
AckedState.TransitionTime 44
AckedState.TrueState 45
AckedState.FalseState 46
ConfirmedState.Id 47
ConfirmedState.TransitionTime 48
ConfirmedState.TrueState 49
ConfirmedState.FalseState 50
ActiveState 51
InputNode 52
SuppressedState 53
OutOfServiceState 54
SuppressedOrShelved 55
MaxTimeShelved 56
AudibleEnabled 57
AudibleSound 58
SilenceState 59
OnDelay 60
OffDelay 61
FirstInGroupFlag 62
LatchedState 63
ReAlarmTime 64
ReAlarmRepeatCount 65
ActiveState.Id 66
ActiveState.TransitionTime 67
ActiveState.EffectiveTransitionTime 68
ActiveState.TrueState 69
ActiveState.FalseState 70
SuppressedState.Id 71
SuppressedState.TransitionTime 72
SuppressedState.TrueState 73
SuppressedState.FalseState 74
OutOfServiceState.Id 75
OutOfServiceState.TransitionTime 76
OutOfServiceState.TrueState 77
OutOfServiceState.FalseState 78
ShelvingState.CurrentState 79
ShelvingState.LastTransition 80
ShelvingState.UnshelveTime 81
ShelvingState.CurrentState.Id 82
ShelvingState.LastTransition.Id 83
ShelvingState.LastTransition.TransitionTime 84
SilenceState.Id 85
SilenceState.TransitionTime 86
SilenceState.TrueState 87
SilenceState.FalseState 88
LatchedState.Id 89
LatchedState.TransitionTime 90
LatchedState.TrueState 91
LatchedState.FalseState 92
HighHighLimit 93
HighLimit 94
LowLimit 95
LowLowLimit 96
BaseHighHighLimit 97
BaseHighLimit 98
BaseLowLimit 99
BaseLowLowLimit 100
SeverityHighHigh 101
SeverityHigh 102
SeverityLow 103
SeverityLowLow 104
HighHighDeadband 105
HighDeadband 106
LowDeadband 107
LowLowDeadband 108
LimitState.CurrentState 109
LimitState.LastTransition 110
LimitState.CurrentState.Id 111
LimitState.LastTransition.Id 112
LimitState.LastTransition.TransitionTime 113
SetpointNode 114
BaseSetpointNode 115
EngineeringUnits 116
HighHighState 117
HighState 118
LowState 119
LowLowState 120
HighHighState.Id 121
HighHighState.TransitionTime 122
HighHighState.TrueState 123
HighHighState.FalseState 124
HighState.Id 125
HighState.TransitionTime 126
HighState.TrueState 127
HighState.FalseState 128
LowState.Id 129
LowState.TransitionTime 130
LowState.TrueState 131
LowState.FalseState 132
LowLowState.Id 133
LowLowState.TransitionTime 134
LowLowState.TrueState 135
LowLowState.FalseState 136
NormalState 137
ExpirationDate 138
ExpirationLimit 139
CertificateType 140
Certificate 141
TrustListId 142
LastUpdateTime 143
UpdateFrequency 144
TargetValueNode 145
ExpectedTime 146
Tolerance 147
Adding Test Test_003
Adding Test Err_004
Adding Test Err_005
AlarmCollector Initialize complete at 2025-03-11T10:21:16.405Z took 2554 ms
TestStateEnum Index 0 State Test_003_Waiting
TestStateEnum Index 1 State Test_003_Running
TestStateEnum Index 2 State Test_003_Completed
TestStateEnum Index 3 State Err_004_Waiting
TestStateEnum Index 4 State Err_004_Running
TestStateEnum Index 5 State Err_004_Completed
TestStateEnum Index 6 State Err_005_Waiting
TestStateEnum Index 7 State Err_005_Running
TestStateEnum Index 8 State Err_005_Completed
...
2025-03-11T10:21:21.468Z - ns=1;i=15011 CanRunTest Err_004 = true Current State Err_004_Running
Err_004:ns=1;i=15011 ackedState false activeState[true]
Size: 149 [0] = size=24, data=0x159C8D02000000001E08000000000000A704F0764E340690|[1] = ns=1;i=11003|[2] = ns=1;i=16009|[3] = Tank1.Level.Measure|[4] = 2025-03-11T10:21:21.309Z|[5] = 2025-03-11T10:21:21.309Z|[6] = TypeId: NodeId: i=8917, NamespaceUri: , ServerIndex: 0, Encoding: OpcUa_ExtensionObjectEncoding_EncodeableObject, TimeZoneDataType: Offset: 0, DaylightSavingInOffset: 0|[7] = Locale: , Text: LowLimit|[8] = 0|[9] = i=17218|[10] = Locale: , Text: SafetyConditionClassType|[11] = Null|[12] = Null|[13] = LowLimit|[14] = Null|[15] = 1|[16] = Null|[17] = Locale: en, Text: Enabled|[18] = Good (0x00000000)|[19] = 0|[20] = Locale: en-US, Text: |[21] = |[22] = 1|[23] = 2025-03-11T09:32:45.064Z|[24] = Null|[25] = Locale: en, Text: Enabled|[26] = Locale: en, Text: Disabled|[27] = 2025-03-11T09:32:45.064Z|[28] = Null|[29] = 2025-03-11T10:21:17.737Z|[30] = Null|[31] = Null|[32] = Null|[33] = Null|[34] = Null|[35] = Null|[36] = Null|[37] = Null|[38] = Null|[39] = Null|[40] = Null|[41] = Locale: en, Text: Unacknowledged|[42] = Locale: en, Text: Confirmed|[43] = 0|[44] = 2025-03-11T10:21:21.308Z|[45] = Locale: en, Text: Acknowledged|[46] = Locale: en, Text: Unacknowledged|[47] = 1|[48] = 2025-03-11T10:21:21.308Z|[49] = Locale: en, Text: Confirmed|[50] = Locale: en, Text: Unconfirmed|[51] = Locale: en, Text: Active|[52] = ns=1;i=16009|[53] = Null|[54] = Null|[55] = 0|[56] = Null|[57] = Null|[58] = Null|[59] = Null|[60] = Null|[61] = Null|[62] = Null|[63] = Null|[64] = Null|[65] = Null|[66] = 1|[67] = 2025-03-11T10:21:21.308Z|[68] = Null|[69] = Locale: en, Text: Active|[70] = Locale: en, Text: Inactive|[71] = Null|[72] = Null|[73] = Locale: en, Text: Suppressed|[74] = Locale: en, Text: Unsuppressed|[75] = Null|[76] = Null|[77] = Locale: en, Text: Out of Service|[78] = Locale: en, Text: In Service|[79] = Null|[80] = Null|[81] = Null|[82] = Null|[83] = Null|[84] = Null|[85] = Null|[86] = Null|[87] = Locale: en, Text: Silenced|[88] = Locale: en, Text: Not Silenced|[89] = Null|[90] = Null|[91] = Locale: en, Text: Latched|[92] = Locale: en, Text: Unlatched|[93] = Null|[94] = Null|[95] = Null|[96] = Null|[97] = Null|[98] = Null|[99] = Null|[100] = Null|[101] = Null|[102] = Null|[103] = Null|[104] = Null|[105] = Null|[106] = Null|[107] = Null|[108] = Null|[109] = Null|[110] = Null|[111] = Null|[112] = Null|[113] = Null|[114] = Null|[115] = Null|[116] = Null|[117] = Null|[118] = Null|[119] = Null|[120] = Null|[121] = Null|[122] = Null|[123] = Null|[124] = Null|[125] = Null|[126] = Null|[127] = Null|[128] = Null|[129] = Null|[130] = Null|[131] = Null|[132] = Null|[133] = Null|[134] = Null|[135] = Null|[136] = Null|[137] = Null|[138] = Null|[139] = Null|[140] = Null|[141] = Null|[142] = Null|[143] = Null|[144] = Null|[145] = Null|[146] = Null|[147] = Null|[148] = ns=1;i=15011
Err_004:ns=1;i=15011 TWO ackedState false activeState[true] state WaitingForAcknowledgedEvent
Audit::PushAuditRecord - Thread and/or Subscription id is not initialized yet
ns=1;i=15011 TestCompleted found stateHolder ns=1;i=15011 state = Err_004_Completed
2025-03-11T10:21:21.470Z - ns=1;i=15011 CanRunTest Err_005 = true Current State Err_005_Running
Size: 149 [0] = size=24, data=0x159C8D02000000001E08000000000000A704F0764E340690|[1] = ns=1;i=11003|[2] = ns=1;i=16009|[3] = Tank1.Level.Measure|[4] = 2025-03-11T10:21:21.309Z|[5] = 2025-03-11T10:21:21.309Z|[6] = TypeId: NodeId: i=8917, NamespaceUri: , ServerIndex: 0, Encoding: OpcUa_ExtensionObjectEncoding_EncodeableObject, TimeZoneDataType: Offset: 0, DaylightSavingInOffset: 0|[7] = Locale: , Text: LowLimit|[8] = 0|[9] = i=17218|[10] = Locale: , Text: SafetyConditionClassType|[11] = Null|[12] = Null|[13] = LowLimit|[14] = Null|[15] = 1|[16] = Null|[17] = Locale: en, Text: Enabled|[18] = Good (0x00000000)|[19] = 0|[20] = Locale: en-US, Text: |[21] = |[22] = 1|[23] = 2025-03-11T09:32:45.064Z|[24] = Null|[25] = Locale: en, Text: Enabled|[26] = Locale: en, Text: Disabled|[27] = 2025-03-11T09:32:45.064Z|[28] = Null|[29] = 2025-03-11T10:21:17.737Z|[30] = Null|[31] = Null|[32] = Null|[33] = Null|[34] = Null|[35] = Null|[36] = Null|[37] = Null|[38] = Null|[39] = Null|[40] = Null|[41] = Locale: en, Text: Unacknowledged|[42] = Locale: en, Text: Confirmed|[43] = 0|[44] = 2025-03-11T10:21:21.308Z|[45] = Locale: en, Text: Acknowledged|[46] = Locale: en, Text: Unacknowledged|[47] = 1|[48] = 2025-03-11T10:21:21.308Z|[49] = Locale: en, Text: Confirmed|[50] = Locale: en, Text: Unconfirmed|[51] = Locale: en, Text: Active|[52] = ns=1;i=16009|[53] = Null|[54] = Null|[55] = 0|[56] = Null|[57] = Null|[58] = Null|[59] = Null|[60] = Null|[61] = Null|[62] = Null|[63] = Null|[64] = Null|[65] = Null|[66] = 1|[67] = 2025-03-11T10:21:21.308Z|[68] = Null|[69] = Locale: en, Text: Active|[70] = Locale: en, Text: Inactive|[71] = Null|[72] = Null|[73] = Locale: en, Text: Suppressed|[74] = Locale: en, Text: Unsuppressed|[75] = Null|[76] = Null|[77] = Locale: en, Text: Out of Service|[78] = Locale: en, Text: In Service|[79] = Null|[80] = Null|[81] = Null|[82] = Null|[83] = Null|[84] = Null|[85] = Null|[86] = Null|[87] = Locale: en, Text: Silenced|[88] = Locale: en, Text: Not Silenced|[89] = Null|[90] = Null|[91] = Locale: en, Text: Latched|[92] = Locale: en, Text: Unlatched|[93] = Null|[94] = Null|[95] = Null|[96] = Null|[97] = Null|[98] = Null|[99] = Null|[100] = Null|[101] = Null|[102] = Null|[103] = Null|[104] = Null|[105] = Null|[106] = Null|[107] = Null|[108] = Null|[109] = Null|[110] = Null|[111] = Null|[112] = Null|[113] = Null|[114] = Null|[115] = Null|[116] = Null|[117] = Null|[118] = Null|[119] = Null|[120] = Null|[121] = Null|[122] = Null|[123] = Null|[124] = Null|[125] = Null|[126] = Null|[127] = Null|[128] = Null|[129] = Null|[130] = Null|[131] = Null|[132] = Null|[133] = Null|[134] = Null|[135] = Null|[136] = Null|[137] = Null|[138] = Null|[139] = Null|[140] = Null|[141] = Null|[142] = Null|[143] = Null|[144] = Null|[145] = Null|[146] = Null|[147] = Null|[148] = ns=1;i=15011
Audit::PushAuditRecord - Thread and/or Subscription id is not initialized yet
AlarmCollector::Store Data ns=1;i=16009 SubscriptionId 20 item id 340
AlarmCollector::Store Data ns=1;i=16009 number of updates 1
Single Loop Event Type ns=1;i=11003 message Locale: , Text: LowLimit |
---|