avd_imm_impl_set fails causing node reboot
It seems there may have been simultaneous IMM reinit threads running.
Nov 14 02:24:26 SC-2-2 osafamfd[4174]: NO Re-initializing with IMM
Nov 14 02:24:26 SC-2-2 osafamfd[4174]: NO Re-initializing with IMM
Nov 14 02:24:26 SC-2-2 osafimmnd[16412]: NO Implementer connected: 44 (safAmfService) <526, 2020f>
Nov 14 02:24:26 SC-2-2 osafamfd[4174]: NO Finished re-initializing with IMM
Nov 14 02:24:26 SC-2-2 osafamfd[4174]: ER saImmOiImplementerSet failed 14
Nov 14 02:24:26 SC-2-2 osafamfd[4174]: ER exiting since avd_imm_impl_set failed
Nov 14 02:24:26 SC-2-2 osafimmnd[16412]: NO Implementer locally disconnected. Marking it as doomed 44 <526, 2020f> (safAmfService)
Nov 14 02:24:26 SC-2-2 osafamfnd[4192]: WA AMF director unexpectedly crashed
Nov 14 02:24:26 SC-2-2 osafamfnd[4192]: Rebooting OpenSAF NodeId = 131599 EE Name = , Reason: local AVD down(Adest) or both AVD down(Vdest) received, OwnNodeId = 131599, SupervisionTime = 60
Nov 14 02:24:26 SC-2-2 osafimmnd[16412]: NO Implementer disconnected 44 <526, 2020f> (safAmfService)
Tickets: #2101
Tickets: #2188
Wiki: ChangeLog-5.0.2
Wiki: ChangeLog-5.1.1
Diff:
backtrace
Hi Gary,
In which scenario it is observed and please provide the traces.
Is this reproducible?
Thanks,
Praveen
Hi Praveen
It's rare but has occurred a few times. I've asked a tester to try and reproduce it with traces. I believe the test kills immnd causing BAD_HANDLE to be returned to AMF etc..
Last edit: Gary Lee 2016-11-15
Hi Gary,
From amfd-core.txt, it seems that avd_imm_reinit_bg() was called two times. This can happen when IMM returns BAD_HANDLE and AMFD calls avd_imm_reinit_bg() to init with in IMM in background. After this if again main thread tries to execute some job for IMM update, IMM will return BAD_HANDLE and AMFD will again call avd_imm_reinit_bg() to init with IMM.
Attached is a patch that will avoid multiple calls to avd_imm_reinit_bg().
Thanks,
Praveen
Hi Praveen
I think there might be problems with threads concurrently accessing avd_imm_status as it is not protected by a mutex. There are already some mutexes in avd_imm_reinit_bg_thread(). Are they supposed to prevent the original problem?
I'm not sure about this in avd_imm_reinit_bg():
It looks like there could be a race with the same code in avd_imm_reinit_bg_thread(). And saImmOiFinalize(0) is called, which could explain "saImmOiImplementerSet failed 14".
Last edit: Gary Lee 2016-11-18
Hi Gary,
In the patch #2188, cb->avd_imm_status in always accesses in main thread, so I think no protection is needed for it.
Also the check added in avd_imm_reinit_bg_thread() will prevent multiple threads running. avd_imm_reinit_bg_thread() is called from main thread only.
Thanks,
Praveen
Hi Praveen
Ah I see. Does that mean we can remove the mutexes?
Thanks
Hi Gary,
The mutexes are used in role.cc for IMM related handling during failovers and switchovers.
I think removal cannot be done so easily. But some refactoring can always be done based on approach taken for this ticket.
Thanks,
Praveen
Crash reported in the ticket "#2101 AMF: Heartbeat timeout observed after ImmNd restart" looks very much similar to this ticket.
With helps from Hung, I have seen 2 concurrent IMM reinit threads by adding delay in immpbe, log/trace is attached.
Below is snippet
2016-11-18 23:13:24 SC-1 osafamfd[488]: NO Re-initializing with IMM
2016-11-18 23:13:24 SC-1 osafimmnd[432]: WA IMMND - Client Node Get Failed for cli_hdl 115964248335
2016-11-18 23:13:24 SC-1 osafimmnd[432]: NO Implementer connected: 12 (safAmfService) <389, 2010f>
2016-11-18 23:13:24 SC-1 osafamfd[488]: NO Re-initializing with IMM
2016-11-18 23:13:24 SC-1 osafamfd[488]: NO Finished re-initializing with IMM
2016-11-18 23:13:24 SC-1 osafimmnd[432]: NO Implementer locally disconnected. Marking it as doomed 12 <389, 2010f> (safAmfService)
2016-11-18 23:13:24 SC-1 osafamfd[488]: ER exec: update FAILED 2
2016-11-18 23:13:24 SC-1 osafamfd[488]: WA saImmOiRtObjectUpdate of 'safSg=AmfDemoTwon,safApp=AmfDemoTwon' osafAmfSGSuOperationList failed with 2
2016-11-18 23:13:24 SC-1 osafamfd[488]: WA saImmOiRtObjectUpdate of 'safSg=AmfDemoTwon,safApp=AmfDemoTwon' osafAmfSGFsmState failed with 2
2016-11-18 23:13:24 SC-1 osafimmnd[432]: NO Implementer disconnected 12 <389, 2010f> (safAmfService)
2016-11-18 23:13:24 SC-1 osafimmnd[432]: NO Implementer connected: 13 (safAmfService) <390, 2010f>
2016-11-18 23:13:24 SC-1 osafamfd[488]: ER ERR_BAD_OPERATION: The SaImmOiHandleT is not associated with any implementer name
2016-11-18 23:13:24 SC-1 osafamfd[488]: WA saImmOiRtObjectUpdate of 'safSg=AmfDemoTwon,safApp=AmfDemoTwon' osafAmfSGSuOperationList failed with 20
2016-11-18 23:13:24 SC-1 osafamfd[488]: ER ERR_BAD_OPERATION: The SaImmOiHandleT is not associated with any implementer name
2016-11-18 23:13:24 SC-1 osafamfd[488]: WA saImmOiRtObjectUpdate of 'safSg=AmfDemoTwon,safApp=AmfDemoTwon' osafAmfSGFsmState failed with 20
2016-11-18 23:13:24 SC-1 osafamfd[488]: ER exec: update FAILED 2
2016-11-18 23:13:24 SC-1 osafimmnd[432]: WA Timeout on syncronous admin operation 1
2016-11-18 23:13:24 SC-1 osafamfd[488]: NO Finished re-initializing with IMM
In another run, I have seen "saImmOiImplementerSet failed 14", but logs were rotated
Below is log left from console
2016-11-18 22:37:27 SC-1 osafamfd[487]: NO Re-initializing with IMM
2016-11-18 22:37:27 SC-1 osafimmnd[431]: WA IMMND - Client Node Get Failed for cli_hdl 115964248335
2016-11-18 22:37:27 SC-1 osafimmnd[431]: NO Implementer connected: 12 (safAmfService) <471, 2010f>
2016-11-18 22:37:27 SC-1 osafamfd[487]: NO Re-initializing with IMM
2016-11-18 22:37:27 SC-1 osafamfd[487]: NO Finished re-initializing with IMM
2016-11-18 22:37:27 SC-1 osafamfd[487]: ER exec: update FAILED 2
2016-11-18 22:37:27 SC-1 osafimmnd[431]: NO Implementer locally disconnected. Marking it as doomed 12 <471, 2010f> (safAmfService)
2016-11-18 22:37:27 SC-1 osafamfd[487]: NO Re-initializing with IMM
2016-11-18 22:37:27 SC-1 osafimmnd[431]: NO Implementer disconnected 12 <471, 2010f> (safAmfService)
2016-11-18 22:37:27 SC-1 osafimmnd[431]: NO Implementer connected: 13 (safAmfService) <472, 2010f>
2016-11-18 22:37:27 SC-1 osafimmnd[431]: WA Timeout on syncronous admin operation 1
2016-11-18 22:37:27 SC-1 osafamfd[487]: NO Finished re-initializing with IMM
2016-11-18 22:37:27 SC-1 osafamfd[487]: ER saImmOiImplementerSet failed 14
2016-11-18 22:37:27 SC-1 osafamfd[487]: ER exiting since avd_imm_impl_set failed
2016-11-18 22:37:27 SC-1 osafamfnd[500]: WA AMF director unexpectedly crashed
2016-11-18 22:37:27 SC-1 osafamfnd[500]: Rebooting OpenSAF NodeId = 131343 EE Name = , Reason: local AVD down(Adest) or both AVD down(Vdest) received, OwnNodeId = 131343, SupervisionTime = 60
Hi Praveen,
Thanks for your patch, I think it could solve the problem of 2 concurrent init threads.
However, I have seen another problem when testing the patch, that it probably needs to handle:
During re-initializing IMM, the imm update will be lost:
- if it calls from avd_saImmOiRtObjectUpdate_sync()
- if it is a job that has IMM returned a code other than the ones are being handled in ImmObjUpdate::exec() , ie. SA_AIS_ERR_BAD_OPERATION
Thanks,
Minh
Agree with Minh, if avd_saImmOiRtObjectUpdate_sync() fails with BAD_HANDLE, we should call avd_saImmOiRtObjectUpdate() and queue the job as last resort.
The following in avd_imm_reinit_bg() should be removed:
`(void) saImmOiFinalize(avd_cb->immOiHandle);
avd_cb->immOiHandle = 0;
avd_cb->is_implementer = false;`
Hi Minh,
I have incorporated all the comments and published officially.
Please review and test it.
Thanks,
Praveen
attached trace tested with lastest patch
changeset: 8364:6813756d7af0
branch: opensaf-5.0.x
parent: 8361:904d3e1d9ab0
user: Praveen Malviya praveen.malviya@oracle.com
date: Fri Nov 25 15:55:39 2016 +0530
summary: amfd: do not spawn multiple threads for imm init[#2188] V2
changeset: 8365:1108027c16f0
branch: opensaf-5.1.x
parent: 8362:13742b479d92
user: Praveen Malviya praveen.malviya@oracle.com
date: Fri Nov 25 15:56:05 2016 +0530
summary: amfd: do not spawn multiple threads for imm init[#2188] V2
changeset: 8366:8584b74dd7ac
tag: tip
parent: 8363:6bf34589a464
user: Praveen Malviya praveen.malviya@oracle.com
date: Fri Nov 25 15:56:19 2016 +0530
summary: amfd: do not spawn multiple threads for imm init[#2188] V2
[staging:681375]
[staging:110802]
[staging:8584b7]
Related
Commit: [110802]
Commit: [681375]
Commit: [8584b7]
Tickets:
#2188Got a coredump
I think by somehow we got to put the below change back, it ensures the OI handle invalidated in main thread (so won't get a Dispatch()) before starting another background thread
Or maybe we don't Dispatch() while avd_imm_status is ON_GOING?
Hi Minh,
I guess this is happening in a very thin time window. When avd_imm_reinit_bg() spawns thread and comes out (thread has still not started finalization of handle). Now poll gets unblocked in main thread for imm event. So there will be race where thread will be finalizing the handle and Dispatch() also tries to use it.
I thinnk one solution is what you have suggest above. Other could be:
diff --git a/osaf/services/saf/amf/amfd/imm.cc b/osaf/services/saf/amf/amfd/imm.cc
--- a/osaf/services/saf/amf/amfd/imm.cc
+++ b/osaf/services/saf/amf/amfd/imm.cc
@@ -1969,7 +1969,7 @@ void avd_imm_reinit_bg(void)
return;
}
avd_cb->avd_imm_status = AVD_IMM_INIT_ONGOING;
-
+ avd_cb->imm_sel_obj = -1;
LOG_NO("Re-initializing with IMM");
We can use both also. Please share the traces if possbile. Based on that we can decide.
Thanks,
Praveen
Hi Praveen,
I think your fix can solve the coredump, but I am a bit worried the other places, where immOiHandle is accessed in mainthread upon other events, eg. failover, report_admin_op_error(), immutil_saImmOiXXX. To be safe I guess we could put the litlle change back, since it does call saImmOiFinalize() first
It was removed because it's executed twice in a row (second in avd_imm_reinit_bg_thread(), I guess. If that's not a big problem then can we leave it, or we can re-organize the while () loop in avd_imm_reinit_bg_thread()
Thanks,
Minh
Ah I will try to run the test and see, will post the trace if I hit it again
Retry the tests many times, but have not seen it