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

[pragmatrix]

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]

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]

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.