[asterisk-users] google voice + asterisk: calls made to GV# processed but weird

Mon Oct 25 01:03:26 CDT 2010

Dear all,

First off, I am very new to asterisk so forgive me if any of my
comments or questions seem trivial.  Thanks to [this
post](http://blog.polybeacon.com/2010/10/17/asterisk-1-8-and-google-voice/)
and [this post](http://www.davidvossel.com/?p=28), I have GV set up on
asterisk through jabber.conf and gtalk.conf.  I can successfully dial
out from asterisk.

I'm trying to set up an auto-attendant on asterisk.  I am doing a
basic "Hello world" example.  My config:

jabber.conf:
[general]
debug=yes
autoprune=no
autoregister=yes

[asterisk]
type=client
serverhost=talk.google.com
username=MYADDY at gmail.com/gmail
secret=MYPASSWORD
port=5222
usetls=yes
usesasl=yes
statusmessage="Connected to Asterisk." ;required do not change
timeout=100

gtalk.conf:
[general]
context=default
allowguest=yes
bindaddr=0.0.0.0

[guest]
disallow=all
allow=ulaw
connection=asterisk

extensions.conf:
[general]
[globals]
[incoming]
exten => s,1,Answer()
exten => s,n,Playback(hello-world)
exten => s,n,Hangup()

[default]
include => incoming

Basically, when I'm logged into another gmail account and "call the
computer" that's connected to asterisk, the "Hello world" example
works.  However, if I call the GV # from a phone, GV rings and end up
at the GV voicemail.  At first I thought it just skipped the pickup
altogether.  However, thanks to the help of p3nguin, pabelanger, and
[TK]D-Fender on #asterisk, I found out that the call IS processed by
asterisk; however, the user does not hear any of it and goes straight
to the GV voicemail.  I wanted to give the mailing list a try to see
if other people have thoughts on this.  Here is the debug:

[Oct 24 21:18:23] VERBOSE[2393] config.c:   == Parsing
'/etc/asterisk/logger.conf': [Oct 24 21:18:23] DEBUG[2393] config.c:
Parsing /etc/asterisk/logger.conf
[Oct 24 21:18:23] VERBOSE[2393] config.c:   == Found
[Oct 24 21:18:23] VERBOSE[2393] logger.c:  Asterisk Queue Logger restarted
[Oct 24 21:18:28] VERBOSE[2405] res_jabber.c:
JABBER: Keep alive packet
[Oct 24 21:18:44] VERBOSE[2405] res_jabber.c:
JABBER: asterisk INCOMING: <presence
from="CALLER at gmail.com/androidfe2b05b6ebb0"
to="MYUSERNAME at gmail.com"><priority>24</priority><caps:c
node="http://www.android.com/gtalk/client/caps" ext="pmuc-v1"
ver="1.1" xmlns:caps="http://jabber.org/protocol/caps"/><status/><x
xmlns="vcard-temp:x:update"><photo>3c4fd5045a18d7417b2e4371bdce077ecd6c8355</photo></x></presence>
[Oct 24 21:18:44] DEBUG[2405] res_jabber.c: JABBER: I am available ^_* 13
[Oct 24 21:18:44] DEBUG[2405] res_jabber.c: JABBER: type is available
[Oct 24 21:18:44] DEBUG[2405] res_jabber.c: JABBER: Handling paktype PRESENCE
[Oct 24 21:18:44] DEBUG[2405] res_jabber.c: XML parsing successful
[Oct 24 21:18:49] VERBOSE[2405] res_jabber.c:
JABBER: asterisk INCOMING: <iq
from="+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy"
to="MYUSERNAME at gmail.com/gmail02D370A8"
id="jingle:10.218.20.143-28982014:1:C3955FF7" type="set"><ses:session
type="initiate" id="SIP183646623 at 10.218.118.3"
initiator="+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy"
xmlns:ses="http://www.google.com/session"><pho:description
xmlns:pho="http://www.google.com/session/phone"><pho:payload-type
id="0" name="PCMU" clockrate="8000"/><pho:payload-type id="101"
name="telephone-event"/></pho:description><transport
behind-symmetric-nat="false" can-receive-from-symmetric-nat="false"
xmlns="http://www.google.com/transport/raw-udp"/><transport
xmlns="http://www.google.com/transport/p2p"/></ses:session></iq>
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: JABBER: Handling paktype IQ
[Oct 24 21:18:49] DEBUG[2405] chan_gtalk.c: The client is guest for alloc
[Oct 24 21:18:49] DEBUG[2405] rtp_engine.c: Using engine 'asterisk'
for RTP instance '0x1b86bc8'
[Oct 24 21:18:49] DEBUG[2405] res_rtp_asterisk.c: Allocated port 11262
for RTP instance '0x1b86bc8'
[Oct 24 21:18:49] DEBUG[2405] rtp_engine.c: RTP instance '0x1b86bc8'
is setup and ready to go
[Oct 24 21:18:49] DEBUG[2405] res_rtp_asterisk.c: Setup RTCP on RTP
instance '0x1b86bc8'
[Oct 24 21:18:49] DEBUG[2405] rtp_engine.c: Setting payload 0 based on
m type on 0x1b86d90
[Oct 24 21:18:49] DEBUG[2405] rtp_engine.c: Setting payload 101 based
on m type on 0x1b86d90
[Oct 24 21:18:49] DEBUG[2405] rtp_engine.c: Incorporating payload 0 on 0x1b86d90
[Oct 24 21:18:49] DEBUG[2405] rtp_engine.c: Incorporating payload 101
on 0x1b86d90
[Oct 24 21:18:49] DEBUG[2399] devicestate.c: No provider found,
checking channel drivers for Gtalk - +1CALLER10DIGIT
[Oct 24 21:18:49] DEBUG[2399] devicestate.c: Changing state for
Gtalk/+1CALLER10DIGIT - state 2 (In use)
[Oct 24 21:18:49] DEBUG[2399] devicestate.c: device
'Gtalk/+1CALLER10DIGIT' state '2'
[Oct 24 21:18:49] VERBOSE[4341] pbx.c:   == Starting
Gtalk/+1CALLER10DIGIT-12d0 at default,MYUSERNAME at gmail.com,1 failed so
falling back to exten 's'
[Oct 24 21:18:49] DEBUG[4341] pbx.c: Launching 'Answer'
[Oct 24 21:18:49] VERBOSE[4341] pbx.c:     -- Executing [s at default:1]
Answer("Gtalk/+1CALLER10DIGIT-12d0", "") in new stack
[Oct 24 21:18:49] DEBUG[2434] app_queue.c: Device
'Gtalk/+1CALLER10DIGIT' changed to state '2' (In use) but we don't
care because they're not a member of any queue.
[Oct 24 21:18:49] DEBUG[4341] chan_gtalk.c: Answer!
[Oct 24 21:18:49] VERBOSE[2405] res_jabber.c:
JABBER: asterisk OUTGOING: <iq type='result'
from='MYUSERNAME at gmail.com/gmail02D370A8'
to='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
id='jingle:10.218.20.143-28982014:1:C3955FF7'/>
[Oct 24 21:18:49] DEBUG[2405] netsock2.c: Splitting 'google.com' gives...
[Oct 24 21:18:49] DEBUG[2405] netsock2.c: ...host 'google.com' and
port '(null)'.
[Oct 24 21:18:49] VERBOSE[4341] res_jabber.c:
JABBER: asterisk OUTGOING: <iq type='set'
to='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
from='MYUSERNAME at gmail.com/gmail02D370A8' id='aaaap'><session
xmlns='http://www.google.com/session' type='accept'
initiator='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
id='SIP183646623 at 10.218.118.3'><description
xmlns='http://www.google.com/session/phone'
xml:lang='en'><payload-type id='0' name='PCMU' clockrate='8000'
bitrate='64000'/><payload-type id='100' name='EG711U' clockrate='8000'
bitrate='64000'/><payload-type id='101' name='telephone-event'
clockrate='8000'/></description></session></iq>
[Oct 24 21:18:49] DEBUG[4341] chan_gtalk.c: Don't know how to indicate
condition '-1'
[Oct 24 21:18:49] DEBUG[2399] devicestate.c: No provider found,
checking channel drivers for Gtalk - +1CALLER10DIGIT
[Oct 24 21:18:49] DEBUG[2399] devicestate.c: Changing state for
Gtalk/+1CALLER10DIGIT - state 2 (In use)
[Oct 24 21:18:49] DEBUG[2399] devicestate.c: device
'Gtalk/+1CALLER10DIGIT' state '2'
[Oct 24 21:18:49] DEBUG[2434] app_queue.c: Device
'Gtalk/+1CALLER10DIGIT' changed to state '2' (In use) but we don't
care because they're not a member of any queue.
[Oct 24 21:18:49] DEBUG[2405] acl.c: Not an IPv4 nor IPv6 address,
cannot get port.
[Oct 24 21:18:49] DEBUG[2405] acl.c: For destination '66.102.7.99',
our source address is '192.168.1.60'.
[Oct 24 21:18:49] VERBOSE[2405] res_jabber.c:
JABBER: asterisk OUTGOING: <iq
from='MYUSERNAME at gmail.com/gmail02D370A8'
to='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
type='set' id='aaaaq'><session type='candidates'
id='SIP183646623 at 10.218.118.3'
initiator='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
xmlns='http://www.google.com/session'><candidate name='rtp'
address='192.168.1.60' port='11262' username='46d9f34967870b77'
password='5a6a34fd4691d8e1' preference='1.00' protocol='udp'
type='local' network='0' generation='0'/><transport
xmlns='http://www.google.com/transport/p2p'/></session></iq>
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: XML parsing successful
[Oct 24 21:18:49] VERBOSE[2405] res_jabber.c:
JABBER: asterisk INCOMING: <iq to="MYUSERNAME at gmail.com/gmail02D370A8"
from="+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy"
id="aaaap" type="result"/>
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: JABBER: Handling paktype IQ
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: XML parsing successful
[Oct 24 21:18:49] VERBOSE[2405] res_jabber.c:
JABBER: asterisk INCOMING: <iq to="MYUSERNAME at gmail.com/gmail02D370A8"
from="+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy"
id="aaaaq" type="result"/>
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: JABBER: Handling paktype IQ
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: XML parsing successful
[Oct 24 21:18:49] VERBOSE[2405] res_jabber.c:
JABBER: asterisk INCOMING: <iq
from="+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy"
to="MYUSERNAME at gmail.com/gmail02D370A8"
id="jingle:10.218.20.143-28982014:1:C3955FF9" type="set"><ses:session
type="candidates" id="SIP183646623 at 10.218.118.3"
initiator="+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy"
xmlns:ses="http://www.google.com/session"><ses:candidate name="rtp"
address="74.125.155.126" port="19295" username="DPf6ayX6cVfawsYS"
preference="1.0" protocol="udp" network="mediaproxy" generation="0"
password="" type="relay"/><ses:candidate name="rtp"
address="74.125.155.126" port="19294" username="DPf6ayX6cVfawsYS"
preference="0.6" protocol="tcp" network="mediaproxy" generation="0"
password="" type="relay"/><ses:candidate name="rtp"
address="74.125.155.126" port="443" username="DPf6ayX6cVfawsYS"
preference="0.5" protocol="ssltcp" network="mediaproxy" generation="0"
password="" type="relay"/></ses:session></iq>
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: JABBER: Handling paktype IQ
[Oct 24 21:18:49] DEBUG[2405] chan_gtalk.c: About to add candidate!
[Oct 24 21:18:49] VERBOSE[2405] res_jabber.c:
JABBER: asterisk OUTGOING: <iq type='result'
from='MYUSERNAME at gmail.com/gmail02D370A8'
to='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
id='jingle:10.218.20.143-28982014:1:C3955FF9'/>
[Oct 24 21:18:49] DEBUG[2405] chan_gtalk.c: Candidate Added!
[Oct 24 21:18:49] DEBUG[2405] res_jabber.c: XML parsing successful
[Oct 24 21:18:49] DEBUG[4341] res_rtp_asterisk.c: Setting RTCP address
on RTP instance '0x1b86bc8'
[Oct 24 21:18:50] DEBUG[4341] chan_gtalk.c: Receiving RTP traffic from
IP 74.125.155.126, matches with remote candidate's IP 74.125.155.126
[Oct 24 21:18:50] DEBUG[4341] chan_gtalk.c: Sending STUN request to
74.125.155.126
[Oct 24 21:18:50] DEBUG[4341] chan_gtalk.c: Receiving RTP traffic from
IP 74.125.155.126, matches with remote candidate's IP 74.125.155.126
[Oct 24 21:18:50] DEBUG[4341] chan_gtalk.c: Sending STUN request to
74.125.155.126
[Oct 24 21:18:50] DEBUG[4341] chan_gtalk.c: Receiving RTP traffic from
IP 74.125.155.126, matches with remote candidate's IP 74.125.155.126
[Oct 24 21:18:50] DEBUG[4341] chan_gtalk.c: Sending STUN request to
74.125.155.126
[Oct 24 21:18:50] DEBUG[4341] pbx.c: Launching 'Playback'
[Oct 24 21:18:50] VERBOSE[4341] pbx.c:     -- Executing [s at default:2]
Playback("Gtalk/+1CALLER10DIGIT-12d0", "hello-world") in new stack
[Oct 24 21:18:50] DEBUG[4341] channel.c: Set channel
Gtalk/+1CALLER10DIGIT-12d0 to write format gsm
[Oct 24 21:18:50] DEBUG[4341] res_rtp_asterisk.c: Ooh, format changed
from unknown to ulaw
[Oct 24 21:18:50] DEBUG[4341] res_rtp_asterisk.c: Created smoother:
format: ulaw ms: 20 len: 160
[Oct 24 21:18:50] DEBUG[4341] channel.c: Scheduling timer at (50
requested / 50 actual) timer ticks per second
[Oct 24 21:18:50] VERBOSE[4341] file.c:     --
<Gtalk/+1CALLER10DIGIT-12d0> Playing 'hello-world.gsm' (language 'en')
[Oct 24 21:18:51] DEBUG[4341] chan_gtalk.c: Receiving RTP traffic from
IP 74.125.155.126, matches with remote candidate's IP 74.125.155.126
[Oct 24 21:18:51] DEBUG[4341] chan_gtalk.c: Sending STUN request to
74.125.155.126
[Oct 24 21:18:51] DEBUG[4341] chan_gtalk.c: Receiving RTP traffic from
IP 74.125.155.126, matches with remote candidate's IP 74.125.155.126
[Oct 24 21:18:51] DEBUG[4341] chan_gtalk.c: Sending STUN request to
74.125.155.126
[Oct 24 21:18:51] DEBUG[4341] chan_gtalk.c: Receiving RTP traffic from
IP 74.125.155.126, matches with remote candidate's IP 74.125.155.126
[Oct 24 21:18:51] DEBUG[4341] chan_gtalk.c: Sending STUN request to
74.125.155.126
[Oct 24 21:18:51] DEBUG[4341] channel.c: Scheduling timer at (0
requested / 0 actual) timer ticks per second
[Oct 24 21:18:51] DEBUG[4341] channel.c: Scheduling timer at (0
requested / 0 actual) timer ticks per second
[Oct 24 21:18:51] DEBUG[4341] channel.c: Scheduling timer at (0
requested / 0 actual) timer ticks per second
[Oct 24 21:18:51] DEBUG[4341] channel.c: Set channel
Gtalk/+1CALLER10DIGIT-12d0 to write format ulaw
[Oct 24 21:18:51] DEBUG[4341] pbx.c: Launching 'Hangup'
[Oct 24 21:18:51] VERBOSE[4341] pbx.c:     -- Executing [s at default:3]
Hangup("Gtalk/+1CALLER10DIGIT-12d0", "") in new stack
[Oct 24 21:18:51] DEBUG[4341] pbx.c: Spawn extension (default,s,3)
exited non-zero on 'Gtalk/+1CALLER10DIGIT-12d0'
[Oct 24 21:18:51] VERBOSE[4341] pbx.c:   == Spawn extension (default,
s, 3) exited non-zero on 'Gtalk/+1CALLER10DIGIT-12d0'
[Oct 24 21:18:51] DEBUG[4341] channel.c: Soft-Hanging up channel
'Gtalk/+1CALLER10DIGIT-12d0'
[Oct 24 21:18:51] DEBUG[4341] channel.c: Hanging up channel
'Gtalk/+1CALLER10DIGIT-12d0'
[Oct 24 21:18:51] VERBOSE[4341] res_jabber.c:
JABBER: asterisk OUTGOING: <iq type='set'
from='MYUSERNAME at gmail.com/gmail02D370A8'
to='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
id='aaaar'><session type='terminate' id='SIP183646623 at 10.218.118.3'
initiator='+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy'
xmlns='http://www.google.com/session'/></iq>
[Oct 24 21:18:51] DEBUG[4341] rtp_engine.c: Destroyed RTP instance '0x1b86bc8'
[Oct 24 21:18:51] DEBUG[2399] devicestate.c: No provider found,
checking channel drivers for Gtalk - +1CALLER10DIGIT
[Oct 24 21:18:51] DEBUG[2399] devicestate.c: Changing state for
Gtalk/+1CALLER10DIGIT - state 0 (Unknown)
[Oct 24 21:18:51] DEBUG[2399] devicestate.c: device
'Gtalk/+1CALLER10DIGIT' state '0'
[Oct 24 21:18:51] DEBUG[2434] app_queue.c: Device
'Gtalk/+1CALLER10DIGIT' changed to state '0' (Unknown) but we don't
care because they're not a member of any queue.
[Oct 24 21:18:51] VERBOSE[2405] res_jabber.c:
JABBER: asterisk INCOMING: <iq to="MYUSERNAME at gmail.com/gmail02D370A8"
from="+1CALLER10DIGIT at voice.google.com/srvres-MTAuMjE4LjIwLjE0Mzo5ODEy"
id="aaaar" type="result"/>
[Oct 24 21:18:51] DEBUG[2405] res_jabber.c: JABBER: Handling paktype IQ
[Oct 24 21:18:51] DEBUG[2405] res_jabber.c: XML parsing successful
[Oct 24 21:19:21] VERBOSE[2405] res_jabber.c:
JABBER: Keep alive packet
[Oct 24 21:19:25] VERBOSE[2405] res_jabber.c:
JABBER: asterisk INCOMING: <presence
from="CALLER at gmail.com/androidfe2b05b6ebb0"
to="MYUSERNAME at gmail.com"><priority>24</priority><caps:c
node="http://www.android.com/gtalk/client/caps" ext="pmuc-v1"
ver="1.1" xmlns:caps="http://jabber.org/protocol/caps"/><status/><x
xmlns="vcard-temp:x:update"><photo>3c4fd5045a18d7417b2e4371bdce077ecd6c8355</photo></x></presence>
[Oct 24 21:19:25] DEBUG[2405] res_jabber.c: JABBER: I am available ^_* 13
[Oct 24 21:19:25] DEBUG[2405] res_jabber.c: JABBER: type is available
[Oct 24 21:19:25] DEBUG[2405] res_jabber.c: JABBER: Handling paktype PRESENCE
[Oct 24 21:19:25] DEBUG[2405] res_jabber.c: XML parsing successful

Thanks so much!
-- Vinh