Occasional crash when running 'node samples/pcma.js'

[MayamaTakeshi]

12:31:27.436  
12:31:27.436  Trying match against expected_events[0]:
12:31:27.436    partial_match({
    event: 'reinvite',
    call_id: 1
  })
12:31:27.437  Match successful
12:31:27.437  
12:31:27.437  wait (pcma.js:92) got expected event:
12:31:27.437    {
    event: 'reinvite',
    call_id: 1,
    msg: 'INVITE sip:sip-lab@127.0.0.1:5061 SIP/2.0\r\n' +
  'Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj79fef73d-c80f-427a-bbea-30f4c0fc2b33\r\n' +
  'Max-Forwards: 70\r\n' +
  'From: sip:alice@test.com;tag=5a3013be-d6f2-4e01-a24a-9c9e95127030\r\n' +
  'To: sip:bob@127.0.0.1;tag=cb336822-2bde-47cd-868c-2587083f5de2\r\n' +
  'Contact: <sip:sip@127.0.0.1:5060>\r\n' +
  'Call-ID: 88bd280e-fe2a-4368-b5fd-1f6a6e43803a\r\n' +
  'CSeq: 18968 INVITE\r\n' +
  'Allow: MESSAGE, SUBSCRIBE, NOTIFY, REFER, INVITE, ACK, BYE, CANCEL, UPDATE\r\n' +
  'Supported: replaces\r\n' +
  'Content-Type: application/sdp\r\n' +
  'Content-Length:   245\r\n' +
  '\r\n' +
  'v=0\r\n' +
  'o=- 3925942287 3925942287 IN IP4 0.0.0.0\r\n' +
  's=pjmedia\r\n' +
  't=0 0\r\n' +
  'm=audio 10000 RTP/AVP 8 120\r\n' +
  'c=IN IP4 127.0.0.1\r\n' +
  'b=TIAS:64000\r\n' +
  'a=rtcp:10001 IN IP4 127.0.0.1\r\n' +
  'a=sendrecv\r\n' +
  'a=rtpmap:8 PCMA/8000\r\n' +
  'a=rtpmap:120 telephone-event/8000\r\n' +
  'a=fmtp:120 0-16\r\n'
  }
12:31:27.437  All expected events received
12:31:27.437  wait (pcma.js:92) finished
pjw_call_respond: call_id=1 json={"code":200,"reason":"OK"}

json_get_string_param reason
process_media call_id=1
i=0 media found

process_media call_id=1 call->local_sdp: v=0
o=- 3925942287 3925942287 IN IP4 0.0.0.0
s=pjmedia
t=0 0
m=audio 10002 RTP/AVP 8 120
c=IN IP4 127.0.0.1
b=TIAS:64000
a=rtcp:10003 IN IP4 127.0.0.1
a=sendrecv
a=rtpmap:8 PCMA/8000
a=rtpmap:120 telephone-event/8000
a=fmtp:120 0-16

on_media_update

call_id=1
on_media_update call_id=1 active local_sdp: v=0
o=- 3925942287 3925942288 IN IP4 0.0.0.0
s=pjmedia
t=0 0
m=audio 10002 RTP/AVP 8 120
c=IN IP4 127.0.0.1
b=TIAS:64000
a=rtcp:10003 IN IP4 127.0.0.1
a=sendrecv
a=rtpmap:8 PCMA/8000
a=rtpmap:120 telephone-event/8000
a=fmtp:120 0-16

on_media_update call_id=1 active remote_sdp: v=0
o=- 3925942287 3925942287 IN IP4 0.0.0.0
s=pjmedia
t=0 0
m=audio 10000 RTP/AVP 8 120
c=IN IP4 127.0.0.1
b=TIAS:64000
a=rtcp:10001 IN IP4 127.0.0.1
a=sendrecv
a=rtpmap:8 PCMA/8000
a=rtpmap:120 telephone-event/8000
a=fmtp:120 0-16

