asterisk users - Jun 2004 - Call Pickup problem in Asterisk with SIP phones

I'm having a tough time getting call pickup to work on *.  Here's my
configuration:

X100P with T-1, channels 1-4 voice <---> * <---CISCO 7960 with SIP 6.0
Image

A call comes in, and * picks up and presents a menu. Caller chooses
extension, (in this case ext 103, SIP/wsmith)

Wsmith is sitting in my office, hears his phone ringing, picks up my phone,
gets dial tone, and presses *8.  He gets a reorder (fast busy) on my phone,
and his phone continues to ring (he then curses loudly, and goes racing down
the hall to try to catch the call)

In * , I get a 

Jun  9 15:45:14 NOTICE[229391]: chan_sip.c:5417 handle_request: Nothing to
pick up

I turned on SIP debugging, cleaned out all the Sip register messages that
were flying about while debugging, and present the logs here.  My version is
CVS-05/24/04 

My zapata.conf looks like:

group=1
callgroup=1
pickupgroup=1-4
context=NuFone-Outgoing
signalling = fxs_ks
callprogress=no
callerid="Radiance Technologies" <(251)-445-0045>
usecallerid=yes

My SIP.conf looks like:

sip.conf            [----]  0 L:[105+37 142/142] *(3505/3516b)= c  99 0x63
dtmfmode=inband
mailbox=102
context=Outgoing
callerid="Dean Li" <102>
username=dli
secret=rad1ance
pickupgroup=1

;the ringing SIP phone:
[wsmith]
type=friend
host=dynamic
nat=yes
canreinvite=no
qualify=1000
;defaultip=192.168.30.108
dtmfmode=inband
mailbox=103
context=Outgoing
callerid="Walter Smith" <103>
username=wsmith
secret=******
pickupgroup=1-4

;The phone attempting the *8
[nmartin]
type=friend
host=dynamic
insecure=no
nat=yes
canreinvite=no
qualify=1000
;defaultip=192.168.30.100
dtmfmode=inband
mailbox=105
context=Outgoing
callerid="Nik Martin" <105>
username=nmartin
secret=******
pickupgroup=1-4
callgroup=1



The SIP debug:

pbxMobile*CLI> 
    -- Starting simple switch on 'Zap/1-1'

pbxMobile*CLI> 
    -- Executing Wait("Zap/1-1", "3") in new stack

pbxMobile*CLI> 
    -- Executing Answer("Zap/1-1", "") in new stack

