SPA3201 - Incoming Call gets cancelled "CSeq: 101 CANCEL"

Dear All,

For the last month or so I have been fighting with my SPA3102. Altough it is a fine piece of software with losts of funtionally the stability is still hard to get.

The environment consists of a trixbox, a SPA941 and a SPA3102 connected to PSTN Line. I have been able to make both outoing and incoming calls the last ones have now a terrible behaviour: it looks as if SPA3102 hangs teh call and dials back again; from the PSTN caller perspective the call is still ringing.

The CLI output follows:
<--- SIP read from 192.168.1.189:5061 --->
INVITE sip:'at'192.168.1.252 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.189:5061;branch=z9hG4bK-97e8a7e0
From: 'at'192.168.1.252>;tag=6baa9984fe2fe440o1
To: 'at'192.168.1.252>
Call-ID: da2365d4-84cd0430'at'192.168.1.189
CSeq: 101 INVITE
Max-Forwards: 70
Contact: 'at'192.168.1.189:5061>
Expires: 240
User-Agent: Linksys/SPA3102-5.1.7(GW)
Content-Length: 255
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: x-sipura, replaces
Content-Type: application/sdp

v=0
o=- 138613 138613 IN IP4 192.168.1.189
s=-
c=IN IP4 192.168.1.189
t=0 0
m=audio 16392 RTP/AVP 0 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

<------------->
--- (14 headers 13 lines) ---
Sending to 192.168.1.189 : 5061 (no NAT)
Using INVITE request as basis request - da2365d4-84cd0430'at'192.168.1.189
Found peer ''
Found RTP audio format 0
Found RTP audio format 100
Found RTP audio format 101
Peer audio RTP is at port 192.168.1.189:16392
Found audio description format PCMU for ID 0
Found unknown media description format NSE for ID 100
Got unsupported a:fmtp in SDP offer
Found audio description format telephone-event for ID 101
Got unsupported a:fmtp in SDP offer
Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
Peer audio RTP is at port 192.168.1.189:16392
Looking for in from-trunk (domain 192.168.1.252)
list_route: hop: 'at'192.168.1.189:5061>

<--- Transmitting (no NAT) to 192.168.1.189:5061 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.189:5061;branch=z9hG4bK-97e8a7e0;received=192.168.1.189
From: 'at'192.168.1.252>;tag=6baa9984fe2fe440o1
To: 'at'192.168.1.252>
Call-ID: da2365d4-84cd0430'at'192.168.1.189
CSeq: 101 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: 'at'192.168.1.252>
Content-Length: 0

