freeswitch/spandsp

FreeSWITCH Crash (most likely in spandsp's t30.c)

Closed this issue · 2 comments

pragmatrix commented

Hi, one of our FreeSWITCH machines recently deadlocked or livelocked. No connections to the Event Socket port 8021 were accepted anymore and after a superficial analysis we are suspecting a bug in spandsp because the last line in the log indicates that a fax ECM frame was received of 3 bytes in length, which in turn caused a call to a memcpy with len == -1.

Here are the last few log entries:

2022-01-17 16:42:06.698682 [DEBUG] mod_spandsp_fax.c:295 FLOW FAX Set rx type 7
2022-01-17 16:42:06.698682 [DEBUG] mod_spandsp_fax.c:295 FLOW FAX Set tx type 0
2022-01-17 16:42:06.698682 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Start T2
2022-01-17 16:42:06.718682 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Carrier down (-1) in state F_DOC_ECM
2022-01-17 16:42:06.718682 [WARNING] mod_spandsp_fax.c:295 WARNING T.30 ECM carrier not found
2022-01-17 16:42:06.718682 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Status changing to Carrier lost during fax receive
2022-01-17 16:42:07.478681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_ECM
2022-01-17 16:42:07.478681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_ECM
2022-01-17 16:42:07.618681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Training failed (-5) in state F_DOC_ECM
2022-01-17 16:42:07.678681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Carrier down (-1) in state F_DOC_ECM
2022-01-17 16:42:07.678681 [WARNING] mod_spandsp_fax.c:295 WARNING T.30 ECM carrier not found
2022-01-17 16:42:07.678681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_ECM
2022-01-17 16:42:07.678681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Carrier down (-1) in state F_DOC_ECM
2022-01-17 16:42:07.678681 [WARNING] mod_spandsp_fax.c:295 WARNING T.30 ECM carrier not found
2022-01-17 16:42:07.678681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_ECM
2022-01-17 16:42:07.818681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Training in progress (-3) in state F_DOC_ECM
2022-01-17 16:42:07.838681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Training succeeded (-4) in state F_DOC_ECM
2022-01-17 16:42:07.838681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Abort (-8) in state F_DOC_ECM
2022-01-17 16:42:07.838681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Framing OK (-6) in state F_DOC_ECM
2022-01-17 16:42:07.838681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Start T1A
2022-01-17 16:42:07.858681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Bad HDLC CRC received
2022-01-17 16:42:07.858681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Bad HDLC CRC received
2022-01-17 16:42:07.878681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Bad HDLC CRC received
2022-01-17 16:42:07.878681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Abort (-8) in state F_DOC_ECM
2022-01-17 16:42:07.898681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Abort (-8) in state F_DOC_ECM
2022-01-17 16:42:07.978681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Bad HDLC CRC received
2022-01-17 16:42:07.978681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 HDLC signal status is Abort (-8) in state F_DOC_ECM
2022-01-17 16:42:08.038681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Stop T1A (278400 remaining)
2022-01-17 16:42:08.038681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Rx:  FCD without final frame tag
2022-01-17 16:42:08.038681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Rx:  ff 03 06
2022-01-17 16:42:08.038681 [DEBUG] mod_spandsp_fax.c:295 FLOW T.30 Storing ECM frame 97, length -1

The code in t30.c I suspect caused the problem:

spandsp/src/t30.c

Lines 3589 to 3590 in 284fe91

span_log(&s->logging, SPAN_LOG_FLOW, "Storing ECM frame %d, length %d\n", frame_no, len - 4);
memcpy(&s->ecm_data[frame_no][0], &msg[4], len - 4);

And the full spandsp related log:

spandsp-error.log

FreeSWITCH version was most likely version 1.10.6.. We are not 100% sure, because we have updated it to 1.10.7 right before reinstating the server again.

mjerris commented

please provide a backtrace of all threads and reopen this issue once it’s attached. this kind of issue can’t be reviewed without that info

pragmatrix commented

We don't have that backtrace now. We have to wait for another crash.

this kind of issue can’t be reviewed without that info

I disagree. The code path is fairly obvious from the log, and the memcpy above can't handle a Rx of size 3 and will most likely lead to UB. Building a test case should be fairly simple for someone accustomed with the code. I'll try my best as soon I've time for that.

  • 👍1