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

Sat Feb 8 04:57:35 MSK 2014

Greetings,
	If you could, please mail the list or Moy, not both, He subscribes to this list too and now any responses he gives may not make it back to the list if he doesn’t do reply-all.  This leaves someone down the line six months from now hanging when they encounter the exact same issue and this email is in the archive standing all by itself.

You would need to provide these items:

1. WANPIPE Verison
2. LibSNG Version
3. FreeSWITCH Git revision
4. Distro information.
5. 32/64 bit CPU?

These should give anyone reading the list a bit more situational awareness of your issue and possible lead to a few more questions or even suggestions on what you might try.  As it stands we can only guess that it could be hardware, software, sunspots or worse… DUST BUNNIES!  :P

In addition log files should be posted in the paste bin if possible.  You can also hop on IRC and get assistance.

--
Brian West
brian at freeswitch.org
FreeSWITCH Solutions, LLC
PO BOX 2531
Brookfield, WI 53008-2531
Twitter: @FreeSWITCH , @briankwest
http://www.freeswitchbook.com
http://www.freeswitchcookbook.com

T: +1.918.420.9001  |  F: +1.918.420.9002  |  M: +1.918.424.WEST
iNUM: +883 5100 1420 9001
ISN: 410*543
Skype:briankwest
PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED)

On Feb 6, 2014, at 6:29 AM, Deepika Agarwal <deepika.agarwal at eng.knowlarity.com> wrote:

> 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 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 --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 841 bytes
Desc: Message signed with OpenPGP using GPGMail
Url : http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140207/3f9f5baf/attachment.bin 