2013-06-11 22:31:26.963579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1, 0, 0] sent data... (R)
2013-06-11 22:31:26.963579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1, 0, 0] sent data... (E)
2013-06-11 22:31:26.963579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1, 0, 0] sent data... (G)
2013-06-11 22:31:26.963579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1, 0, 0] sent data... (?)
2013-06-11 22:31:26.963579 [DEBUG] gsmopen_protocol.cpp:1966 rev |[(nil)|37     ][DEBUG_GSMOPEN  1966 ][gsm01     ][-1, 0, 0] sent (carriage return)
2013-06-11 22:31:26.983584 [DEBUG] gsmopen_protocol.cpp:733 rev |[(nil)|37     ][DEBUG_GSMOPEN  733  ][gsm01     ][-1, 0, 0] Read line 0: |+CREG: 1,1| la_counter=2
2013-06-11 22:31:26.983584 [DEBUG] gsmopen_protocol.cpp:733 rev |[(nil)|37     ][DEBUG_GSMOPEN  733  ][gsm01     ][-1, 0, 0] Read line 1: |OK| la_counter=2
2013-06-11 22:31:26.983584 [DEBUG] gsmopen_protocol.cpp:1008 rev |[(nil)|37     ][DEBUG_GSMOPEN  1008 ][gsm01     ][-1, 0, 0] |+CREG: 1,1| +CREG: Display: 1, Registration=1
2013-06-11 22:31:26.983584 [DEBUG] gsmopen_protocol.cpp:1022 rev |[(nil)|37     ][DEBUG_GSMOPEN  1022 ][gsm01     ][-1, 0, 0] |+CREG: 1,1| CELLPHONE is registered to the HOME network
2013-06-11 22:31:26.983584 [DEBUG] gsmopen_protocol.cpp:1584 rev |[(nil)|37     ][DEBUG_GSMOPEN  1584 ][gsm01     ][-1, 0, 0] got OK
2013-06-11 22:34:11.203579 [NOTICE] switch_channel.c:978 New Channel sofia/sipinterface_4/190@sip.example.com [e421bdee-d2cd-11e2-8043-9974f952483c]
2013-06-11 22:34:11.203579 [DEBUG] switch_core_session.c:998 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.203579 [DEBUG] switch_core_session.c:998 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.203579 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_4/190@sip.example.com) Running State Change CS_NEW
2013-06-11 22:34:11.203579 [DEBUG] switch_core_state_machine.c:433 (sofia/sipinterface_4/190@sip.example.com) State NEW
2013-06-11 22:34:11.223577 [DEBUG] switch_core_session.c:998 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.223577 [DEBUG] sofia.c:1767 detaching session e421bdee-d2cd-11e2-8043-9974f952483c
2013-06-11 22:34:11.483579 [DEBUG] sofia.c:1859 Re-attaching to session e421bdee-d2cd-11e2-8043-9974f952483c
2013-06-11 22:34:11.483579 [DEBUG] switch_core_session.c:998 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.483579 [DEBUG] switch_core_session.c:998 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.543576 [DEBUG] sofia.c:5685 Channel sofia/sipinterface_4/190@sip.example.com entering state [received][100]
2013-06-11 22:34:11.543576 [DEBUG] sofia.c:5696 Remote SDP:
v=0
o=190 96271082 49276412 IN IP4 XXX.XXX.XXX.29
s=SIP CALL
c=IN IP4 XXX.XXX.XXX.29
t=0 0
m=audio 6000 RTP/AVP 8 0 18 3 4 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:3 GSM/8000
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2013-06-11 22:34:11.543576 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2013-06-11 22:34:11.543576 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-06-11 22:34:11.543576 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-06-11 22:34:11.543576 [DEBUG] sofia_glue.c:3119 Set Codec sofia/sipinterface_4/190@sip.example.com PCMA/8000 20 ms 160 samples 64000 bits
2013-06-11 22:34:11.543576 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_4/190@sip.example.com Original read codec set to PCMA:8
2013-06-11 22:34:11.543576 [DEBUG] sofia_glue.c:5305 Set 2833 dtmf send/recv payload to 101
2013-06-11 22:34:11.543576 [DEBUG] sofia.c:5929 (sofia/sipinterface_4/190@sip.example.com) State Change CS_NEW -> CS_INIT
2013-06-11 22:34:11.543576 [DEBUG] switch_core_session.c:1333 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_4/190@sip.example.com) Running State Change CS_INIT
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:454 (sofia/sipinterface_4/190@sip.example.com) State INIT
2013-06-11 22:34:11.543576 [DEBUG] mod_sofia.c:87 sofia/sipinterface_4/190@sip.example.com SOFIA INIT
2013-06-11 22:34:11.543576 [DEBUG] mod_sofia.c:127 (sofia/sipinterface_4/190@sip.example.com) State Change CS_INIT -> CS_ROUTING
2013-06-11 22:34:11.543576 [DEBUG] switch_core_session.c:1333 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:454 (sofia/sipinterface_4/190@sip.example.com) State INIT going to sleep
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_4/190@sip.example.com) Running State Change CS_ROUTING
2013-06-11 22:34:11.543576 [DEBUG] switch_channel.c:2034 (sofia/sipinterface_4/190@sip.example.com) Callstate Change DOWN -> RINGING
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:470 (sofia/sipinterface_4/190@sip.example.com) State ROUTING
2013-06-11 22:34:11.543576 [DEBUG] mod_sofia.c:150 sofia/sipinterface_4/190@sip.example.com SOFIA ROUTING
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:117 sofia/sipinterface_4/190@sip.example.com Standard ROUTING
2013-06-11 22:34:11.543576 [INFO] mod_dialplan_xml.c:557 Processing 190 <190>->XXXXXXXXXX in context sip.example.com
Dialplan: sofia/sipinterface_4/190@sip.example.com parsing [sip.example.com->extension-intercom] continue=false
Dialplan: sofia/sipinterface_4/190@sip.example.com Regex (FAIL) [extension-intercom] destination_number(XXXXXXXXXX) =~ /^(1[0-9][0-9])$/ break=on-false
Dialplan: sofia/sipinterface_4/190@sip.example.com parsing [sip.example.com->gsmopen] continue=false
Dialplan: sofia/sipinterface_4/190@sip.example.com Regex (PASS) [gsmopen] destination_number(XXXXXXXXXX) =~ /^(.*)$/ break=on-false
Dialplan: sofia/sipinterface_4/190@sip.example.com Action bridge(gsmopen/gsm01/XXXXXXXXXX) 
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:167 (sofia/sipinterface_4/190@sip.example.com) State Change CS_ROUTING -> CS_EXECUTE
2013-06-11 22:34:11.543576 [DEBUG] switch_core_session.c:1333 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:470 (sofia/sipinterface_4/190@sip.example.com) State ROUTING going to sleep
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_4/190@sip.example.com) Running State Change CS_EXECUTE
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:477 (sofia/sipinterface_4/190@sip.example.com) State EXECUTE
2013-06-11 22:34:11.543576 [DEBUG] mod_sofia.c:243 sofia/sipinterface_4/190@sip.example.com SOFIA EXECUTE
2013-06-11 22:34:11.543576 [DEBUG] switch_core_state_machine.c:209 sofia/sipinterface_4/190@sip.example.com Standard EXECUTE
EXECUTE sofia/sipinterface_4/190@sip.example.com bridge(gsmopen/gsm01/XXXXXXXXXX)
2013-06-11 22:34:11.543576 [DEBUG] switch_ivr_originate.c:2044 Parsing global variables
2013-06-11 22:34:11.543576 [DEBUG] mod_gsmopen.cpp:1073 rev |[(nil)|37     ][DEBUG_GSMOPEN  1073 ][none      ][-1,-1,-1] 1 SESSION_REQUEST e4566a08-d2cd-11e2-804a-9974f952483c
2013-06-11 22:34:11.543576 [DEBUG] mod_gsmopen.cpp:1115 rev |[(nil)|37     ][DEBUG_GSMOPEN  1115 ][none      ][-1,-1,-1] globals.GSMOPEN_INTERFACES[1].name=|||gsm01|||?
2013-06-11 22:34:11.543576 [DEBUG] gsmopen_protocol.cpp:3160 rev |[(nil)|37     ][DEBUG_GSMOPEN  3160 ][gsm01     ][-1, 0, 0] port /dev/ttyUSB5, SUCCESS open
2013-06-11 22:34:11.543576 [DEBUG] gsmopen_protocol.cpp:3175 rev |[(nil)|37     ][DEBUG_GSMOPEN  3175 ][gsm01     ][-1, 0, 0] serial_audio_init res=0
2013-06-11 22:34:11.543576 [DEBUG] mod_gsmopen.cpp:299 rev |[(nil)|37     ][DEBUG_GSMOPEN  299  ][gsm01     ][-1, 0, 0] gsmopen_codec SUCCESS
2013-06-11 22:34:11.543576 [NOTICE] switch_channel.c:978 New Channel gsmopen/gsm01/XXXXXXXXXX [e4566a08-d2cd-11e2-804a-9974f952483c]
2013-06-11 22:34:11.543576 [DEBUG] mod_gsmopen.cpp:1182 (gsmopen/gsm01/XXXXXXXXXX) State Change CS_NEW -> CS_INIT
2013-06-11 22:34:11.543576 [DEBUG] switch_core_session.c:1333 Send signal gsmopen/gsm01/XXXXXXXXXX [BREAK]
2013-06-11 22:34:11.543576 [DEBUG] mod_gsmopen.cpp:665 rev |[(nil)|37     ][DEBUG_GSMOPEN  665  ][gsm01     ][-1, 0, 0] gsm01 CHANNEL KILL_CHANNEL
2013-06-11 22:34:11.543576 [DEBUG] mod_gsmopen.cpp:676 rev |[(nil)|37     ][DEBUG_GSMOPEN  676  ][gsm01     ][-1, 0, 0] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_SIG_BREAK
2013-06-11 22:34:11.543576 [DEBUG] gsmopen_protocol.cpp:2706 rev |[(nil)|37     ][DEBUG_GSMOPEN  2706 ][gsm01     ][-1, 0, 0] Calling GSM, rdest is: XXXXXXXXXX
2013-06-11 22:34:11.543576 [DEBUG] gsmopen_protocol.cpp:2322 rev |[(nil)|37     ][DEBUG_PBX  2322 ][gsm01     ][-1, 0, 0] Dialing XXXXXXXXXX
2013-06-11 22:34:11.543576 [DEBUG] gsmopen_protocol.cpp:2337 rev |[(nil)|37     ][DEBUG_PBX  2337 ][gsm01     ][-1, 3, 3] Dialstring ATDXXXXXXXXXX;
2013-06-11 22:34:11.623579 [DEBUG] gsmopen_protocol.cpp:2165 rev |[(nil)|37     ][DEBUG_GSMOPEN  2165 ][gsm01     ][-1, 3, 3] sending: ATDXXXXXXXXXX;, expecting: OK
2013-06-11 22:34:11.623579 [DEBUG] mod_gsmopen.cpp:2848 rev |[(nil)|37     ][DEBUG_GSMOPEN  2848 ][gsm01     ][-1, 3, 3] WE'RE DIALING, let's take the earlymedia
2013-06-11 22:34:11.623579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (A)
2013-06-11 22:34:11.623579 [NOTICE] mod_gsmopen.cpp:2196 Pre-Answer gsmopen/gsm01/XXXXXXXXXX!
2013-06-11 22:34:11.623579 [DEBUG] switch_channel.c:3265 (gsmopen/gsm01/XXXXXXXXXX) Callstate Change DOWN -> EARLY
2013-06-11 22:34:11.623579 [DEBUG] mod_gsmopen.cpp:2197 rev |[(nil)|37     ][DEBUG_GSMOPEN  2197 ][gsm01     ][-1,24, 3] gsmopen_call: REMOTE PARTY EARLY MEDIA
2013-06-11 22:34:11.623579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (T)
2013-06-11 22:34:11.623579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (D)
2013-06-11 22:34:11.623579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (0)
2013-06-11 22:34:11.623579 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (7)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (3)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (3)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (3)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (5)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (5)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (5)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (7)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (8)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (;)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:1966 rev |[(nil)|37     ][DEBUG_GSMOPEN  1966 ][gsm01     ][-1,24, 3] sent (carriage return)
2013-06-11 22:34:11.643576 [DEBUG] gsmopen_protocol.cpp:609 rev |[(nil)|37     ][DEBUG_GSMOPEN  609  ][gsm01     ][-1,24, 3] TIMEOUT=500
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:733 rev |[(nil)|37     ][DEBUG_GSMOPEN  733  ][gsm01     ][-1,24, 3] Read line 0: |OK| la_counter=1
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1578 rev |[(nil)|37     ][DEBUG_GSMOPEN  1578 ][gsm01     ][-1,24, 3] |OK| got what EXPECTED
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:2165 rev |[(nil)|37     ][DEBUG_GSMOPEN  2165 ][gsm01     ][-1,24, 3] sending: AT^DDSETEX=2, expecting: OK
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (A)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (T)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (^)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (D)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (D)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (S)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (E)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (T)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (E)
2013-06-11 22:34:11.663580 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (X)
2013-06-11 22:34:11.683576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (=)
2013-06-11 22:34:11.683576 [DEBUG] gsmopen_protocol.cpp:1918 rev |[(nil)|37     ][DEBUG_GSMOPEN  1918 ][gsm01     ][-1,24, 3] sent data... (2)
2013-06-11 22:34:11.683576 [DEBUG] gsmopen_protocol.cpp:1966 rev |[(nil)|37     ][DEBUG_GSMOPEN  1966 ][gsm01     ][-1,24, 3] sent (carriage return)
2013-06-11 22:34:11.683576 [DEBUG] gsmopen_protocol.cpp:609 rev |[(nil)|37     ][DEBUG_GSMOPEN  609  ][gsm01     ][-1,24, 3] TIMEOUT=500
2013-06-11 22:34:11.703580 [DEBUG] gsmopen_protocol.cpp:733 rev |[(nil)|37     ][DEBUG_GSMOPEN  733  ][gsm01     ][-1,24, 3] Read line 0: |OK| la_counter=1
2013-06-11 22:34:11.703580 [DEBUG] gsmopen_protocol.cpp:1578 rev |[(nil)|37     ][DEBUG_GSMOPEN  1578 ][gsm01     ][-1,24, 3] |OK| got what EXPECTED
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:415 (gsmopen/gsm01/XXXXXXXXXX) Running State Change CS_INIT
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:454 (gsmopen/gsm01/XXXXXXXXXX) State INIT
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:525 (gsmopen/gsm01/XXXXXXXXXX) State Change CS_INIT -> CS_ROUTING
2013-06-11 22:34:11.703580 [DEBUG] switch_core_session.c:1333 Send signal gsmopen/gsm01/XXXXXXXXXX [BREAK]
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:665 rev |[(nil)|37     ][DEBUG_GSMOPEN  665  ][gsm01     ][-1,24, 3] gsm01 CHANNEL KILL_CHANNEL
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:676 rev |[(nil)|37     ][DEBUG_GSMOPEN  676  ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_SIG_BREAK
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:530 rev |[(nil)|37     ][DEBUG_GSMOPEN  530  ][gsm01     ][-1,24, 3] gsm01 CHANNEL INIT e4566a08-d2cd-11e2-804a-9974f952483c
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:454 (gsmopen/gsm01/XXXXXXXXXX) State INIT going to sleep
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:415 (gsmopen/gsm01/XXXXXXXXXX) Running State Change CS_ROUTING
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:470 (gsmopen/gsm01/XXXXXXXXXX) State ROUTING
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:632 rev |[(nil)|37     ][DEBUG_GSMOPEN  632  ][gsm01     ][-1,24, 3] gsm01 CHANNEL ROUTING
2013-06-11 22:34:11.703580 [DEBUG] switch_ivr_originate.c:67 (gsmopen/gsm01/XXXXXXXXXX) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-06-11 22:34:11.703580 [DEBUG] switch_core_session.c:1333 Send signal gsmopen/gsm01/XXXXXXXXXX [BREAK]
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:665 rev |[(nil)|37     ][DEBUG_GSMOPEN  665  ][gsm01     ][-1,24, 3] gsm01 CHANNEL KILL_CHANNEL
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:676 rev |[(nil)|37     ][DEBUG_GSMOPEN  676  ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_SIG_BREAK
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:470 (gsmopen/gsm01/XXXXXXXXXX) State ROUTING going to sleep
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:415 (gsmopen/gsm01/XXXXXXXXXX) Running State Change CS_CONSUME_MEDIA
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:489 (gsmopen/gsm01/XXXXXXXXXX) State CONSUME_MEDIA
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:695 rev |[(nil)|37     ][DEBUG_GSMOPEN  695  ][gsm01     ][-1,24, 3] gsm01 CHANNEL CONSUME_MEDIA
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:489 (gsmopen/gsm01/XXXXXXXXXX) State CONSUME_MEDIA going to sleep
2013-06-11 22:34:11.703580 [INFO] switch_ivr_originate.c:3427 Sending early media
2013-06-11 22:34:11.703580 [DEBUG] sofia_glue.c:3378 AUDIO RTP [sofia/sipinterface_4/190@sip.example.com] XXX.XXX.XXX.24 port 24490 -> XXX.XXX.XXX.29 port 6000 codec: 8 ms: 20
2013-06-11 22:34:11.703580 [DEBUG] switch_rtp.c:1985 Starting timer [soft] 160 bytes per 20ms
2013-06-11 22:34:11.703580 [DEBUG] sofia_glue.c:3642 Set 2833 dtmf send payload to 101
2013-06-11 22:34:11.703580 [DEBUG] sofia_glue.c:3648 Set 2833 dtmf receive payload to 101
2013-06-11 22:34:11.703580 [DEBUG] sofia_glue.c:3675 sofia/sipinterface_4/190@sip.example.com Set rtp dtmf delay to 40
2013-06-11 22:34:11.703580 [DEBUG] mod_sofia.c:2842 Ring SDP:
v=0
o=FreeSWITCH 1370954761 1370954762 IN IP4 XXX.XXX.XXX.24
s=FreeSWITCH
c=IN IP4 XXX.XXX.XXX.24
t=0 0
m=audio 24490 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2013-06-11 22:34:11.703580 [NOTICE] mod_sofia.c:2845 Pre-Answer sofia/sipinterface_4/190@sip.example.com!
2013-06-11 22:34:11.703580 [DEBUG] switch_channel.c:3265 (sofia/sipinterface_4/190@sip.example.com) Callstate Change RINGING -> EARLY
2013-06-11 22:34:11.703580 [DEBUG] switch_core_session.c:853 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.703580 [DEBUG] switch_ivr_originate.c:3478 Originate Resulted in Success: [gsmopen/gsm01/XXXXXXXXXX]
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:989 rev |[(nil)|37     ][DEBUG_GSMOPEN  989  ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_MESSAGE_INDICATE_AUDIO_SYNC
2013-06-11 22:34:11.703580 [DEBUG] switch_core_session.c:998 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.703580 [DEBUG] sofia.c:5685 Channel sofia/sipinterface_4/190@sip.example.com entering state [early][183]
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:989 rev |[(nil)|37     ][DEBUG_GSMOPEN  989  ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_MESSAGE_INDICATE_AUDIO_SYNC
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:999 rev |[(nil)|37     ][DEBUG_GSMOPEN  999  ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_MESSAGE_INDICATE_BRIDGE
2013-06-11 22:34:11.703580 [DEBUG] switch_core_session.c:853 Send signal gsmopen/gsm01/XXXXXXXXXX [BREAK]
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:665 rev |[(nil)|37     ][DEBUG_GSMOPEN  665  ][gsm01     ][-1,24, 3] gsm01 CHANNEL KILL_CHANNEL
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:676 rev |[(nil)|37     ][DEBUG_GSMOPEN  676  ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_SIG_BREAK
2013-06-11 22:34:11.703580 [DEBUG] switch_core_session.c:853 Send signal sofia/sipinterface_4/190@sip.example.com [BREAK]
2013-06-11 22:34:11.703580 [DEBUG] switch_ivr_bridge.c:1391 (gsmopen/gsm01/XXXXXXXXXX) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2013-06-11 22:34:11.703580 [DEBUG] switch_core_session.c:1333 Send signal gsmopen/gsm01/XXXXXXXXXX [BREAK]
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:415 (gsmopen/gsm01/XXXXXXXXXX) Running State Change CS_EXCHANGE_MEDIA
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:665 rev |[(nil)|37     ][DEBUG_GSMOPEN  665  ][gsm01     ][-1,24, 3] gsm01 CHANNEL KILL_CHANNEL
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:676 rev |[(nil)|37     ][DEBUG_GSMOPEN  676  ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_SIG_BREAK
2013-06-11 22:34:11.703580 [DEBUG] switch_core_state_machine.c:480 (gsmopen/gsm01/XXXXXXXXXX) State EXCHANGE_MEDIA
2013-06-11 22:34:11.703580 [DEBUG] mod_gsmopen.cpp:703 rev |[(nil)|37     ][DEBUG_GSMOPEN  703  ][gsm01     ][-1,24, 3] gsm01 CHANNEL EXCHANGE_MEDIA
2013-06-11 22:34:11.743580 [DEBUG] mod_gsmopen.cpp:770 rev |[(nil)|37     ][DEBUG_GSMOPEN  770  ][gsm01     ][-1,24, 3] read more than 320, samples=640
2013-06-11 22:34:11.743580 [DEBUG] mod_gsmopen.cpp:837 rev |[(nil)|37     ][DEBUG_GSMOPEN  837  ][gsm01     ][-1,24, 3] BREAK: CHANNEL READ FRAME goto CNG
2013-06-11 22:34:11.803580 [DEBUG] switch_rtp.c:3704 Correct ip/port confirmed.
2013-06-11 22:34:11.863583 [DEBUG] mod_gsmopen.cpp:1002 rev |[(nil)|37     ][DEBUG_GSMOPEN  1002 ][gsm01     ][-1,24, 3] gsmopen/gsm01/XXXXXXXXXX CHANNEL got SWITCH_MESSAGE_INDICATE_TRANSCODING_NECESSARY