[Freeswitch-users] failed to wait for I/O

Troy Anderson freeswitch at tlainvestments.com
Fri Nov 5 09:58:00 PDT 2010


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 at 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 at 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 at 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 at 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 at 192.168.1.20:5060!
2010-11-05 10:18:21.104067 [DEBUG] switch_channel.c:2544 (sofia/internal/903 at 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 at 192.168.1.20:5060 [BREAK]
2010-11-05 10:18:21.104067 [DEBUG] switch_ivr_originate.c:1128 Raw Codec Activation Success L16 at 8000hz 1 channel 30ms
2010-11-05 10:18:21.104067 [DEBUG] switch_core_codec.c:116 sofia/internal/903 at 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 at 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 at 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 at 192.168.1.20:5060 [BREAK]
2010-11-05 10:18:21.320116 [DEBUG] switch_core_codec.c:141 sofia/internal/903 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.1.20:5060 [BREAK]
2010-11-05 10:18:32.309133 [DEBUG] switch_channel.c:2694 (sofia/internal/903 at 192.168.1.20:5060) Callstate Change EARLY -> ACTIVE
2010-11-05 10:18:32.309133 [DEBUG] sofia.c:4569 Channel sofia/internal/903 at 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 at 192.168.1.20:5060] has been answered
2010-11-05 10:18:32.310131 [DEBUG] switch_channel.c:2778 sofia/internal/903 at 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 at 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 at 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 at 192.168.1.20:5060 receive message [DISPLAY]
2010-11-05 10:18:32.540207 [DEBUG] sofia.c:4569 Channel sofia/internal/903 at 192.168.1.20:5060 entering state [calling][0]
2010-11-05 10:18:32.707131 [DEBUG] sofia.c:4569 Channel sofia/internal/903 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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]




More information about the FreeSWITCH-users mailing list