Hello All,
We are facing a peculiar problem in which the frequent connect/disconnect events on the PRI line results in FreeSwitch not able to handle any further incoming calls.
The workaround to the above problem is to
restart mod_freetdm or the complete freeswitch.
I'm providing some of the logs with my analysis:
30111 2014-01-31 10:32:53.522513 [NOTICE] mod_freetdm.c:1889 Alarm raised on channel 13:15
30112 2014-01-31 10:32:53.522513 [DEBUG] ftmod_wanpipe.c:1630 [s3c7][3:7] read wanpipe event 17
30113 2014-01-31 10:32:53.522513 [NOTICE] mod_freetdm.c:1889 Alarm raised on channel 3:22
30114 2014-01-31 10:32:53.522513 [INFO] ftmod_sangoma_isdn_stack_rcv.c:663 [SNGISDN PHY] D-chan 3 : T1/E1/BRI Disconnected
30115 2014-01-31 10:32:53.522513 [DEBUG] mod_freetdm.c:2416 got clear channel sig [ALARM_TRAP]
30116 2014-01-31 10:32:53.522513 [DEBUG] ftmod_wanpipe.c:1385 [s3c7][3:7] Ignoring wanpipe link disconnected event
30117 2014-01-31 10:32:53.522513 [INFO] ftmod_sangoma_isdn_stack_rcv.c:663 [SNGISDN PHY] D-chan 3 : T1/E1/BRI Disconnected
30118 2014-01-31 10:32:53.522513 [DEBUG] mod_freetdm.c:2416 got clear channel sig [ALARM_TRAP]
30119 2014-01-31 10:32:53.522513 [DEBUG] ftmod_wanpipe.c:1630 [s3c8][3:8] read wanpipe event 17
30313 2014-01-31 10:32:53.682516 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1004 sng_isdn->s16: Invalid Q.921/Q.931 frame - ignoring len:1
30314 2014-01-31 10:32:53.722506 [DEBUG] mod_freetdm.c:866 Dropping frame! (write note ready) in channel FreeTDM/3:8/43850327 device 3:8!
30315 2014-01-31 10:32:53.722506 [DEBUG] mod_freetdm.c:866 Dropping frame! (write note ready) in channel FreeTDM/3:4/43850118 device 3:4!
30316 2014-01-31 10:32:53.722506 [DEBUG] ftmod_wanpipe.c:945 [s14c11][14:11] Rx Queue length exceeded 80% hreshold (9/10)
30317 2014-01-31 10:32:53.722506 [DEBUG] ftmod_wanpipe.c:945 [s23c11][23:11] Rx Queue length exceeded 80% hreshold (9/10)
30318 2014-01-31 10:32:53.722506 [DEBUG] mod_freetdm.c:866 Dropping frame! (write note ready) in channel FreeTDM/3:5/43851158 device 3:5!
30319 2014-01-31 10:32:53.722506 [DEBUG] ftmod_wanpipe.c:945 [s24c2][24:2] Rx Queue length exceeded 80% hreshold (9/10)
30320 2014-01-31 10:32:53.722506 [DEBUG] mod_freetdm.c:866 Dropping frame! (write note ready) in channel FreeTDM/3:6/43850118 device 3:6!
30321 2014-01-31 10:32:53.722506 [DEBUG] ftmod_wanpipe.c:945 [s6c17][6:18] Rx Queue length exceeded 80% hreshold (9/10)
30322 2014-01-31 10:32:53.742514 [DEBUG] mod_freetdm.c:866 Dropping frame! (write note ready) in channel FreeTDM/3:3/43850523 device 3:3!
30323 2014-01-31 10:32:53.762508 [WARNING] mod_freetdm.c:763 Too many timeouts while waiting I/O in channel FreeTDM/3:6/43850118 device 3:6!
30324 2014-01-31 10:32:53.762508 [ERR] mod_freetdm.c:808 clearing IO in channel FreeTDM/3:6/43850118 device 3:6!
30325 2014-01-31 10:32:53.762508 [WARNING] mod_freetdm.c:763 Too many timeouts while waiting I/O in channel FreeTDM/3:1/43852488 device 3:1!
30326 2014-01-31 10:32:53.762508 [ERR] mod_freetdm.c:808 clearing IO in channel FreeTDM/3:1/43852488 device 3:1!
Because of the timeout in the read channel, the TFLAG_IO gets cleared and leads to a recurrent logs w.r.t the TFLAG_IO flag (as shown in line 30413)
30403 2014-01-31 10:32:53.762508 [WARNING] mod_freetdm.c:763 Too many timeouts while waiting I/O in channel FreeTDM/3:8/43850327 device 3:8!
30404 2014-01-31 10:32:53.762508 [ERR] mod_freetdm.c:808 clearing IO in channel FreeTDM/3:8/43850327 device 3:8!
30405 2014-01-31 10:32:53.762508 [DEBUG] switch_ivr_bridge.c:505 FreeTDM/3:8/43850327 ending bridge by request from read function
30406 2014-01-31 10:32:53.762508 [WARNING] mod_freetdm.c:763 Too many timeouts while waiting I/O in channel FreeTDM/3:4/43850118 device 3:4!
30407 2014-01-31 10:32:53.762508 [ERR] mod_freetdm.c:808 clearing IO in channel FreeTDM/3:4/43850118 device 3:4!
30408 2014-01-31 10:32:53.762508 [DEBUG] switch_ivr_bridge.c:505 FreeTDM/3:4/43850118 ending bridge by request from read function
30409 2014-01-31 10:32:53.762508 [WARNING] mod_freetdm.c:763 Too many timeouts while waiting I/O in channel FreeTDM/3:10/43115865 device 3:10!
30410 2014-01-31 10:32:53.762508 [ERR] mod_freetdm.c:808 clearing IO in channel FreeTDM/3:10/43115865 device 3:10!
30411 2014-01-31 10:32:53.762508 [DEBUG] switch_ivr_play_say.c:1678 done playing file /srv/sounds/usr/159d/0491/-a6f/0-48/e4-8/1df-/1823/c766/9 6e8.mp3
30412 2014-01-31 10:32:53.762508 [DEBUG] switch_ivr_play_say.c:1306 Codec Activated L16@8000hz 1 channels 20ms
30413 2014-01-31 10:32:53.762508 [DEBUG] mod_freetdm.c:747 TFLAG_IO is not set in channel FreeTDM/3:10/43115865 device 3:10!30414 2014-01-31 10:32:53.762508 [ERR] mod_freetdm.c:808 clearing IO in channel FreeTDM/3:10/43115865 device 3:10!
Upon further looking at the code, it appears that the TFLAG_IO gets cleared because of the timeout (as a result of PRI connect/disconnect), but as this flag is not inturn set upon PRI line recovery, the channel_read_frame (in mod_freetdm.c) is not able to read any further frames.