[Freeswitch-users] Frequent connect/disconnect on PRI line leaves mod_freetdm in stuck state

[Deepika Agarwal]

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 1730113 2014-01-31 10:32:53.522513 [NOTICE]
mod_freetdm.c:1889 Alarm raised on channel 3:2230114 2014-01-31
10:32:53.522513 [INFO] ftmod_sangoma_isdn_stack_rcv.c:663 [SNGISDN PHY]
D-chan 3 : T1/E1/BRI Disconnected30115 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 at 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.

Please provide your comments in this regard and any further inputs would be
much appreciated.

Thanks
Deepika
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140206/9070e935/attachment.html