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]