New subject: Calls getting stuck in playback application playing a tone_stream

26 Jan 2017

      I am having issues with calls getting stuck in the playback application.
This seems to happen only when the call is executing javascript with mod_v8
and the javascript calls some kind of sound playback on the channel.

We are currently on freeswitch 1.6.12-b91a0a6 on 64bit linux Debian Jessie,
Linux kernel 4.4.6.

Here is what a stuck call looks like:
bef33c54-66f2-4183-b281-35b5b9ade65f,inbound,2017-01-25
13:05:03,1485374703,sofia/external/###########@###.##.##.##,CS_EXECUTE,###########,###########,192.168.24.77,###########,playback,tone_stream://v=-7;>=10;+=.1;%(750,0,293.6,370.0,440.0);v=-7;>=5;+=.1;%(1500,250,293.6,370.0,440.0),XML,public,PCMU,8000,64000,PCMU,8000,64000,,laxvoip6,,,,ACTIVE,,,,,,,###########,###########,192.168.24.77,###########,XML,public

The most basic form of the javascript that causes this looks like this:

    if ( session.ready() ) {
        session.answer();
        var dtmf = session.getDigits(30, "*", 20*1000);
        var otherUUID = getDTMF(dtmf);
        session.execute("playback",
"tone_stream://v=-7;>=10;+=.1;%(750,0,293.6,370.0,440.0);v=-7;>=5;+=.1;%(1500,250,293.6,370.0,440.0)");
    }

99.9% of the calls that go through this path work fine, but about 1 in 1000
get stuck in this state.  And once this happens all messages from the far
side are ignored, including the BYE, and the media never times out even
though there is no data being transmitted anymore.

I have been able to get a core dump and this looks like the offending
threads bt:

#0  0x00007f0187361a9d in read () at ../sysdeps/unix/syscall-template.S:81
81    ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0  0x00007f0187361a9d in read () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f0187ef25b6 in _timerfd_next (timer=0x1bbdeb8) at
src/switch_time.c:474
#2  timer_next (timer=0x1bbdeb8) at src/switch_time.c:838
#3  0x00007f0187e27e78 in switch_core_timer_next (timer=<optimized out>) at
src/switch_core_timer.c:74
#4  0x00007f00fc1f07f4 in read_stream_thread (thread=0x51,
obj=0x7f00fc1364a0) at mod_local_stream.c:445
#5  0x00007f018811a840 in dummy_worker (opaque=0x1bbea40) at
threadproc/unix/thread.c:151
#6  0x00007f018735b064 in start_thread (arg=0x7f00fc137700) at
pthread_create.c:309
#7  0x00007f0186a3362d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:111
(gdb) thread 46
[Switching to thread 46 (Thread 0x7f00db373700 (LWP 9663))]
#0  0x00007f0187361e03 in recvfrom () at
../sysdeps/unix/syscall-template.S:81
81    ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0  0x00007f0187361e03 in recvfrom () at
../sysdeps/unix/syscall-template.S:81
#1  0x00007f01881184b5 in apr_socket_recvfrom (from=from@entry=0x7f015d2eb8c0,
sock=0x7f015d2ebb30, flags=0, buf=0x7efd6a066cf0 "\200",
len=0x7f00db36e230) at network_io/unix/sendrecv.c:155
#2  0x00007f0187e0f829 in switch_socket_recvfrom (from=0x7f015d2eb8c0,
sock=<optimized out>, flags=<optimized out>, buf=<optimized out>,
len=<optimized out>) at src/switch_apr.c:946
#3  0x00007f0187ea6198 in do_flush (force=<optimized out>,
bytes_in=139644540165635, bytes_in@entry=88, rtp_session=<optimized out>)
at src/switch_rtp.c:5111
#4  rtp_common_read (rtp_session=0x7efd6a05eb58,
payload_type=0x7efd6a066cf0 "\200", payload_type@entry=0x7f015d2dc984 "",
pmapP=0x4020, pmapP@entry=0x7f015d2dc9a8,
    flags=0x7f0187361e03 <recvfrom+51>, flags@entry=0x7f015d2dc998,
io_flags=2) at src/switch_rtp.c:6861
#5  0x00007f0187ea6cef in switch_rtp_zerocopy_read_frame
(rtp_session=0x7efd6a05eb58, frame=0x7f015d2dc940, io_flags=2) at
src/switch_rtp.c:7304
#6  0x00007f0187e5b023 in switch_core_media_read_frame
(session=0x7f015d2d32d8, frame=0x7f015d2dc2e8, flags=1563281800,
stream_id=-2026496509, stream_id@entry=0, type=SWITCH_MEDIA_TYPE_AUDIO)
    at src/switch_core_media.c:2184
#7  0x00007f016b1830a5 in sofia_read_frame (session=0x7f015d2d32d8,
frame=0x7f00db370760, flags=2, stream_id=0) at mod_sofia.c:1018
#8  0x00007f0187e45b2d in switch_core_session_read_frame
(session=0x7f015d2d32d8, frame=0x7f00db370760, flags=16416,
stream_id=-2026496509) at src/switch_core_io.c:175
#9  0x00007f0187ed133a in switch_ivr_play_file (session=0x7f015d2d32d8,
fh=0x7f00db370f40, file=0x7f00db370f00 "\300\004\363h\001\177",
args=0x7f0187361e03 <recvfrom+51>,
    args@entry=0x7f00db370f00) at src/switch_ivr_play_say.c:1822
#10 0x00007f0168f2a7b3 in playback_function (session=0x7f015d2d32d8,
data=<optimized out>) at mod_dptools.c:2831
#11 0x00007f0187e4036a in switch_core_session_exec (session=0x7f015d2d32d8,
application_interface=0x1abb0b8,
    arg=0x7efd69adf478
"tone_stream://v=-7;>=10;+=.1;%(750,0,293.6,370.0,440.0);v=-7;>=5;+=.1;%(1500,250,293.6,370.0,440.0)")
at src/switch_core_session.c:2784
#12 0x00007f00e3bdc1c8 in FSSession::ExecuteImpl (this=0x7efd5d9ca280,
info=...) at src/fssession.cpp:1391
#13 0x00007f00e3be03cd in FSSession::Execute (info=...) at
./include/fssession.hpp:125
#14 0x00007f00e347a619 in
v8::internal::FunctionCallbackArguments::Call(void
(*)(v8::FunctionCallbackInfo<v8::Value> const&)) () from
/usr/local/freeswitch/lib/libv8.so
#15 0x00007f00e3495b08 in v8::internal::Builtin_HandleApiCall(int,
v8::internal::Object**, v8::internal::Isolate*) () from
/usr/local/freeswitch/lib/libv8.so

Has anyone seen this before?

Let me know if there is any other information needed.

Thanks
Luke

Calls getting stuck in playback application playing a tone_stream

Luke Wahlmeier

Ken Rice

Luke Wahlmeier

Anthony Minessale

tags

participants (3)