pbxMobile*CLI> 
    -- Executing NoOp("Zap/1-1", ""MOBILE, AL"
<xxxxxxxxx>") in new stack

pbxMobile*CLI> 
    -- Executing Wait("Zap/1-1", "1") in new stack

pbxMobile*CLI> 
Jun  9 15:45:02 WARNING[2211866]: chan_zap.c:3073 zt_handle_event:
Ring/Off-hook in strange state 6 on channel 1

pbxMobile*CLI> 
    -- Executing BackGround("Zap/1-1", "radiancewelcome") in
new stack

pbxMobile*CLI> 
    -- Playing 'radiancewelcome' (language 'en')

pbxMobile*CLI> 
11 headers, 2 lines
  
8 headers, 0 lines

pbxMobile*CLI> 
  == CDR updated on Zap/1-1

pbxMobile*CLI> 
    -- Executing Dial("Zap/1-1", "SIP/wsmith|20|tT") in new
stack

pbxMobile*CLI> 
We're at 172.31.30.3 port 15418

pbxMobile*CLI> 
Answering with preferred capability 4

pbxMobile*CLI> 
Answering with preferred capability 2

pbxMobile*CLI> 
12 headers, 9 lines

pbxMobile*CLI> 
Reliably Transmitting:
INVITE sip:wsmith@172.31.30.11 SIP/2.0 Via: SIP/2.0/UDP
172.31.30.3:5060;branch=z9hG4bK5cc08566 From: "MOBILE, AL"
<sip:xxxxxxxxxx@172.31.30.3>;tag=as05f4b37a To:
<sip:wsmith@172.31.30.11>
Contact: <sip:xxxxxxxxxx@172.31.30.3> Call-ID:
1243b0b263606de8358bfebe3d418293@172.31.30.3 CSeq: 102 INVITE User-Agent:
Asterisk PBX Date: Wed, 09 Jun 2004 20:45:09 GMT Allow: INVITE, ACK, CANCEL,
OPTIONS, BYE, REFER Content-Type: application/sdp Content-Length: 181  v=0
o=root 20260 20260 IN IP4 172.31.30.3 s=session c=IN IP4 172.31.30.3 t=0 0
m=audio 15418 RTP/AVP 0 3 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000
a=silenceSupp:off - - - -  (NAT) to 172.31.30.11:5060

pbxMobile*CLI> 
    -- Called wsmith

pbxMobile*CLI>  
Sip read: 
SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.31.30.3:5060;branch=z9hG4bK5cc08566
From: "MOBILE, AL" <sip:xxxxxxxxxx@172.31.30.3>;tag=as05f4b37a
To:
<sip:wsmith@172.31.30.11> Call-ID:
1243b0b263606de8358bfebe3d418293@172.31.30.3 Date: Wed, 09 Jun 2004 20:48:00
GMT CSeq: 102 INVITE Server: CSCO/6 Contact:
<sip:wsmith@172.31.30.11:5060>
Content-Length: 0  
10 headers, 0 lines

pbxMobile*CLI>  
Sip read: 
SIP/2.0 180 Ringing Via: SIP/2.0/UDP 172.31.30.3:5060;branch=z9hG4bK5cc08566
From: "MOBILE, AL" <sip:xxxxxxxxxx@172.31.30.3>;tag=as05f4b37a
To:
<sip:wsmith@172.31.30.11>;tag=000b46e9ae7e485f2abff4bc-43940b23 Call-ID:
1243b0b263606de8358bfebe3d418293@172.31.30.3 Date: Wed, 09 Jun 2004 20:48:00
GMT CSeq: 102 INVITE Server: CSCO/6 Contact:
<sip:wsmith@172.31.30.11:5060>
Content-Length: 0  
10 headers, 0 lines

pbxMobile*CLI> 
    -- SIP/wsmith-7e27 is ringing

pbxMobile*CLI>  
 

pbxMobile*CLI>  
Sip read: 
INVITE sip:*8@172.31.30.3 SIP/2.0 Via: SIP/2.0/UDP
172.31.30.7:5060;branch=z9hG4bK2408959c From: "105 - Nik Martin"
<sip:nmartin@172.31.30.3>;tag=003094c4481f49565aff56ad-226e8953 To:
<sip:*8@172.31.30.3> Call-ID:
003094c4-481f008d-2e5594fa-365507cc@172.31.30.7 Date: Wed, 09 Jun 2004
20:47:30 GMT CSeq: 101 INVITE User-Agent: CSCO/6 Contact:
<sip:nmartin@172.31.30.7:5060> Expires: 180 Content-Type: application/sdp
Content-Length: 244 Accept: application/sdp Remote-Party-ID: "105 - Nik
Martin"
<sip:nmartin@172.31.30.7>;party=calling;id-type=subscriber;privacy=off;scree
n=no  v=0 o=Cisco-SIPUA 24482 2915 IN IP4 172.31.30.7 s=SIP Call c=IN IP4
172.31.30.7 t=0 0 m=audio 26676 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15 
14 headers, 11 lines
Using latest request as basis request
Sending to 172.31.30.7 : 5060 (non-NAT)
Found audio format UNKN
Found audio format ALAW
Found audio format UNKN
Found audio format UNKN
Found description format PCMU
Found description format PCMA
Found description format G729
Found description format telephone-event
Capabilities: us - 6, them - 268/0, combined - 4
Non-codec capabilities: us - 1, them - 1, combined - 1
Reliably Transmitting (NAT):
SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP
172.31.30.7:5060;branch=z9hG4bK2408959c;received=172.31.30.7 From: "105 -
Nik Martin"
<sip:nmartin@172.31.30.3>;tag=003094c4481f49565aff56ad-226e8953
To: <sip:*8@172.31.30.3>;tag=as6f213426 Call-ID:
003094c4-481f008d-2e5594fa-365507cc@172.31.30.7 CSeq: 101 INVITE User-Agent:
Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact:
<sip:*8@172.31.30.3> Proxy-Authenticate: Digest
realm="asterisk",
nonce="2152fdb4" Content-Length: 0  
 to 172.31.30.7:5060

pbxMobile*CLI>  
Sip read: 
ACK sip:*8@172.31.30.3 SIP/2.0 Via: SIP/2.0/UDP
172.31.30.7:5060;branch=z9hG4bK2408959c From: "105 - Nik Martin"
<sip:nmartin@172.31.30.3>;tag=003094c4481f49565aff56ad-226e8953 To:
<sip:*8@172.31.30.3>;tag=as6f213426 Call-ID:
003094c4-481f008d-2e5594fa-365507cc@172.31.30.7 Date: Wed, 09 Jun 2004
20:47:30 GMT CSeq: 101 ACK Content-Length: 0  
8 headers, 0 lines

pbxMobile*CLI>  
Sip read: 
INVITE sip:*8@172.31.30.3 SIP/2.0 Via: SIP/2.0/UDP
172.31.30.7:5060;branch=z9hG4bK77078702 From: "105 - Nik Martin"
<sip:nmartin@172.31.30.3>;tag=003094c4481f49565aff56ad-226e8953 To:
<sip:*8@172.31.30.3> Call-ID:
003094c4-481f008d-2e5594fa-365507cc@172.31.30.7 Date: Wed, 09 Jun 2004
20:47:30 GMT CSeq: 102 INVITE User-Agent: CSCO/6 Contact:
<sip:nmartin@172.31.30.7:5060> Proxy-Authorization: Digest
username="nmartin",realm="asterisk",uri="sip:172.31.30.3",response="31288731
f7791b64666a923ebe8a16f3",nonce="2152fdb4",algorithm=md5 Expires:
180
Content-Type: application/sdp Content-Length: 244 Remote-Party-ID: "105 -
Nik Martin"
<sip:nmartin@172.31.30.7>;party=calling;id-type=subscriber;privacy=off;scree
n=no  v=0 o=Cisco-SIPUA 24482 2915 IN IP4 172.31.30.7 s=SIP Call c=IN IP4
172.31.30.7 t=0 0 m=audio 26676 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15 
14 headers, 11 lines
Using latest request as basis request
Sending to 172.31.30.7 : 5060 (NAT)
Found audio format UNKN
Found audio format ALAW
Found audio format UNKN
Found audio format UNKN
Found description format PCMU
Found description format PCMA
Found description format G729
Found description format telephone-event
Capabilities: us - 6, them - 268/0, combined - 4
Non-codec capabilities: us - 1, them - 1, combined - 1
Looking for *8 in Outgoing
list_route: hop: <sip:nmartin@172.31.30.7:5060>
Transmitting (NAT):
SIP/2.0 100 Trying Via: SIP/2.0/UDP
172.31.30.7:5060;branch=z9hG4bK77078702;received=172.31.30.7 From: "105 -
Nik Martin"
<sip:nmartin@172.31.30.3>;tag=003094c4481f49565aff56ad-226e8953
To: <sip:*8@172.31.30.3>;tag=as200f8b5c Call-ID:
003094c4-481f008d-2e5594fa-365507cc@172.31.30.7 CSeq: 102 INVITE User-Agent:
Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact:
<sip:*8@172.31.30.3> Content-Length: 0  
 to 172.31.30.7:5060
Jun  9 15:45:14 NOTICE[229391]: chan_sip.c:5417 handle_request: Nothing to
pick up
Reliably Transmitting (NAT):
SIP/2.0 503 Unavailable Via: SIP/2.0/UDP
172.31.30.7:5060;branch=z9hG4bK77078702;received=172.31.30.7 From: "105 -
Nik Martin"
<sip:nmartin@172.31.30.3>;tag=003094c4481f49565aff56ad-226e8953
To: <sip:*8@172.31.30.3>;tag=as200f8b5c Call-ID:
003094c4-481f008d-2e5594fa-365507cc@172.31.30.7 CSeq: 102 INVITE User-Agent:
Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact:
<sip:*8@172.31.30.3> Content-Length: 0  
 to 172.31.30.7:5060

pbxMobile*CLI>  
Sip read: 
ACK sip:*8@172.31.30.3 SIP/2.0 Via: SIP/2.0/UDP
172.31.30.7:5060;branch=z9hG4bK77078702 From: "105 - Nik Martin"
<sip:nmartin@172.31.30.3>;tag=003094c4481f49565aff56ad-226e8953 To:
<sip:*8@172.31.30.3>;tag=as200f8b5c Call-ID:
003094c4-481f008d-2e5594fa-365507cc@172.31.30.7 Date: Wed, 09 Jun 2004
20:47:30 GMT CSeq: 102 ACK Content-Length: 0  
8 headers, 0 lines

pbxMobile*CLI> 
Reliably Transmitting:
CANCEL sip:wsmith@172.31.30.11:5060 SIP/2.0 Via: SIP/2.0/UDP
172.31.30.3:5060;branch=z9hG4bK5cc08566 From: "MOBILE, AL"
<sip:xxxxxxxxxx@172.31.30.3>;tag=as05f4b37a To:
<sip:wsmith@172.31.30.11>
Contact: <sip:xxxxxxxxxx@172.31.30.3> Call-ID:
1243b0b263606de8358bfebe3d418293@172.31.30.3 CSeq: 102 CANCEL User-Agent:
Asterisk PBX Content-Length: 0   (NAT) to 172.31.30.11:5060
  == Spawn extension (default, 103, 1) exited non-zero on 'Zap/1-1'
    -- Executing Hangup("Zap/1-1", "") in new stack
  == Spawn extension (default, h, 1) exited non-zero on 'Zap/1-1'
    -- Hungup 'Zap/1-1'

pbxMobile*CLI>  
Sip read: 
SIP/2.0 200 OK Via: SIP/2.0/UDP 172.31.30.3:5060;branch=z9hG4bK5cc08566
From: "MOBILE, AL" <sip:xxxxxxxxxx@172.31.30.3>;tag=as05f4b37a
To:
<sip:wsmith@172.31.30.11>;tag=000b46e9ae7e485f2abff4bc-43940b23 Call-ID:
1243b0b263606de8358bfebe3d418293@172.31.30.3 Date: Wed, 09 Jun 2004 20:48:19
GMT CSeq: 102 CANCEL Server: CSCO/6 Content-Length: 0  
9 headers, 0 lines

pbxMobile*CLI>  
Sip read: 
SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP
172.31.30.3:5060;branch=z9hG4bK5cc08566 From: "MOBILE, AL"
<sip:xxxxxxxxxx@172.31.30.3>;tag=as05f4b37a To:
<sip:wsmith@172.31.30.11>;tag=000b46e9ae7e485f2abff4bc-43940b23 Call-ID:
1243b0b263606de8358bfebe3d418293@172.31.30.3 Date: Wed, 09 Jun 2004 20:48:19
GMT CSeq: 102 INVITE Server: CSCO/6 Contact:
<sip:wsmith@172.31.30.11:5060>
Content-Length: 0  
10 headers, 0 lines
Transmitting:
ACK sip:wsmith@172.31.30.11:5060 SIP/2.0 Via: SIP/2.0/UDP
172.31.30.3:5060;branch=z9hG4bK5cc08566 From: "MOBILE, AL"
<sip:xxxxxxxxxx@172.31.30.3>;tag=as05f4b37a To:
<sip:wsmith@172.31.30.11>;tag=000b46e9ae7e485f2abff4bc-43940b23 Contact:
<sip:xxxxxxxxxx@172.31.30.3> Call-ID:
1243b0b263606de8358bfebe3d418293@172.31.30.3 CSeq: 102 ACK User-Agent:
Asterisk PBX Content-Length: 0   (NAT) to 172.31.30.11:5060

pbxMobile*CLI> sip debugexitsip no debug pbxMobile*CLI> 
SIP Debugging Disabled

pbxMobile*CLI> exit root@pbxMobile:~# logout