call_id=1 restart_media_stream: stream characteristics no change
audio_endpoint_remove_port
node: ../src/pj/os_core_unix.c:1436: pj_mutex_lock: Assertion `mutex' failed.

Thread 11 "clock" received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffcd9fc640 (LWP 42190)]
__pthread_kill_implementation (no_tid=0, signo=6, threadid=140736643188288) at ./nptl/pthread_kill.c:44
44  ./nptl/pthread_kill.c: No such file or directory.
(gdb) bt
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=140736643188288) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=140736643188288) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=140736643188288, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007ffff7842476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007ffff78287f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007ffff782871b in __assert_fail_base (fmt=0x7ffff79dd130 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x7ffff4e04089 "mutex", 
    file=0x7ffff4e2ad33 "../src/pj/os_core_unix.c", line=1436, function=<optimized out>) at ./assert/assert.c:92
#6  0x00007ffff7839e96 in __GI___assert_fail (assertion=assertion@entry=0x7ffff4e04089 "mutex", file=file@entry=0x7ffff4e2ad33 "../src/pj/os_core_unix.c", line=line@entry=1436, 
    function=function@entry=0x7ffff4e2b130 <__PRETTY_FUNCTION__.9> "pj_mutex_lock") at ./assert/assert.c:101
#7  0x00007ffff4d1515d in pj_mutex_lock (mutex=<optimized out>) at ../src/pj/os_core_unix.c:1436
#8  0x00007ffff4cb2144 in get_frame (port=0x5c950e8, frame=0x7fffcd9fbc60) at ../src/pjmedia/stream.c:554
#9  0x00007ffff4ca0dfc in read_port (type=<synthetic pointer>, count=160, frame=<optimized out>, cport=0x5c9a270, conf=0x5c99260) at ../src/pjmedia/conference.c:1588
#10 get_frame (this_port=<optimized out>, frame=0x7fffcd9fbcd0) at ../src/pjmedia/conference.c:2042
#11 0x00007ffff4ca5fb3 in clock_callback (ts=0x5c9a230, user_data=0x5c9b498) at ../src/pjmedia/master_port.c:193
#12 0x00007ffff4cc154b in clock_thread (arg=0x5c9a210) at ../src/pjmedia/clock_thread.c:391
#13 0x00007ffff4d15498 in thread_main (param=0x5c72c48) at ../src/pj/os_core_unix.c:701
#14 0x00007ffff7894ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#15 0x00007ffff7926850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
(gdb) bt full
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=140736643188288) at ./nptl/pthread_kill.c:44
        tid = <optimized out>
        ret = 0
        pd = 0x7fffcd9fc640
        old_mask = {__val = {140736347507668, 140736347507568, 140736347507668, 0, 0, 0, 0, 0, 550822543707, 0, 1071251456, 0, 1072508315, 372577457275977216, 18446744073709551615, 
            372577457275977216}}
        ret = <optimized out>
        pd = <optimized out>
        old_mask = <optimized out>
        ret = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
        resultvar = <optimized out>
        resultvar = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
        __futex = <optimized out>
        resultvar = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
        __futex = <optimized out>
        __private = <optimized out>
        __oldval = <optimized out>
        result = <optimized out>
#1  __pthread_kill_internal (signo=6, threadid=140736643188288) at ./nptl/pthread_kill.c:78
No locals.
#2  __GI___pthread_kill (threadid=140736643188288, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
No locals.
#3  0x00007ffff7842476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
        ret = <optimized out>
#4  0x00007ffff78287f3 in __GI_abort () at ./stdlib/abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x7fffbc000b70, sa_sigaction = 0x7fffbc000b70}, sa_mask = {__val = {16, 140736347507568, 2147483647, 4, 140737347683562, 0, 0, 
              140736643185056, 372577457275977216, 0, 18446744073709551248, 0, 140737301884211, 1436, 140737301725321, 97096288}}, sa_flags = -141929389, 
          sa_restorer = 0x7ffff7a17600 <_IO_file_jumps>}
        sigs = {__val = {32, 140737347958432, 140737301884211, 1436, 140737301725321, 97096288, 140736643188288, 140737346267374, 206158430256, 140736643185280, 206158430232, 
            140736643185280, 140736643185072, 372577457275977216, 140737488346791, 140737347684002}}
#5  0x00007ffff782871b in __assert_fail_base (fmt=0x7ffff79dd130 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x7ffff4e04089 "mutex", 
    file=0x7ffff4e2ad33 "../src/pj/os_core_unix.c", line=1436, function=<optimized out>) at ./assert/assert.c:92
        str = 0x7fffbc000b70 ""
        total = 4096
#6  0x00007ffff7839e96 in __GI___assert_fail (assertion=assertion@entry=0x7ffff4e04089 "mutex", file=file@entry=0x7ffff4e2ad33 "../src/pj/os_core_unix.c", line=line@entry=1436, 
    function=function@entry=0x7ffff4e2b130 <__PRETTY_FUNCTION__.9> "pj_mutex_lock") at ./assert/assert.c:101
--Type <RET> for more, q to quit, c to continue without paging--
No locals.
#7  0x00007ffff4d1515d in pj_mutex_lock (mutex=<optimized out>) at ../src/pj/os_core_unix.c:1436
        status = <optimized out>
        __PRETTY_FUNCTION__ = "pj_mutex_lock"
#8  0x00007ffff4cb2144 in get_frame (port=0x5c950e8, frame=0x7fffcd9fbc60) at ../src/pjmedia/stream.c:554
        stream = 0x5c948d8
        channel = 0x5c98b70
        samples_count = <optimized out>
        samples_per_frame = <optimized out>
        samples_required = <optimized out>
        p_out_samp = <optimized out>
        status = <optimized out>
        __PRETTY_FUNCTION__ = "get_frame"
#9  0x00007ffff4ca0dfc in read_port (type=<synthetic pointer>, count=160, frame=<optimized out>, cport=0x5c9a270, conf=0x5c99260) at ../src/pjmedia/conference.c:1588
        f = {type = PJMEDIA_FRAME_TYPE_AUDIO, buf = 0x5c9b4d0, size = 320, timestamp = {u32 = {lo = 1280, hi = 0}, u64 = 1280}, bit_info = 0}
        status = <optimized out>
        __PRETTY_FUNCTION__ = "read_port"
        f = <optimized out>
        status = <optimized out>
        samples_req = <optimized out>
        f = <optimized out>
        status = <optimized out>
        src_count = <optimized out>
#10 get_frame (this_port=<optimized out>, frame=0x7fffcd9fbcd0) at ../src/pjmedia/conference.c:2042
        status = <optimized out>
        frame_type = <optimized out>
        conf_port = 0x5c9a270
        level = 0
        conf = 0x5c99260
        speaker_frame_type = PJMEDIA_FRAME_TYPE_NONE
        ci = <optimized out>
        cj = <optimized out>
        i = 1
        j = <optimized out>
        p_in = <optimized out>
        __PRETTY_FUNCTION__ = "get_frame"
#11 0x00007ffff4ca5fb3 in clock_callback (ts=0x5c9a230, user_data=0x5c9b498) at ../src/pjmedia/master_port.c:193
        m = 0x5c9b498
        frame = {type = PJMEDIA_FRAME_TYPE_NONE, buf = 0x5c9b4d0, size = 320, timestamp = {u32 = {lo = 1440, hi = 0}, u64 = 1440}, bit_info = 0}
        status = <optimized out>
#12 0x00007ffff4cc154b in clock_thread (arg=0x5c9a210) at ../src/pjmedia/clock_thread.c:391
        now = {u32 = {lo = 2322518126, hi = 4901}, u64 = 21051957235822}
        clock = 0x5c9a210
#13 0x00007ffff4d15498 in thread_main (param=0x5c72c48) at ../src/pj/os_core_unix.c:701
        rec = <optimized out>
        result = <optimized out>
        rc = <optimized out>
        __PRETTY_FUNCTION__ = "thread_main"
#14 0x00007ffff7894ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
        ret = <optimized out>
        pd = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737488317712, 9131951491889639090, 140736643188288, 98, 140737346357200, 140737488318064, -9131982550885060942, 
                -9131933981679538510}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#15 0x00007ffff7926850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.
(gdb) 

However, this is not specific to PCMA (samples/g729.js can also cause this). This is just the easiest way to reproduce this issue (as the script is short and doesn't wait for lengthy operations like dtmf detection).

Commit: 73030106bea75db7c208edce73bed10fd95a542d

[MayamaTakeshi]

The assertion failure happens from HERE:

static pj_status_t get_frame( pjmedia_port *port, pjmedia_frame *frame)
{
    pjmedia_stream *stream = (pjmedia_stream*) port->port_data.pdata;
    pjmedia_channel *channel = stream->dec;
    unsigned samples_count, samples_per_frame, samples_required;
    pj_int16_t *p_out_samp;
    pj_status_t status;

    /* Return no frame is channel is paused */
    if (channel->paused) {
        frame->type = PJMEDIA_FRAME_TYPE_NONE;
        return PJ_SUCCESS;
    }

    if (stream->soft_start_cnt) {
        if (stream->soft_start_cnt == PJMEDIA_STREAM_SOFT_START) {
            PJ_LOG(4,(stream->port.info.name.ptr,
                      "Resetting jitter buffer in stream playback start"));
            pj_mutex_lock( stream->jb_mutex );
            pjmedia_jbuf_reset(stream->jb);
            pj_mutex_unlock( stream->jb_mutex );
        }
        --stream->soft_start_cnt;
        frame->type = PJMEDIA_FRAME_TYPE_NONE;
        return PJ_SUCCESS;
    }

    /* Repeat get frame from the jitter buffer and decode the frame
     * until we have enough frames according to codec's ptime.
     */

    /* Lock jitter buffer mutex first */
    pj_mutex_lock( stream->jb_mutex ); // HERE (pjmedia/src/pjmedia/stream.c:554)

So it is likely, the stream object might have been discarded at that point and the working thread is still using it.