We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call. I appreciate any insights or advice on tracking this down. Here are the logs for the call from SIP extension 903 to 1239xxxxxxx via PRI span 1, channel 20. The WARNING is near the end: EXECUTE sofia/internal/903@192.168.1.20:5060 bridge(freetdm/1/A/1239xxxxxxx) 2010-11-05 10:18:21.094993 [DEBUG] switch_core_session.c:1919 sofia/internal/903@192.168.1.20:5060 receive message [APPLICATION_EXEC] 2010-11-05 10:18:21.094993 [INFO] ftmod_zt.c:636 Setting echo cancel to 64 taps for 1:20 2010-11-05 10:18:21.094993 [DEBUG] mod_freetdm.c:377 Set codec PCMU 20ms 2010-11-05 10:18:21.094993 [DEBUG] mod_freetdm.c:1334 Connect outbound channel FreeTDM/1:20/1239xxxxxxx 2010-11-05 10:18:21.094993 [NOTICE] switch_channel.c:784 New Channel FreeTDM/1:20/1239xxxxxxx [4d47f77d-6591-40c1-94e5-73da4e5e157a] 2010-11-05 10:18:21.094993 [DEBUG] mod_freetdm.c:1348 (FreeTDM/1:20/1239xxxxxxx) State Change CS_NEW -> CS_INIT 2010-11-05 10:18:21.094993 [DEBUG] switch_core_session.c:1057 Send signal FreeTDM/1:20/1239xxxxxxx [BREAK] 2010-11-05 10:18:21.094993 [DEBUG] ftmod_libpri.c:92 [s1c20][1:20] Changed state from DOWN to DIALING 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:318 (FreeTDM/1:20/1239xxxxxxx) Running State Change CS_INIT 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:342 (FreeTDM/1:20/1239xxxxxxx) State INIT 2010-11-05 10:18:21.095991 [DEBUG] mod_freetdm.c:405 (FreeTDM/1:20/1239xxxxxxx) State Change CS_INIT -> CS_ROUTING 2010-11-05 10:18:21.095991 [DEBUG] switch_core_session.c:1057 Send signal FreeTDM/1:20/1239xxxxxxx [BREAK] 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:342 (FreeTDM/1:20/1239xxxxxxx) State INIT going to sleep 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:318 (FreeTDM/1:20/1239xxxxxxx) Running State Change CS_ROUTING 2010-11-05 10:18:21.095991 [DEBUG] switch_channel.c:1615 (FreeTDM/1:20/1239xxxxxxx) Callstate Change DOWN -> RINGING 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:345 (FreeTDM/1:20/1239xxxxxxx) State ROUTING 2010-11-05 10:18:21.095991 [DEBUG] mod_freetdm.c:428 FreeTDM/1:20/1239xxxxxxx CHANNEL ROUTING 2010-11-05 10:18:21.095991 [DEBUG] switch_ivr_originate.c:66 (FreeTDM/1:20/1239xxxxxxx) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2010-11-05 10:18:21.095991 [DEBUG] switch_core_session.c:1057 Send signal FreeTDM/1:20/1239xxxxxxx [BREAK] 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:345 (FreeTDM/1:20/1239xxxxxxx) State ROUTING going to sleep 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:318 (FreeTDM/1:20/1239xxxxxxx) Running State Change CS_CONSUME_MEDIA 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:364 (FreeTDM/1:20/1239xxxxxxx) State CONSUME_MEDIA 2010-11-05 10:18:21.095991 [DEBUG] switch_core_state_machine.c:364 (FreeTDM/1:20/1239xxxxxxx) State CONSUME_MEDIA going to sleep 2010-11-05 10:18:21.097993 [DEBUG] switch_ivr_originate.c:1079 sofia/internal/903@192.168.1.20:5060 receive message [PROGRESS] 2010-11-05 10:18:21.101999 [INFO] switch_ivr_originate.c:1079 Sending early media 2010-11-05 10:18:21.101999 [DEBUG] sofia_glue.c:2961 AUDIO RTP [sofia/internal/903@192.168.1.20:5060] 192.168.1.20 port 17872 -> 192.168.1.194 port 3000 codec: 0 ms: 30 2010-11-05 10:18:21.101999 [DEBUG] switch_rtp.c:1418 Starting timer [soft] 240 bytes per 30ms 2010-11-05 10:18:21.104067 [DEBUG] sofia_glue.c:3179 Set 2833 dtmf send payload to 101 2010-11-05 10:18:21.104067 [DEBUG] sofia_glue.c:3184 Set 2833 dtmf receive payload to 101 2010-11-05 10:18:21.104067 [DEBUG] mod_sofia.c:2169 Ring SDP: v=0 o=FreeSWITCH 1288948829 1288948830 IN IP4 192.168.1.20 s=FreeSWITCH c=IN IP4 192.168.1.20 t=0 0 m=audio 17872 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:30 a=sendrecv 2010-11-05 10:18:21.104067 [NOTICE] mod_sofia.c:2172 Pre-Answer sofia/internal/903@192.168.1.20:5060! 2010-11-05 10:18:21.104067 [DEBUG] switch_channel.c:2544 (sofia/internal/903@192.168.1.20:5060) Callstate Change RINGING -> EARLY 2010-11-05 10:18:21.104067 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/903@192.168.1.20:5060 [BREAK] 2010-11-05 10:18:21.104067 [DEBUG] switch_ivr_originate.c:1128 Raw Codec Activation Success L16@8000hz 1 channel 30ms 2010-11-05 10:18:21.104067 [DEBUG] switch_core_codec.c:116 sofia/internal/903@192.168.1.20:5060 Push codec L16:10 2010-11-05 10:18:21.104067 [DEBUG] switch_ivr_originate.c:1193 Play Ringback Tone [%(2000,4000,440.0,480.0)] 2010-11-05 10:18:21.104994 [DEBUG] sofia.c:4564 Channel sofia/internal/903@192.168.1.20:5060 skipping state [early][183] 2010-11-05 10:18:21.109994 [DEBUG] switch_core_io.c:723 sofia/internal/903@192.168.1.20:5060 receive message [TRANSCODING_NECESSARY] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:466 1:20 STATE [DIALING] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 -- Making new call for cref 34100 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > DL-DATA request 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Protocol Discriminator: Q.931 (8) len=52 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > TEI=0 Call Ref: len= 2 (reference 1332/0x534) (Sent from originator) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Message Type: SETUP (5) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 TEI=0 Transmitting N(S)=121, window is open V(A)=121 K=7 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > V(A)=121, V(S)=121, V(R)=15 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > T200_id=0, N200=3, T203_id=1 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > [ 00 01 f2 1e 08 02 05 34 05 04 03 80 90 a2 18 03 a1 83 94 28 07 b1 41 20 57 61 72 64 6c 0c 00 81 37 30 36 33 34 38 34 33 30 38 70 0c 80 31 32 33 39 36 34 32 38 36 38 37 ] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Informational frame: 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > SAPI: 00 C/R: 0 EA: 0 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > TEI: 000 EA: 1 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > N(S): 121 0: 0 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > N(R): 015 P: 0 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > 52 bytes of data 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Protocol Discriminator: Q.931 (8) len=52 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > TEI=0 Call Ref: len= 2 (reference 1332/0x534) (Sent from originator) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Message Type: SETUP (5) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > [04 03 80 90 a2] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > User information layer 1: u-Law (34) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > [18 03 a1 83 94] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 Preferred Dchan: 0 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > ChanSel: As indicated in following octets 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Ext: 1 Coding: 0 Number Specified Channel Type: 3 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Ext: 1 Channel: 20 Type: CPE] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > [28 07 b1 41 20 57 61 72 64] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Display (len= 7) Charset: 31 [ A Ward ] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > [6c 0c 00 81 37 30 36 33 34 38 34 33 30 38] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Calling Number (len=14) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Presentation: Presentation permitted, user number passed network screening (1) '706xxxxxxx' ] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > [70 0c 80 31 32 33 39 36 34 32 38 36 38 37] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 > Called Number (len=14) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '1239xxxxxxx' ] 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 -- Stopping T203 timer 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 -- Starting T200 timer 2010-11-05 10:18:21.145993 [DEBUG] ftmod_libpri.c:143 q931.c:4959 q931_setup: Call 34100 enters state 1 (Call Initiated). Hold state: Idle 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < V(A)=121, V(S)=122, V(R)=15 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < T200_id=1, N200=3, T203_id=0 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < [ 00 01 01 f4 ] 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < Supervisory frame: 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < SAPI: 00 C/R: 0 EA: 0 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < TEI: 000 EA: 1 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < N(R): 122 P/F: 0 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 < 0 bytes of data 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 -- Got ACK for N(S)=121 to (but not including) N(S)=122 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 -- ACKing N(S)=121, txqueue head is N(S)=-1 (-1 is empty, -2 is not transmitted) 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 -- Stopping T200 timer 2010-11-05 10:18:21.168073 [DEBUG] ftmod_libpri.c:143 -- Starting T203 timer 2010-11-05 10:18:21.169069 [DEBUG] ftmod_libpri.c:143 Done handling message for SAPI/TEI=0/0 2010-11-05 10:18:21.293134 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:21.293134 [DEBUG] ftmod_libpri.c:143 < TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:21.293134 [DEBUG] ftmod_libpri.c:143 < V(A)=122, V(S)=122, V(R)=15 2010-11-05 10:18:21.293134 [DEBUG] ftmod_libpri.c:143 < K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:21.293134 [DEBUG] ftmod_libpri.c:143 < T200_id=0, N200=3, T203_id=1 2010-11-05 10:18:21.293134 [DEBUG] ftmod_libpri.c:143 < [ 02 01 1e f4 08 02 85 34 02 18 03 a9 83 94 ] 2010-11-05 10:18:21.293134 [DEBUG] ftmod_libpri.c:143 < Informational frame: 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < SAPI: 00 C/R: 1 EA: 0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < TEI: 000 EA: 1 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < N(S): 015 0: 0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < N(R): 122 P: 0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < 10 bytes of data 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < Protocol Discriminator: Q.931 (8) len=10 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < TEI=0 Call Ref: len= 2 (reference 1332/0x534) (Sent to originator) 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < Message Type: CALL PROCEEDING (2) 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < [18 03 a9 83 94] 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 Exclusive Dchan: 0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < ChanSel: As indicated in following octets 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < Ext: 1 Coding: 0 Number Specified Channel Type: 3 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 < Ext: 1 Channel: 20 Type: CPE] 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 Received message for call 0x2aaac801ff90 on 0x8e45f70 TEI/SAPI 0/0, call->pri is 0x8e45f70 TEI/SAPI 0/0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 -- Processing IE 24 (cs0, Channel Identification) 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 q931.c:6998 post_handle_q931_message: Call 34100 enters state 3 (Outgoing Call Proceeding). Hold state: Idle 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 -- Got ACK for N(S)=122 to (but not including) N(S)=122 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 -- T200 requested to stop when not started 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 T203 requested to start without stopping first 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 -- Starting T203 timer 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > V(A)=122, V(S)=122, V(R)=16 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > T200_id=0, N200=3, T203_id=1 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > [ 02 01 01 20 ] 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > Supervisory frame: 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > SAPI: 00 C/R: 1 EA: 0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > TEI: 000 EA: 1 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > N(R): 016 P/F: 0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 > 0 bytes of data 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:143 Done handling message for SAPI/TEI=0/0 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:757 -- Proceeding on channel 1:20 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:758 [s1c20][1:20] Changed state from DIALING to PROGRESS_MEDIA 2010-11-05 10:18:21.294064 [DEBUG] ftmod_libpri.c:466 1:20 STATE [PROGRESS_MEDIA] 2010-11-05 10:18:21.294064 [DEBUG] mod_freetdm.c:2048 got clear channel sig [PROGRESS_MEDIA] 2010-11-05 10:18:21.294064 [NOTICE] mod_freetdm.c:2097 Pre-Answer FreeTDM/1:20/1239xxxxxxx! 2010-11-05 10:18:21.294064 [DEBUG] switch_channel.c:2544 (FreeTDM/1:20/1239xxxxxxx) Callstate Change RINGING -> EARLY 2010-11-05 10:18:21.294064 [DEBUG] switch_channel.c:2588 Send signal sofia/internal/903@192.168.1.20:5060 [BREAK] 2010-11-05 10:18:21.320116 [DEBUG] switch_core_codec.c:141 sofia/internal/903@192.168.1.20:5060 Restore previous codec PCMU:0. 2010-11-05 10:18:21.320116 [DEBUG] switch_ivr_originate.c:3333 Originate Resulted in Success: [FreeTDM/1:20/1239xxxxxxx] 2010-11-05 10:18:21.320116 [DEBUG] switch_ivr.c:196 FreeTDM/1:20/1239xxxxxxx receive message [AUDIO_SYNC] 2010-11-05 10:18:21.320116 [DEBUG] switch_ivr.c:196 sofia/internal/903@192.168.1.20:5060 receive message [AUDIO_SYNC] 2010-11-05 10:18:21.320116 [DEBUG] switch_ivr_bridge.c:1175 FreeTDM/1:20/1239xxxxxxx receive message [BRIDGE] 2010-11-05 10:18:21.320116 [DEBUG] switch_core_session.c:676 Send signal FreeTDM/1:20/1239xxxxxxx [BREAK] 2010-11-05 10:18:21.320116 [DEBUG] switch_ivr_bridge.c:1182 sofia/internal/903@192.168.1.20:5060 receive message [BRIDGE] 2010-11-05 10:18:21.320116 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/903@192.168.1.20:5060 [BREAK] 2010-11-05 10:18:21.320116 [DEBUG] switch_ivr_bridge.c:1226 (FreeTDM/1:20/1239xxxxxxx) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2010-11-05 10:18:21.320116 [DEBUG] switch_core_session.c:1057 Send signal FreeTDM/1:20/1239xxxxxxx [BREAK] 2010-11-05 10:18:21.320116 [DEBUG] switch_core_state_machine.c:318 (FreeTDM/1:20/1239xxxxxxx) Running State Change CS_EXCHANGE_MEDIA 2010-11-05 10:18:21.320116 [DEBUG] switch_core_state_machine.c:355 (FreeTDM/1:20/1239xxxxxxx) State EXCHANGE_MEDIA 2010-11-05 10:18:21.320116 [DEBUG] mod_freetdm.c:569 CHANNEL EXCHANGE_MEDIA 2010-11-05 10:18:21.340108 [DEBUG] switch_core_io.c:723 sofia/internal/903@192.168.1.20:5060 receive message [TRANSCODING_NECESSARY] 2010-11-05 10:18:21.340108 [DEBUG] switch_core_io.c:970 Engaging Write Buffer at 480 bytes to accommodate 320->480 2010-11-05 10:18:21.410086 [DEBUG] switch_rtp.c:2544 Correct ip/port confirmed. 2010-11-05 10:18:21.410086 [DEBUG] switch_core_io.c:723 FreeTDM/1:20/1239xxxxxxx receive message [TRANSCODING_NECESSARY] 2010-11-05 10:18:21.410086 [DEBUG] switch_core_io.c:970 Engaging Write Buffer at 320 bytes to accommodate 480->320 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < V(A)=122, V(S)=122, V(R)=16 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < T200_id=0, N200=3, T203_id=1 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < [ 02 01 20 f4 08 02 85 34 01 1e 02 82 88 ] 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < Informational frame: 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < SAPI: 00 C/R: 1 EA: 0 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < TEI: 000 EA: 1 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < N(S): 016 0: 0 2010-11-05 10:18:23.093023 [DEBUG] ftmod_libpri.c:143 < N(R): 122 P: 0 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 < 9 bytes of data 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 < Protocol Discriminator: Q.931 (8) len=9 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 < TEI=0 Call Ref: len= 2 (reference 1332/0x534) (Sent to originator) 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 < Message Type: ALERTING (1) 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 < [1e 02 82 88] 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2) 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 Received message for call 0x2aaac801ff90 on 0x8e45f70 TEI/SAPI 0/0, call->pri is 0x8e45f70 TEI/SAPI 0/0 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 -- Processing IE 30 (cs0, Progress Indicator) 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 q931.c:6888 post_handle_q931_message: Call 34100 enters state 4 (Call Delivered). Hold state: Idle 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 -- Got ACK for N(S)=122 to (but not including) N(S)=122 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 -- T200 requested to stop when not started 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 T203 requested to start without stopping first 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 -- Starting T203 timer 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > V(A)=122, V(S)=122, V(R)=17 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > T200_id=0, N200=3, T203_id=1 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > [ 02 01 01 22 ] 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > Supervisory frame: 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > SAPI: 00 C/R: 1 EA: 0 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > TEI: 000 EA: 1 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > N(R): 017 P/F: 0 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 > 0 bytes of data 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:143 Done handling message for SAPI/TEI=0/0 2010-11-05 10:18:23.094018 [DEBUG] ftmod_libpri.c:782 -- Ringing on channel 1:20 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < V(A)=122, V(S)=122, V(R)=17 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < T200_id=0, N200=3, T203_id=1 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < [ 02 01 22 f4 08 02 85 34 07 ] 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < Informational frame: 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < SAPI: 00 C/R: 1 EA: 0 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < TEI: 000 EA: 1 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < N(S): 017 0: 0 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < N(R): 122 P: 0 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < 5 bytes of data 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < Protocol Discriminator: Q.931 (8) len=5 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < TEI=0 Call Ref: len= 2 (reference 1332/0x534) (Sent to originator) 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 < Message Type: CONNECT (7) 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 Received message for call 0x2aaac801ff90 on 0x8e45f70 TEI/SAPI 0/0, call->pri is 0x8e45f70 TEI/SAPI 0/0 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 q931.c:6919 post_handle_q931_message: Call 34100 enters state 10 (Active). Hold state: Idle 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 > DL-DATA request 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 > Protocol Discriminator: Q.931 (8) len=5 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 > TEI=0 Call Ref: len= 2 (reference 1332/0x534) (Sent from originator) 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 > Message Type: CONNECT ACKNOWLEDGE (15) 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 TEI=0 Transmitting N(S)=122, window is open V(A)=122 K=7 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 > TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:32.293205 [DEBUG] ftmod_libpri.c:143 > V(A)=122, V(S)=122, V(R)=18 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > T200_id=0, N200=3, T203_id=1 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > [ 00 01 f4 24 08 02 05 34 0f ] 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > Informational frame: 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > SAPI: 00 C/R: 0 EA: 0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > TEI: 000 EA: 1 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > N(S): 122 0: 0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > N(R): 018 P: 0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > 5 bytes of data 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > Protocol Discriminator: Q.931 (8) len=5 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > TEI=0 Call Ref: len= 2 (reference 1332/0x534) (Sent from originator) 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > Message Type: CONNECT ACKNOWLEDGE (15) 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 -- Stopping T203 timer 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 -- Starting T200 timer 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > V(A)=122, V(S)=123, V(R)=18 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > T200_id=1, N200=3, T203_id=0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > [ 02 01 01 24 ] 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > Supervisory frame: 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > SAPI: 00 C/R: 1 EA: 0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > TEI: 000 EA: 1 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > N(R): 018 P/F: 0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 > 0 bytes of data 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:143 Done handling message for SAPI/TEI=0/0 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:732 -- Answer on channel 1:20 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:733 [s1c20][1:20] Changed state from PROGRESS_MEDIA to UP 2010-11-05 10:18:32.294210 [DEBUG] ftmod_libpri.c:466 1:20 STATE [UP] 2010-11-05 10:18:32.294210 [DEBUG] mod_freetdm.c:2048 got clear channel sig [UP] 2010-11-05 10:18:32.294210 [DEBUG] switch_channel.c:2694 (FreeTDM/1:20/1239xxxxxxx) Callstate Change EARLY -> ACTIVE 2010-11-05 10:18:32.294210 [DEBUG] switch_channel.c:2706 Send signal sofia/internal/903@192.168.1.20:5060 [BREAK] 2010-11-05 10:18:32.294210 [NOTICE] mod_freetdm.c:2083 Channel [FreeTDM/1:20/1239xxxxxxx] has been answered 2010-11-05 10:18:32.294210 [DEBUG] switch_channel.c:2778 FreeTDM/1:20/1239xxxxxxx receive message [AUDIO_SYNC] 2010-11-05 10:18:32.294210 [DEBUG] ftdm_io.c:2613 [s1c20][1:20] Enabled software DTMF detector 2010-11-05 10:18:32.300188 [DEBUG] switch_ivr_bridge.c:398 sofia/internal/903@192.168.1.20:5060 receive message [ANSWER] 2010-11-05 10:18:32.309133 [DEBUG] mod_sofia.c:680 Local SDP sofia/internal/903@192.168.1.20:5060: v=0 o=FreeSWITCH 1288948829 1288948831 IN IP4 192.168.1.20 s=FreeSWITCH c=IN IP4 192.168.1.20 t=0 0 m=audio 17872 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:30 a=sendrecv 2010-11-05 10:18:32.309133 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/903@192.168.1.20:5060 [BREAK] 2010-11-05 10:18:32.309133 [DEBUG] switch_channel.c:2694 (sofia/internal/903@192.168.1.20:5060) Callstate Change EARLY -> ACTIVE 2010-11-05 10:18:32.309133 [DEBUG] sofia.c:4569 Channel sofia/internal/903@192.168.1.20:5060 entering state [completed][200] 2010-11-05 10:18:32.309133 [NOTICE] switch_ivr_bridge.c:398 Channel [sofia/internal/903@192.168.1.20:5060] has been answered 2010-11-05 10:18:32.310131 [DEBUG] switch_channel.c:2778 sofia/internal/903@192.168.1.20:5060 receive message [AUDIO_SYNC] 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < TEI: 0 State 7(Multi-frame established) 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < V(A)=122, V(S)=123, V(R)=18 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < K=7, RC=0, l3initiated=0, reject_except=0, ack_pend=0 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < T200_id=1, N200=3, T203_id=0 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < [ 00 01 01 f6 ] 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < Supervisory frame: 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < SAPI: 00 C/R: 0 EA: 0 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < TEI: 000 EA: 1 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < N(R): 123 P/F: 0 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 < 0 bytes of data 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 -- Got ACK for N(S)=122 to (but not including) N(S)=123 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 -- ACKing N(S)=122, txqueue head is N(S)=-1 (-1 is empty, -2 is not transmitted) 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 -- Stopping T200 timer 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 -- Starting T203 timer 2010-11-05 10:18:32.310131 [DEBUG] ftmod_libpri.c:143 Done handling message for SAPI/TEI=0/0 2010-11-05 10:18:32.505128 [DEBUG] sofia.c:4569 Channel sofia/internal/903@192.168.1.20:5060 entering state [ready][200] 2010-11-05 10:18:32.510132 [DEBUG] switch_core_session.c:738 Send signal FreeTDM/1:20/1239xxxxxxx [BREAK] 2010-11-05 10:18:32.510132 [DEBUG] switch_core_session.c:738 Send signal sofia/internal/903@192.168.1.20:5060 [BREAK] 2010-11-05 10:18:32.520128 [DEBUG] switch_ivr_bridge.c:133 FreeTDM/1:20/1239xxxxxxx receive message [DISPLAY] 2010-11-05 10:18:32.540207 [DEBUG] switch_ivr_bridge.c:133 sofia/internal/903@192.168.1.20:5060 receive message [DISPLAY] 2010-11-05 10:18:32.540207 [DEBUG] sofia.c:4569 Channel sofia/internal/903@192.168.1.20:5060 entering state [calling][0] 2010-11-05 10:18:32.707131 [DEBUG] sofia.c:4569 Channel sofia/internal/903@192.168.1.20:5060 entering state [ready][200] 2010-11-05 10:18:32.707131 [DEBUG] sofia.c:4580 Remote SDP: v=0 o=MxSIP 0 1 IN IP4 192.168.1.194 s=SIP Call c=IN IP4 192.168.1.194 t=0 0 m=audio 3000 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=silenceSupp:off - - - - a=ptime:30 2010-11-05 10:18:32.707131 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:30:64000]/[G7221:115:32000:20:48000] 2010-11-05 10:18:32.707131 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:30:64000]/[G7221:107:16000:20:32000] 2010-11-05 10:18:32.707131 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:30:64000]/[G722:9:8000:20:64000] 2010-11-05 10:18:32.707131 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:30:64000]/[PCMU:0:8000:20:64000] 2010-11-05 10:18:32.707131 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:30:64000]/[PCMA:8:8000:20:64000] 2010-11-05 10:18:32.707131 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:30:64000]/[GSM:3:8000:20:13200] 2010-11-05 10:18:32.707131 [DEBUG] sofia_glue.c:4406 Substituting codec PCMU@30i@8000h 2010-11-05 10:18:32.708248 [DEBUG] sofia_glue.c:2654 Already using PCMU 2010-11-05 10:18:32.708248 [DEBUG] sofia_glue.c:4457 Set 2833 dtmf send/recv payload to 101 2010-11-05 10:18:32.708248 [DEBUG] sofia.c:5027 Processing updated SDP 2010-11-05 10:18:32.708248 [DEBUG] sofia_glue.c:2946 Audio params are unchanged for sofia/internal/903@192.168.1.20:5060. *** Snip 12213 lines that do not have the phone number, extension, nor PRI reference number in them (other calls) *** 2010-11-05 10:20:05.562219 [DEBUG] sofia.c:5421 Process REFER to [903@192.168.1.20] *** Snip 6775 lines that do not have the phone number, extension, nor PRI reference number in them (other calls) *** 2010-11-05 10:20:08.331307 [DEBUG] sofia.c:5421 Process REFER to [903@192.168.1.20] *** Snip 15859 lines that do not have the phone number, extension, nor PRI reference number in them (other calls) *** 2010-11-05 10:20:59.890996 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:483 FreeTDM/1:20/1239xxxxxxx ending bridge by request from read function 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:564 BRIDGE THREAD DONE [FreeTDM/1:20/1239xxxxxxx] 2010-11-05 10:20:59.890996 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-05 10:20:59.890996 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:483 FreeTDM/1:22/14345286762 ending bridge by request from read function 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:483 FreeTDM/1:19/4843 ending bridge by request from read function 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:564 BRIDGE THREAD DONE [FreeTDM/1:22/14345286762] 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:564 BRIDGE THREAD DONE [FreeTDM/1:19/4843] 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:584 Send signal sofia/internal/405@192.168.1.20:5060 [BREAK] 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:584 Send signal sofia/internal/sip:410@192.168.1.179:5060 [BREAK] 2010-11-05 10:20:59.890996 [DEBUG] switch_utils.c:631 Emailed file [/tmp/mail.12889668575391] to [award@tribetrans.com] 2010-11-05 10:20:59.890996 [DEBUG] switch_channel.c:2457 (FreeTDM/1:22/14345286762) Callstate Change ACTIVE -> HANGUP 2010-11-05 10:20:59.890996 [DEBUG] mod_voicemail.c:2581 Sending message to award@tribetrans.com 2010-11-05 10:20:59.890996 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:483 FreeTDM/1:17/4843 ending bridge by request from read function 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:564 BRIDGE THREAD DONE [FreeTDM/1:17/4843] 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:584 Send signal sofia/internal/sip:506@192.168.1.169:5060 [BREAK] 2010-11-05 10:20:59.890996 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:483 FreeTDM/1:15/15085868226 ending bridge by request from read function 2010-11-05 10:20:59.890996 [NOTICE] switch_ivr_bridge.c:636 Hangup FreeTDM/1:22/14345286762 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2010-11-05 10:20:59.890996 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:483 FreeTDM/1:18/16786171267 ending bridge by request from read function 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:564 BRIDGE THREAD DONE [FreeTDM/1:15/15085868226] 2010-11-05 10:20:59.890996 [DEBUG] switch_ivr_bridge.c:584 Send signal sofia/internal/509@192.168.1.20:5060 [BREAK] 2010-11-05 10:20:59.890996 [DEBUG] switch_channel.c:2457 (FreeTDM/1:15/15085868226) Callstate Change ACTIVE -> HANGUP 2010-11-05 10:20:59.890996 [DEBUG] switch_channel.c:2473 Send signal FreeTDM/1:22/14345286762 [KILL]
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen. Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
Thanks for the code change providing additional diagnostics. I finally saw another call drop, but didn't have full logging on at the time. The additional logging provided the following: 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c23][1:23] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c19][1:19] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c20][1:20] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c21][1:21] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O I'll turn up logging and see what shows up next time, but any ideas on what may cause this? Thanks! Troy On Nov 6, 2010, at 2:17 PM, Moises Silva wrote:
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
sigh, another case of DAHDI issues. On Fri, Nov 12, 2010 at 10:25 AM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
Thanks for the code change providing additional diagnostics. I finally saw another call drop, but didn't have full logging on at the time. The additional logging provided the following:
2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c23][1:23] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c19][1:19] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c20][1:20] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c21][1:21] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O
I'll turn up logging and see what shows up next time, but any ideas on what may cause this?
Thanks! Troy
On Nov 6, 2010, at 2:17 PM, Moises Silva wrote:
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
When looking at the code, it looks like it's a case of a poll() call returning EINTR, which, I think means that the poll() should be retried in stead of returning an error. Does this sound like the solution? Thanks, Troy On Nov 12, 2010, at 10:26 AM, Anthony Minessale wrote:
sigh, another case of DAHDI issues.
On Fri, Nov 12, 2010 at 10:25 AM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
Thanks for the code change providing additional diagnostics. I finally saw another call drop, but didn't have full logging on at the time. The additional logging provided the following:
2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c23][1:23] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c19][1:19] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c20][1:20] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c21][1:21] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O
I'll turn up logging and see what shows up next time, but any ideas on what may cause this?
Thanks! Troy
On Nov 6, 2010, at 2:17 PM, Moises Silva wrote:
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
I've been looking deeper into this, and it seems that poll() in zt_wait ftmod_zt.c is returning EINTR, which means it was interrupted by a signal while in the system call (as the error points out). After STFW for a while, the advice is to immediately call poll() again if receiving an EINTR. I would patch the code and try it, but the only place I'm experiencing this is in a busy installation, and I don't want to risk the downtime before getting some feedback as the the viability of such an approach. In addition, I am not familiar enough with linux signals to be sure this is a good idea. Is there a way to find out what signal is interrupting the system call? That may be helpful in determining what's going on here. Here's the patch I'm considering: --- a/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c +++ b/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c @@ -885,7 +885,8 @@ static FIO_WAIT_FUNCTION(zt_wait) memset(&pfds[0], 0, sizeof(pfds[0])); pfds[0].fd = ftdmchan->sockfd; pfds[0].events = inflags; - result = poll(pfds, 1, to); + while ((result = poll(pfds, 1, to)) < 0 && errno == EINTR) + continue; *flags = 0; if (pfds[0].revents & POLLERR) { Any thoughts? Thanks, Troy On Nov 12, 2010, at 10:26 AM, Anthony Minessale wrote:
sigh, another case of DAHDI issues.
On Fri, Nov 12, 2010 at 10:25 AM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
Thanks for the code change providing additional diagnostics. I finally saw another call drop, but didn't have full logging on at the time. The additional logging provided the following:
2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c23][1:23] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c19][1:19] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c20][1:20] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c21][1:21] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O
I'll turn up logging and see what shows up next time, but any ideas on what may cause this?
Thanks! Troy
On Nov 6, 2010, at 2:17 PM, Moises Silva wrote:
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
That is good enough. I committed a patch that should fix it, try git pull please. Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com On Sun, Nov 14, 2010 at 7:10 PM, Troy Anderson < freeswitch@tlainvestments.com> wrote:
I've been looking deeper into this, and it seems that poll() in zt_wait ftmod_zt.c is returning EINTR, which means it was interrupted by a signal while in the system call (as the error points out). After STFW for a while, the advice is to immediately call poll() again if receiving an EINTR. I would patch the code and try it, but the only place I'm experiencing this is in a busy installation, and I don't want to risk the downtime before getting some feedback as the the viability of such an approach.
In addition, I am not familiar enough with linux signals to be sure this is a good idea. Is there a way to find out what signal is interrupting the system call? That may be helpful in determining what's going on here.
Here's the patch I'm considering:
--- a/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c +++ b/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c @@ -885,7 +885,8 @@ static FIO_WAIT_FUNCTION(zt_wait) memset(&pfds[0], 0, sizeof(pfds[0])); pfds[0].fd = ftdmchan->sockfd; pfds[0].events = inflags; - result = poll(pfds, 1, to); + while ((result = poll(pfds, 1, to)) < 0 && errno == EINTR) + continue; *flags = 0;
if (pfds[0].revents & POLLERR) {
Any thoughts?
Thanks, Troy
On Nov 12, 2010, at 10:26 AM, Anthony Minessale wrote:
sigh, another case of DAHDI issues.
On Fri, Nov 12, 2010 at 10:25 AM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
Thanks for the code change providing additional diagnostics. I finally saw another call drop, but didn't have full logging on at the time. The additional logging provided the following:
2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c23][1:23] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c19][1:19] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c20][1:20] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c21][1:21] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O
I'll turn up logging and see what shows up next time, but any ideas on what may cause this?
Thanks! Troy
On Nov 6, 2010, at 2:17 PM, Moises Silva wrote:
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:+19193869900
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Thanks! I was getting pressure from the client, so I downgraded to openzap. I looked at the code there, though, and it does the same thing, so it will be interesting to see if it exhibits the same issue. If it does, I'll get the updated freetdm in place and see if that fixes it. Is it possible that the interrupt was just reporting something else bad, and that the messages from freetdm are just symptoms, and not the cause? -Troy On Nov 16, 2010, at 9:42 PM, Moises Silva wrote:
That is good enough. I committed a patch that should fix it, try git pull please.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
On Sun, Nov 14, 2010 at 7:10 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote: I've been looking deeper into this, and it seems that poll() in zt_wait ftmod_zt.c is returning EINTR, which means it was interrupted by a signal while in the system call (as the error points out). After STFW for a while, the advice is to immediately call poll() again if receiving an EINTR. I would patch the code and try it, but the only place I'm experiencing this is in a busy installation, and I don't want to risk the downtime before getting some feedback as the the viability of such an approach.
In addition, I am not familiar enough with linux signals to be sure this is a good idea. Is there a way to find out what signal is interrupting the system call? That may be helpful in determining what's going on here.
Here's the patch I'm considering:
--- a/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c +++ b/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c @@ -885,7 +885,8 @@ static FIO_WAIT_FUNCTION(zt_wait) memset(&pfds[0], 0, sizeof(pfds[0])); pfds[0].fd = ftdmchan->sockfd; pfds[0].events = inflags; - result = poll(pfds, 1, to); + while ((result = poll(pfds, 1, to)) < 0 && errno == EINTR) + continue; *flags = 0;
if (pfds[0].revents & POLLERR) {
Any thoughts?
Thanks, Troy
On Nov 12, 2010, at 10:26 AM, Anthony Minessale wrote:
sigh, another case of DAHDI issues.
On Fri, Nov 12, 2010 at 10:25 AM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
Thanks for the code change providing additional diagnostics. I finally saw another call drop, but didn't have full logging on at the time. The additional logging provided the following:
2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c23][1:23] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c19][1:19] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c20][1:20] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c21][1:21] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O
I'll turn up logging and see what shows up next time, but any ideas on what may cause this?
Thanks! Troy
On Nov 6, 2010, at 2:17 PM, Moises Silva wrote:
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Look in /var/log/messages Also bear in mind we do not fix nor improve anything on openzap anymore. Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com On Wed, Nov 17, 2010 at 12:22 AM, Troy Anderson < freeswitch@tlainvestments.com> wrote:
Thanks!
I was getting pressure from the client, so I downgraded to openzap. I looked at the code there, though, and it does the same thing, so it will be interesting to see if it exhibits the same issue. If it does, I'll get the updated freetdm in place and see if that fixes it.
Is it possible that the interrupt was just reporting something else bad, and that the messages from freetdm are just symptoms, and not the cause?
-Troy
On Nov 16, 2010, at 9:42 PM, Moises Silva wrote:
That is good enough. I committed a patch that should fix it, try git pull please.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
On Sun, Nov 14, 2010 at 7:10 PM, Troy Anderson < freeswitch@tlainvestments.com> wrote:
I've been looking deeper into this, and it seems that poll() in zt_wait ftmod_zt.c is returning EINTR, which means it was interrupted by a signal while in the system call (as the error points out). After STFW for a while, the advice is to immediately call poll() again if receiving an EINTR. I would patch the code and try it, but the only place I'm experiencing this is in a busy installation, and I don't want to risk the downtime before getting some feedback as the the viability of such an approach.
In addition, I am not familiar enough with linux signals to be sure this is a good idea. Is there a way to find out what signal is interrupting the system call? That may be helpful in determining what's going on here.
Here's the patch I'm considering:
--- a/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c +++ b/libs/freetdm/src/ftmod/ftmod_zt/ftmod_zt.c @@ -885,7 +885,8 @@ static FIO_WAIT_FUNCTION(zt_wait) memset(&pfds[0], 0, sizeof(pfds[0])); pfds[0].fd = ftdmchan->sockfd; pfds[0].events = inflags; - result = poll(pfds, 1, to); + while ((result = poll(pfds, 1, to)) < 0 && errno == EINTR) + continue; *flags = 0;
if (pfds[0].revents & POLLERR) {
Any thoughts?
Thanks, Troy
On Nov 12, 2010, at 10:26 AM, Anthony Minessale wrote:
sigh, another case of DAHDI issues.
On Fri, Nov 12, 2010 at 10:25 AM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
Thanks for the code change providing additional diagnostics. I finally saw another call drop, but didn't have full logging on at the time. The additional logging provided the following:
2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c23][1:23] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c19][1:19] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c20][1:20] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O 2010-11-12 11:12:54.906656 [ERR] ftmod_zt.c:904 [s1c21][1:21] Failed to poll DAHDI device: Interrupted system call 2010-11-12 11:12:54.906656 [WARNING] mod_freetdm.c:660 failed to wait for I/O
I'll turn up logging and see what shows up next time, but any ideas on what may cause this?
Thanks! Troy
On Nov 6, 2010, at 2:17 PM, Moises Silva wrote:
On Fri, Nov 5, 2010 at 12:58 PM, Troy Anderson <freeswitch@tlainvestments.com> wrote:
We have an installation with a dual PRI and lots of call volume. Among many successful calls each day, we have been experiencing a one or two dropped per day, and they always coincide with a "failed to wait for I/O" warning from mod_freetdm. I have attempted to track down the root cause in the source and by poring over the logs, but cannot figure it out. I have included the redacted logs here. The log file in question is 10MB and has lots of call data that doesn't relate - I know I risked removing something important, but I tried to put in all the data related to this call.
I appreciate any insights or advice on tracking this down.
If you update your git tree you will be able to get more information the next time it happens. I added some code to print the reason for that error to happen.
Moises Silva Senior Software Engineer Sangoma Technologies Inc. | 100 Renfrew Drive, Suite 100, Markham ON L3R 9R6 Canada t. 1 905 474 1990 x128 | e. moy@sangoma.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:+19193869900
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
participants (3)
-
Anthony Minessale
-
Moises Silva
-
Troy Anderson