[FS-9776] SIP Transfer generates high CPU Created: 28/Nov/16  Updated: 28/Dec/16  Resolved: 28/Dec/16

Status: Resolved
Project: FreeSWITCH
Component/s: mod_sofia
Affects Version/s: 1.6
Fix Version/s: None

Type: Improvement Priority: Minor
Reporter: Stéphane Alnet Assignee: Mike Jerris
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment: Debian/testing

Attachments: Text File freeswitch.log    
CPU Architecture:
x86-64
Kernel:
Linux
Userland:
GNU/Linux
Distribution:
Debian
Distribution Version:
Debian 7 wheezy
Compiler:
gcc
FreeSWITCH GIT Revision: 7884bee06a1089d97131017565c6efc58083d0f6
GIT Master Revision hash:: 7884bee06a1089d97131017565c6efc58083d0f6

 Description   
If I set ringback to

  tone_stream://%(300,10000,440);loops=-1

then during a blind transfer FreeSwitch will

  [NOTICE] switch_ivr.c:2167 Transfer sofia/huge-play-sbc-egress/12@test.centrex.phone.kwaoo.net to inline[endless_playback:
tone_stream://%(300,10000,440);loops=-1,park@refer]

which then leads to

  EXECUTE sofia/huge-play-sbc-egress/12@test.centrex.phone.kwaoo.net endless_playback(tone_stream://%(300)

(notice how the end of the `tone_stream` is missing) and then to

  [DEBUG] switch_ivr_play_say.c:1911 done playing file tone_stream://%(300

repeatedly for as long as the call is ringing, because the `while` loop in endless_playback_function attempts to (unsuccesfully) execute the command, eventually leading to high CPU.

The basic issue is that the parsing for the `inline` dialplan in mod_dptools.c uses the comma `,` as default delimiters, and strips the end of the tone_stream command when sending it to endless_playback.

I'm opening the issues against mod_sofia because I believe the root cause of the problem to be the `endless_playback` command created at line 8681 of sofia.c, with limited control over how it is built.

It could be useful for example that the separator be specified (apparently the inline dialplan allows for `m:!:` where `!` is the separator, see mod_dptools.c line 76, if I read it properly) and sofia.c could then say (for example)

  "endless_playback:m:!:%s!park"

instead of

  "endless_playback:%s,park"

(I'm using `!` as an exemple, a different separator might be a better solution.)

Workaround: use `silence` or another string that does not contain a comma as your ringback tone.

 Comments   
Comment by Stéphane Alnet [ 28/Nov/16 ]
Ahem, obviously it is the music-on-hold which is set to `tone_stream`, not the ringback.
Comment by Mike Jerris [ 28/Nov/16 ]
what is the exact setting you are using?
Comment by Stéphane Alnet [ 29/Nov/16 ]
The application code would set `hold_music` to `tone_stream://%(300,10000,440);loops=-1`
Comment by Mike Jerris [ 29/Nov/16 ]
please show me THE EXACT setting you are using. How are you setting this?
Comment by Brian West [ 29/Nov/16 ]
set your hold music to \'tone_stream://%(300,10000,440);loops=-1\'

That'll probably fix it.

/b
Comment by Stéphane Alnet [ 29/Nov/16 ]
freeswitch.log: fsctl loglevel 7 + fsctl debug_level 7 + sofia global siptrace on

This debug file shows a single incoming call going to extension 12 which then attempts a blind transfer to extension 10.
Comment by Stéphane Alnet [ 29/Nov/16 ]
Brian -- adding single quotes fails with: 2016-11-29 22:33:14.453118 [ERR] switch_core_file.c:264 Invalid file format ['tone_stream] for [%(300,10000,440);loops=-1']!

Mike, this is set using an application over ESL, the backquotes are not included. The command is:

   export(hold_music=tone_stream://%(300,10000,440);loops=-1)

I've attached a console debug (freeswitch.log; fsctl loglevel 7 + fsctl debug_level 7 + sofia global siptrace on); that debug shows a single incoming call going to extension 12 which then attempts a blind transfer to extension 10. In freeswitch.log, the command that sets the variable is shown on line 415, the sofia command that starts the music-on-hold during the transfer is on line 1630, the problem is exhibited starting line 1777.
Comment by Mike Jerris [ 29/Nov/16 ]
after you 've set the var via esl... use uuid_getvar to see exactly what was set and if its correct or not. I suspect the escaping is colliding with whatever language you are using to create the export command in esl.
Comment by Stéphane Alnet [ 29/Nov/16 ]
Mike -- the variable is properly set and works if the call is placed on hold instead of transfered. I'll go ahead and get the value with uuid_getvar still.

IMHO the issue happens after sofia.c does (line 8681):

        if (moh) {
                char *xdest;
                xdest = switch_core_session_sprintf(a_session, "endless_playback:%s,park", moh);
                switch_ivr_session_transfer(a_session, xdest, "inline", NULL);
        }

and the inline dialplan tries to parse

       endless_playback:tone_stream://%(300,10000,440);loops=-1,park

which it does by splitting on commas (by default), which leads to the first section being interpreted as

       endless_playback:tone_stream://%(300

which is what is shown in the log.
Comment by Brian West [ 29/Nov/16 ]
You may actually have to do \\' depending on how may levels deep that all happens.
Comment by Stéphane Alnet [ 30/Nov/16 ]
I'm working on a PR to test this fully.
Comment by Mike Jerris [ 13/Dec/16 ]
any update on this?
Comment by Stéphane Alnet [ 13/Dec/16 ]
This is still on my list. I haven't been able / had time to rebuild FS to test my fix because of the libssl issues in Debian, which I'm working on in a separate Jira.
Comment by Stéphane Alnet [ 22/Dec/16 ]
OK, created PR https://freeswitch.org/stash/projects/FS/repos/freeswitch/pull-requests/1122/overview for this.

Tested (master + FS-9785 (required for compilation) + FS-9776) and the fix works as expected; the `inline` dialplan properly parses

```
2016-12-22 23:26:34.276189 [NOTICE] switch_ivr.c:2196 Transfer sofia/huge-play-sbc-ingress/336434827…@178.250.209.… to inline[m:":endless_playback:tone_stream://%(300,10000,440);loops=-1"park@transfer-162d2eb9-9bb5-4678-a849-dff13a59f42d]
```

and executes

```
EXECUTE sofia/huge-play-sbc-ingress/336434827…@178.250.209.… endless_playback(tone_stream://%(300,10000,440);loops=-1)
```

However I noticed the `park` command is not executed, and thinking of it, I'm wondering whether it is needed after `endless_playback` (I guess `endless_playback` might fail and we need a fallback situation?).

I guess the only item that might be left open to discussion is whether the double-quote is the best separator in this patch.
Comment by Brian West [ 28/Dec/16 ]
I reviewed and " makes sense there just in case ! is used in teletone, I fixed both locations.

Thanks,

/b
Generated at Mon Oct 23 19:11:37 CDT 2017 using JIRA 7.3.3#73014-sha1:d5be8da522213be2ca9ad7b043c51da6e4cc9754.