test samples/sip_cancel.js occasional crash

[MayamaTakeshi]

takeshi@takeshi-desktop:sip-lab$ node samples/sip_cancel.js
...ABRIDGED...
14:10:56.771         sip_endpoint.c  Processing incoming message: Request msg CANCEL/cseq=17669 (rdata0x7fe52aca33f8)
14:10:56.771      dlg0x7fe52ad27c58  .Received Request msg CANCEL/cseq=17669 (rdata0x7fe52aca33f8)
14:10:56.771      tsx0x7fe52accdd88  ...Transaction created for Request msg CANCEL/cseq=17669 (rdata0x7fe52aca33f8)
14:10:56.771      tsx0x7fe52accdd88  ..Incoming Request msg CANCEL/cseq=17669 (rdata0x7fe52aca33f8) in state Null
14:10:56.771      tsx0x7fe52accdd88  ...State changed from Null to Trying, event=RX_MSG
14:10:56.771      dlg0x7fe52ad27c58  ....Transaction tsx0x7fe52accdd88 state changed to Trying
14:10:56.771             sip_util.c  .....Response msg 200/CANCEL/cseq=17669 (tdta0x7fe52acce598) created
14:10:56.771      dlg0x7fe52ad27c58  ......Sending Response msg 200/CANCEL/cseq=17669 (tdta0x7fe52acce598)
14:10:56.771      tsx0x7fe52accdd88  ......Sending Response msg 200/CANCEL/cseq=17669 (tdta0x7fe52acce598) in state Trying
14:10:56.771      tsx0x7fe52accdd88  .......State changed from Trying to Completed, event=TX_MSG
14:10:56.771      dlg0x7fe52ad27c58  ........Transaction tsx0x7fe52accdd88 state changed to Completed
14:10:56.771      dlg0x7fe52ad27c58  ......Sending Response msg 487/INVITE/cseq=17669 (tdta0x7fe52acddd38)
14:10:56.771      tsx0x7fe530742718  ......Sending Response msg 487/INVITE/cseq=17669 (tdta0x7fe52acddd38) in state Proceeding
14:10:56.771      tsx0x7fe530742718  .......State changed from Proceeding to Completed, event=TX_MSG
14:10:56.771      dlg0x7fe52ad27c58  ........Transaction tsx0x7fe530742718 state changed to Completed
14:10:56.771      inv0x7fe52ad27c58  .........State changed from EARLY to DISCONNECTED, event=TSX_STATE
on_state_changed

e->type=5
inv->state=6
call will terminate call=0x7fe52acd9728

close_media call_id=1
Segmentation fault (core dumped)
takeshi@takeshi-desktop:sip-lab$

This is easily reproducible with a few tries.

[MayamaTakeshi]

The problem is that we get invalid data when we try to access msg len and buf:

    char evt[2048];
    int sip_msg_len = 0;
    char *sip_msg = (char *)"";
    if (e->type == PJSIP_EVENT_TSX_STATE) {
      sip_msg_len = e->body.rx_msg.rdata->msg_info.len;
      sip_msg = e->body.rx_msg.rdata->msg_info.msg_buf;
    }

    printf("call_id=%i sip_msg_len=%i sip_msg=%p\n", call_id, sip_msg_len, sip_msg);
    make_evt_call_ended(evt, sizeof(evt), call_id, sip_msg_len, sip_msg);
    dispatch_event(evt);

close_media call_id=1
call_id=1 sip_msg_len=0 sip_msg=0x40000000000
Segmentation fault (core dumped)
takeshi@takeshi-desktop:sip-lab$ node samples/sip_cancel.js 

close_media call_id=1
call_id=1 sip_msg_len=-1574164581 sip_msg=0x71d41ed5c3bf
Segmentation fault (core dumped)
takeshi@takeshi-desktop:sip-lab$ 

[MayamaTakeshi]

I tried updating to latest pjproject commit c36802585ddefb3ca477d1f6d773d179510c5412 but issue persists:

close_media call_id=1
call_id=1 sip_msg_len=1600941153 sip_msg=0x6322202c2265736e
Segmentation fault (core dumped)
takeshi@takeshi-desktop:sip-lab$ 

[MayamaTakeshi]

Actually our code was dying due to a bug when calling printf in event_templates.cpp:

   printf("make_evt_call_ended sip_msg_len=%i sip_msg=%s\n", sip_msg_len,
          sip_msg);

We will not be able to report the message body but at least there will be no crash.