[Home]

Summary:ASTERISK-19853: CDR(custom_field) field set in a DYNAMIC_FEATURE is reverted to the previous value when the call is terminated.
Reporter:Philippe Lindheimer (p_lindheimer)Labels:
Date Opened:2012-05-08 17:07:09Date Closed:2013-11-14 16:42:21.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_cdr
Versions:1.8.11.1 10.2.1 Frequency of
Occurrence		Constant
Related
Issues:
Environment:FreePBX 2.10 or later systemAttachments:
Description:FreePBX uses it's own DYNAMIC_FEATURE for doing on-demand call recording, "*1" which previously used automixmon.

The specific bug is that a value set in a dynamic feature using the CDR(variable)=xyz function reverts back to the value that was set prior to the call being bridged when the call is hung up even though after the dynamic feature is pressed it can be confirmed that the value has in fact been properly set and present in the channel.

Repro:

- Enable on-demand recording on an extension but no record always settings
- Make a call
- press the *1 'start recording' button and confirm it started (check the CLI)
- now check the channel contents - 'core show channel SIP/702-xxxxxx' to confirm that CDR(recordingfile) was set properly.
- now hangup, check the DB and no value is set

The specific variable in question is CDR(recordingfile) and here are some snap-shot examples to demonstrate the behavior:

Partial Dialplan before call is bridged:

{noformat}
   -- Executing [s@sub-record-check:12] Set("SIP/702-000002c0", "__REC_STATUS=INITIALIZED") in new stack
   -- Executing [s@sub-record-check:13] Set("SIP/702-000002c0", "CDR(recordingfile)=INITIALIZED") in new stack
{noformat}

Partial dump of channel after call is bridged:

{noformat}
 CDR Variables:
level 1: dnid=9203760286
level 1: recordingfile=INITIALIZED
level 1: clid=702
level 1: src=702
{noformat}

Partial dialplan when DYNAMIC_FEATURE is being executed:

{noformat}
   -- Executing [s@macro-one-touch-record:16] Set("SIP/702-000002c0", "MASTER_CHANNEL(CDR(recordingfile))=out-9203761234-702-20120508-141552-1336511752.1205.wav") in new stack
   -- Executing [s@macro-one-touch-record:17] Set("SIP/702-000002c0", "CDR(recordingfile)=out-9203761234-702-20120508-141552-1336511752.1205.wav") in new stack
{noformat}

Now confirmation from a dump of the channel while the call is still active after the feature is pressed:

{noformat}
 CDR Variables:
level 1: recordingfile=out-9203761234-702-20120508-141552-1336511752.1205.wav
level 1: dnid=9203760286
level 1: clid=702
{noformat}

Now some debug code in the hangup macro showing what is in the CDR(recordingfile):

{noformat}
   -- Executing [h@macro-dialout-trunk:1] Macro("SIP/702-000002c0", "hangupcall,") in new stack
   -- Executing [s@macro-hangupcall:1] NoOp("SIP/702-000002c0", "recordingfile: INITIALIZED") in new stack
   -- Executing [s@macro-hangupcall:2] GotoIf("SIP/702-000002c0", "1?theend") in new stack
   -- Goto (macro-hangupcall,s,5)
   -- Executing [s@macro-hangupcall:5] Hangup("SIP/702-000002c0", "") in new stack
{noformat}

As can be seen it has reverted.

Further testing shows that IF we set a different channel variable during the dynamic feature execution and then IN the hangup macro we set CDR(recordingfile) to that variable, that it is then properly stored in the database, and also confirms that the channel variable survives the hangup macro and does not revert unlike the CDR(recordingfile)
Comments:By: Matt Jordan (mjordan) 2013-11-05 17:14:19.307-0600

So, there's no question this is a bug, and a strange one to boot.

This problem can be reproduced by doing the following:

# In any mid-call event (such as a dynamic feature), set a CDR property on a channel
# After the call, the CDR property will be gone in the {{h}} extension
# After the {{h}} extension, the CDR property set on the channel during the mid-call event will be written out to the CDR logs

The reason for all of this is murky at best, but almost assuredly involves logic attempting to clean up the affects of masquerades. In {{features.c}}, the following occurs:

