#1273 AMF : dependent SIs are assigned, if sponsor SI assignment fails,

[Srikanth R]

Version : 4.6 FC
model : 2n
configuration : 1App,1SG,2SUs with 4comps each, 4SIs with 1 CSI each
si-si deps configured as SI1 is sponsor to SI2,3,&4.
SU1 is mapped to pl-3 and SU2 to pl-4
saAmfSGAutoRepair=1(True)
SuFailover=0(False)
component recovery policy - 3 (comp failover)
SG is brought down to locked state and all the SUs are SIs are in unlocked state

Issue : Dependent SIs are assigned, if sponsor SI assignment fails

Steps performed :

1) Before unlocking SG, ensure that component receiving sponsor SI rejects the active assignment.

2) When the SG is unlocked, component 1 of SU1 shall receive the csi callback of the sponsor and the component rejects the callback.

Observation & anomaly :

1) Even though the component 1 of SU1 is not able to take sponsor assignment, component2,3 and 4 of SU1 got CSI assignments for SI2, SI3 and SI4 ( which are dependent on unassigned sponsor SI1 )

2) Later CSI assignments for comp2,comp3 and comp4 of SU1 are removed as part of comp failover and components of SU2 are assigned properly with sponsor SI1 getting assigned first and later followed by dependent SIs.

Below is the syslog from PL-3 :

ar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI1,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO SU failover probation timer started (timeout: 1200000000000 ns)
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Performing failover of 'safSu=SU1,safSg=SG,safApp=test2nApp' (SU failover count: 1)
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO 'safComp=COMP1,safSu=SU1,safSg=SG,safApp=test2nApp' faulted due to 'csiSetcallbackFailed' : Recovery is 'componentFailover'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO 'safSu=SU1,safSg=SG,safApp=test2nApp' Presence State INSTANTIATED => TERMINATING
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigned 'safSi=SI1,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI2,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI3,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI4,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigned 'safSi=SI2,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigned 'safSi=SI3,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigned 'safSi=SI4,safApp=test2nApp' ACTIVE to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removing 'all (4) SIs' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removing 'safSi=SI1,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removing 'safSi=SI2,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removing 'safSi=SI3,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removing 'safSi=SI4,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removed 'safSi=SI1,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removed 'safSi=SI2,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removed 'safSi=SI3,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removed 'safSi=SI4,safApp=test2nApp' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:48 SYSTEST-PLD-1 osafamfnd[1895]: NO Removed 'all SIs' from 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO 'safSu=SU1,safSg=SG,safApp=test2nApp' Presence State TERMINATING => INSTANTIATED
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI1,safApp=test2nApp' STANDBY to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI2,safApp=test2nApp' STANDBY to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI3,safApp=test2nApp' STANDBY to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigning 'safSi=SI4,safApp=test2nApp' STANDBY to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigned 'safSi=SI4,safApp=test2nApp' STANDBY to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigned 'safSi=SI3,safApp=test2nApp' STANDBY to 'safSu=SU1,safSg=SG,safApp=test2nApp'
Mar 19 16:34:49 SYSTEST-PLD-1 osafamfnd[1895]: NO Assigned 'safSi=SI2,safApp=test2nApp' STANDBY to 'safSu=SU1,safSg=SG,safApp=test2nApp'

Below is the list of callbacks and flow of the operations from the journal :
=================:Performing operation Setting callbackType as 1 on safComp=COMP1,safSu=SU1,safSg=SG,safApp=test2nApp :=================
=================:Performing operation Setting response 21 on safComp=COMP1,safSu=SU1,safSg=SG,safApp=test2nApp :=================
=================:Performing operation unlock on safSg=SG,safApp=test2nApp :=================
3 19 16:34:48.197946 safComp=COMP1,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI1,safSi=SI1,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.230025 safComp=COMP1,safSu=SU1,safSg=SG,safApp=test2nApp UnRegistered
3 19 16:34:48.270640 safComp=COMP2,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI2,safSi=SI2,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.273532 safComp=COMP3,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI3,safSi=SI3,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.277232 safComp=COMP4,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI4,safSi=SI4,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.293886 safComp=COMP3,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSIREMOVE_CALLBACK', 'csiName': '', 'prevCsiAssigned': ['safCsi=CSI3,safSi=SI3,safApp=test2nApp']}
3 19 16:34:48.295144 safComp=COMP4,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSIREMOVE_CALLBACK', 'csiName': '', 'prevCsiAssigned': ['safCsi=CSI4,safSi=SI4,safApp=test2nApp']}
3 19 16:34:48.304954 safComp=COMP2,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSIREMOVE_CALLBACK', 'csiName': '', 'prevCsiAssigned': ['safCsi=CSI2,safSi=SI2,safApp=test2nApp']}
3 19 16:34:48.324604 safComp=COMP1,safSu=SU2,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI1,safSi=SI1,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.363418 safComp=COMP2,safSu=SU2,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI2,safSi=SI2,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.365529 safComp=COMP3,safSu=SU2,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI3,safSi=SI3,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.368614 safComp=COMP1,safSu=SU1,safSg=SG,safApp=test2nApp Registered
3 19 16:34:48.369101 safComp=COMP4,safSu=SU2,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_ACTIVE_CALLBACK', 'csiName': 'safCsi=CSI4,safSi=SI4,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.449215 safComp=COMP3,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_STANDBY_CALLBACK', 'csiName': 'safCsi=CSI3,safSi=SI3,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.453592 safComp=COMP4,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_STANDBY_CALLBACK', 'csiName': 'safCsi=CSI4,safSi=SI4,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.459336 safComp=COMP2,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_STANDBY_CALLBACK', 'csiName': 'safCsi=CSI2,safSi=SI2,safApp=test2nApp', 'prevCsiAssigned': []}
3 19 16:34:48.469925 safComp=COMP1,safSu=SU1,safSg=SG,safApp=test2nApp DataReceived {'DATA': 'CSISET_STANDBY_CALLBACK', 'csiName': 'safCsi=CSI1,safSi=SI1,safApp=test2nApp', 'prevCsiAssigned': []}

[Srikanth R]

The similar issue is observed for AMF / CLM node unlock operation ( with the SG / SI / SU in unlocked state ) and sponsor SI unlock operation ( with the remaining entities in unlocked state)

[Praveen]

This issue is reproducible on 4.4 GA changeset:
parent: 5042:2dec93c82bf0 4.4.GA.

Attached are AMF traces and syslog in 1273.tgz after reproducing on 4.4 GA.

[Praveen]

I have verified, #1259 solves this problem also.