<------------>
-- Executing ['at'from-trunk:1] Set("SIP/-08ee87e0", "__FROM_DID=") in new stack
-- Executing ['at'from-trunk:2] Gosub("SIP/-08ee87e0", "app-blacklist-check|s|1") in new stack
-- Executing [s'at'app-blacklist-check:1] LookupBlacklist("SIP/-08ee87e0", "") in new stack
-- Executing [s'at'app-blacklist-check:2] GotoIf("SIP/-08ee87e0", "0?blacklisted") in new stack
-- Executing [s'at'app-blacklist-check:3] Return("SIP/-08ee87e0", "") in new stack
-- Executing ['at'from-trunk:3] GotoIf("SIP/-08ee87e0", "0 ?cidok") in new stack
-- Executing ['at'from-trunk:4] Set("SIP/-08ee87e0", "CALLERID(name)=0") in new stack
-- Executing ['at'from-trunk:5] NoOp("SIP/-08ee87e0", "CallerID is "0" <0>") in new stack
-- Executing ['at'from-trunk:6] Set("SIP/-08ee87e0", "__CALLINGPRES_SV=allowed_not_screened") in new stack
-- Executing ['at'from-trunk:7] SetCallerPres("SIP/-08ee87e0", "allowed_not_screened") in new stack
-- Executing ['at'from-trunk:8] Goto("SIP/-08ee87e0", "ext-group|600|1") in new stack
-- Goto (ext-group,600,1)
-- Executing [600'at'ext-group:1] Macro("SIP/-08ee87e0", "user-callerid|") in new stack
-- Executing [s'at'macro-user-callerid:1] NoOp("SIP/-08ee87e0", "user-callerid: 0 0") in new stack
-- Executing [s'at'macro-user-callerid:2] Set("SIP/-08ee87e0", "AMPUSER=0") in new stack
-- Executing [s'at'macro-user-callerid:3] GotoIf("SIP/-08ee87e0", "0?report") in new stack
-- Executing [s'at'macro-user-callerid:4] ExecIf("SIP/-08ee87e0", "1|Set|REALCALLERIDNUM=0") in new stack
-- Executing [s'at'macro-user-callerid:5] NoOp("SIP/-08ee87e0", "REALCALLERIDNUM is 0") in new stack
-- Executing [s'at'macro-user-callerid:6] Set("SIP/-08ee87e0", "AMPUSER=") in new stack
-- Executing [s'at'macro-user-callerid:7] Set("SIP/-08ee87e0", "AMPUSERCIDNAME=") in new stack
-- Executing [s'at'macro-user-callerid:8] GotoIf("SIP/-08ee87e0", "1?report") in new stack
-- Goto (macro-user-callerid,s,13)
-- Executing [s'at'macro-user-callerid:13] NoOp("SIP/-08ee87e0", "TTL: ARG1: ") in new stack
-- Executing [s'at'macro-user-callerid:14] GotoIf("SIP/-08ee87e0", "0?continue") in new stack
-- Executing [s'at'macro-user-callerid:15] Set("SIP/-08ee87e0", "__TTL=64") in new stack
-- Executing [s'at'macro-user-callerid:16] GotoIf("SIP/-08ee87e0", "1?continue") in new stack
-- Goto (macro-user-callerid,s,23)
-- Executing [s'at'macro-user-callerid:23] NoOp("SIP/-08ee87e0", "Using CallerID "0" <0>") in new stack
-- Executing [600'at'ext-group:2] GotoIf("SIP/-08ee87e0", "1?skipdb") in new stack
-- Goto (ext-group,600,4)
-- Executing [600'at'ext-group:4] Set("SIP/-08ee87e0", "__NODEST=") in new stack
-- Executing [600'at'ext-group:5] Set("SIP/-08ee87e0", "__BLKVM_OVERRIDE=BLKVM/600/SIP/-08ee87e0") in new stack
-- Executing [600'at'ext-group:6] Set("SIP/-08ee87e0", "__BLKVM_BASE=600") in new stack
-- Executing [600'at'ext-group:7] Set("SIP/-08ee87e0", "DB(BLKVM/600/SIP/-08ee87e0)=TRUE") in new stack
-- Executing [600'at'ext-group:8] Set("SIP/-08ee87e0", "RRNODEST=") in new stack
-- Executing [600'at'ext-group:9] Set("SIP/-08ee87e0", "__NODEST=600") in new stack
-- Executing [600'at'ext-group:10] Set("SIP/-08ee87e0", "RecordMethod=Group") in new stack
-- Executing [600'at'ext-group:11] Macro("SIP/-08ee87e0", "record-enable|200|Group") in new stack
-- Executing [s'at'macro-record-enable:1] GotoIf("SIP/-08ee87e0", "0?2:4") in new stack
-- Goto (macro-record-enable,s,4)
-- Executing [s'at'macro-record-enable:4] AGI("SIP/-08ee87e0", "recordingcheck|20080820-235342|1219272821.70") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
-- AGI Script recordingcheck completed, returning 0
-- Executing [s'at'macro-record-enable:5] NoOp("SIP/-08ee87e0", "No recording needed") in new stack
-- Executing [600'at'ext-group:12] Set("SIP/-08ee87e0", "RingGroupMethod=ringall") in new stack
-- Executing [600'at'ext-group:13] Macro("SIP/-08ee87e0", "dial|10|tr|200") in new stack
-- Executing [s'at'macro-dial:1] GotoIf("SIP/-08ee87e0", "1?dial") in new stack
-- Goto (macro-dial,s,3)
-- Executing [s'at'macro-dial:3] AGI("SIP/-08ee87e0", "dialparties.agi") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
== Parsing '/etc/asterisk/manager.conf': Found
== Parsing '/etc/asterisk/manager_additional.conf': Found
== Parsing '/etc/asterisk/manager_custom.conf': Found
== Manager 'admin' logged on from 127.0.0.1
dialparties.agi: Caller ID name is '0' number is '0'
dialparties.agi: USE_CONFIRMATION: 'FALSE'
dialparties.agi: RINGGROUP_INDEX: ''
dialparties.agi: Methodology of ring is 'ringall'
-- dialparties.agi: Added extension 200 to extension map
-- dialparties.agi: Extension 200 cf is disabled
-- dialparties.agi: Extension 200 do not disturb is disabled
> dialparties.agi: extnum 200 has: cw: 1; hascfb: 0 [] hascfu: 0 []
-- dialparties.agi: dbset CALLTRACE/200 to 0
-- dialparties.agi: Filtered ARG3: 200
> dialparties.agi: NODEST: 600 adding M(auto-blkvm) to dialopts: trM(auto-blkvm)
> dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: trM(auto-blkvm)
== Manager 'admin' logged off from 127.0.0.1
-- AGI Script dialparties.agi completed, returning 0
-- Executing [s'at'macro-dial:7] Dial("SIP/-08ee87e0", "SIP/200|10|trM(auto-blkvm)") in new stack
-- Called 200
trixbox1*CLI>

SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.1.189:5061;branch=z9hG4bK-97e8a7e0;received=192.168.1.189
From: 'at'192.168.1.252>;tag=6baa9984fe2fe440o1
To: 'at'192.168.1.252>;tag=as462fa14c
Call-ID: da2365d4-84cd0430'at'192.168.1.189
CSeq: 101 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: 'at'192.168.1.252>
Content-Length: 0

<------------>
-- SIP/200-08f35dc8 is ringing
trixbox1*CLI>
<--- SIP read from 192.168.1.189:5061 --->
CANCEL sip:'at'192.168.1.252 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.189:5061;branch=z9hG4bK-97e8a7e0
From: 'at'192.168.1.252>;tag=6baa9984fe2fe440o1
To: 'at'192.168.1.252>
Call-ID: da2365d4-84cd0430'at'192.168.1.189
CSeq: 101 CANCEL
Max-Forwards: 70
User-Agent: Linksys/SPA3102-5.1.7(GW)
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---
Sending to 192.168.1.189 : 5061 (no NAT)

<--- Reliably Transmitting (no NAT) to 192.168.1.189:5061 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 192.168.1.189:5061;branch=z9hG4bK-97e8a7e0;received=192.168.1.189
From: 'at'192.168.1.252>;tag=6baa9984fe2fe440o1
To: 'at'192.168.1.252>;tag=as462fa14c
Call-ID: da2365d4-84cd0430'at'192.168.1.189
CSeq: 101 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0

<------------>
trixbox1*CLI>
<--- Transmitting (no NAT) to 192.168.1.189:5061 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.189:5061;branch=z9hG4bK-97e8a7e0;received=192.168.1.189
From: 'at'192.168.1.252>;tag=6baa9984fe2fe440o1
To: 'at'192.168.1.252>;tag=as462fa14c
Call-ID: da2365d4-84cd0430'at'192.168.1.189
CSeq: 101 CANCEL
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: 'at'192.168.1.252>
Content-Length: 0

<------------>
== Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/-08ee87e0'
-- Executing [h'at'macro-dial:1] Macro("SIP/-08ee87e0", "hangupcall") in new stack

Wierdly the second time SPA3102 establishes the call the Calling Number shown is the PSTN Number and not the PSTN Caller Number.

Have you come across such behaviour? How have you solved it?
Thanks in advance,
nbviegas