# Prior to the channels being bridged, the CDR on the channel is dup'd into {{bridge_cdr}}. Any forked CDRs are removed from {{bridge_cdr}}:
{noformat}
ast_set_flag(chan_cdr, AST_CDR_FLAG_MAIN);
ast_cdr_update(chan);
bridge_cdr = ast_cdr_dup_unique_swap(chan_cdr);
/* rip any forked CDR's off of the chan_cdr and attach
* them to the bridge_cdr instead */
bridge_cdr->next = chan_cdr->next;
chan_cdr->next = NULL;
{noformat}
# The CDR on the channel is manipulated during the in call event. The {{bridge_cdr}} is not updated as a result.
# Things get really weird when the bridge breaks. If we're going to run an {{h}} extension on the channel - or a hangup handler - we put the {{bridge_cdr}} back on the channel, restoring its CDR state prior to it entering into the bridge while it is in the handler.
{noformat}
/* run the hangup exten on the chan object IFF it was NOT involved in a parking situation
* if it were, then chan belongs to a different thread now, and might have been hung up long
* ago.
*/
if (!(ast_channel_softhangup_internal_flag(chan) & (AST_SOFTHANGUP_ASYNCGOTO | AST_SOFTHANGUP_UNBRIDGE))
&& !ast_test_flag(&config->features_caller, AST_FEATURE_NO_H_EXTEN)) {

ast_channel_lock(chan);
if (bridge_cdr) {
/*
* Swap the bridge_cdr and the chan cdr for a moment, and let
* the hangup dialplan code operate on it.
*/
swapper = ast_channel_cdr(chan);
ast_channel_cdr_set(chan, bridge_cdr);

/* protect the lastapp/lastdata against the effects of the hangup/dialplan code */
ast_copy_string(savelastapp, bridge_cdr->lastapp, sizeof(bridge_cdr->lastapp));
ast_copy_string(savelastdata, bridge_cdr->lastdata, sizeof(bridge_cdr->lastdata));
}
{noformat}
# Finally, once the {{h}} extension and hangup handlers have run, we put the original CDR back onto the channel:
{noformat}
ast_channel_lock(chan);

/* swap it back */
ast_channel_context_set(chan, save_context);
ast_channel_exten_set(chan, save_exten);
ast_channel_priority_set(chan, save_prio);
if (bridge_cdr) {
if (ast_channel_cdr(chan) == bridge_cdr) {
ast_channel_cdr_set(chan, swapper);

/* Restore the lastapp/lastdata */
ast_copy_string(bridge_cdr->lastapp, savelastapp, sizeof(bridge_cdr->lastapp));
ast_copy_string(bridge_cdr->lastdata, savelastdata, sizeof(bridge_cdr->lastdata));
} else {
bridge_cdr = NULL;
}
}
ast_channel_unlock(chan);
{noformat}
This results in the wrong value being in the {{h}} extension and/or hangup handlers, but the correct value being written to the CDR backends.

I'm pretty sure this incredibly stupid logic was put in place to handle the case where a channel is transferred and a masquerade occurs on the channel that originally had the CDR. In that case, the original CDR would have been copied over to the new channel and the channel being run in the {{h}} extension/hangup handler would have no CDR information - so the {{bridge_cdr}} - which was the original state - was put on it. Unfortunately, it's a bad solution at best, as it doesn't contain information that occurred during the bridge.

It's also incredibly brittle. Either we don't do this swapping - in which case, someone depending on its behavior will break (and we'll probably also break CDRs in blind/attended transfers) - or we copy the variables explicitly so that the values are present in the hangup logic. The problem with the second approach is that there could *still* conceivably be a conflict, if someone did masquerade the channel after we changed the variable mid-bridge. You'd end up with the values from some channel that didn't really belong to you.

To quote the code just a few lines later:

{noformat}
/*
* If the channel CDR has been modified during the call, record
* the changes in the bridge cdr, BUT, if hangup_run, the CDR
* got swapped so don't overwrite what was done in the
* h-extension or hangup handlers.  What a mess.  This is why
* you never touch CDR code.
*/
{noformat}

As it is, this problem doesn't exist in Asterisk 12. In that version, none of this crap happens. Channels don't get masqueraded, and we don't attempt to move channel CDR information around from one channel to another. A CDR is associated with a channel that is the Party A in the record, and that's it. Period.

As such, given the risk of this change - and the fact that you already successfully worked around it - I'm inclined to close this as "fixed" in Asterisk 12. Let me know if that's okay - if not, I can analyze this some more and try to find a patch that doesn't break this behavior in 1.8/11.
By: David Woolley (davidw) 2013-11-06 05:43:19.722-0600

Having worked round similar problems in the past and having looked at the code, I would favour waiting for the Asterisk 12 fix.  (I think we forced out the CDR in the h extension, by using ResetCDR, but that doesn't help here.
By: Matt Jordan (mjordan) 2013-11-06 08:08:28.071-0600

FreePBX is currently working around the problem by using a channel variable to store the property, then setting it in the {{h}} extension as well as in a macro executed by the dynamic feature. If I'm reading the code correctly, if you don't need to make a decision based on the value in the {{h}} extension but simply want to record the value in the CDR, you shouldn't have to do anything - the correct value *should* get stored. In FreePBX's case, however, this value tracks information about call recording, so some logical decisions are made in the {{h}} extension. Using a channel variable is a valid work around in that case.
By: Philippe Lindheimer (p_lindheimer) 2013-11-13 16:05:54.224-0600

Given the complexity of a fix and the fact that FreePBX has a workaround for this bug that's been in production for a long time, I have no problems deferring the fix to Asterisk 12 and leaving our work around in FreePBX.