Solved: Need help with Cisco phone and "Call ID match not found: Rejecti

artisticcheese · ‎08-09-2011

Hello,

I have SIP configured Cisco 7960 phone which is receiving incoming SIP call and rejecting it. SIP debug messages are below telling something about "Call ID match not found". What does this mean?

[11:02:38:369711] sipTransportSendMessage: Closed a one-time UDP send channel handle = 5

[11:02:38:369716] SIPTaskProcessListEvent: cmd = 0x160200

[11:02:38:369716] SIPProcessUDPMessage: recv UDP message from <69.59.142.213>:<50195>, length=<354>, message=

[11:02:38:369717] ACK sip:artisticcheese@192.168.1.80:8061;transport=udp SIP/2.0

Via: SIP/2.0/UDP 69.59.142.213:5060;branch=z9hG4bKadee01b823f34ae5b1226228b8d87925;rport

To: <sip:artisticcheese@sipsorcery.com>

From: "FRISCO TX" <sip:9721111111@66.54.140.46>;tag=1158419552

Call-ID: a46dd5fa862040f995618fee7ba64eec

CSeq: 1 ACK

Max-Forwards: 69

Content-Length: 0

[11:02:38:369719] SIPTaskProcessSIPMessage: Line filter: Determining destination line...

[11:02:38:369721] SIPTaskProcessSIPMessage: Line filter: Previous Call ID. Message not in reTx list.

[11:02:38:369721] SIPTaskProcessSIPMessage: Line filter: Call ID match not found: Rejecting.

jleehawkins · ‎08-10-2011

The problem is the proxy port on line one.

The SIP INVITE is being sent to port 5060, the default SIP port number.

Via: SIP/2.0/UDP 69.59.142.213:5060

Contact: <69.59.142.213:5060>

Notice what port calls are being sent to on line two.

Via: SIP/2.0/UDP 204.11.192.23:5080

So either change the proxy port on line one to 5060 or tell your SP to send calls to port 5070.

Let me know how it turns out.

View solution in original post

Jonathan Schulenberg · ‎08-09-2011

Can we see the rest of this SIP call dialog? Is the Call-ID header, the tag of the From header, and the branch of the Via consistant since the INVITE was received?

artisticcheese · ‎08-09-2011

Here is entire communication

debugs: timestamp

SIP Phone> debug ?

console-stall malloc-table sk-platform flash http timestamp timers dsp dsp-keepa

live vcm dtmf cpr-info task-socket xml-events xml-deck xml-vars xml-post lsm fsm

auth fim gsm cc cc-msg sip-task sip-state sip-messages sip-reg-state sip-trx cd

p dns sntp sntp-packet config

debugs: timestamp

SIP Phone> debug sip-task sip-state sip-messages sip-reg-state sip-trx

Enabling bug logging on this terminal - use 'tty mon 0' to disable

debugs: timestamp sip-task sip-state sip-messages sip-reg-state sip-trx

SIP Phone> [05:51:06:11435] SIPTaskProcessListEvent: cmd = 0x160200

[05:51:06:11435] SIPProcessUDPMessage: recv UDP message from <69.59.142.213>:<50

195>, length=<794>, message=

[05:51:06:11435] INVITE sip:artisticcheese@192.168.1.80:8061;transport=udp SIP/2

.0

Via: SIP/2.0/UDP 69.59.142.213:5060;branch=z9hG4bK4e958931769b4e32b97b84ecc457fe

f2;rport

To: <>artisticcheese@sipsorcery.com>

From: "IRVING TX" <>;tag=1238637560

Call-ID: 593fcd9141194c7d8898d534ccaddc08

CSeq: 1 INVITE

Contact: <69.59.142.213:5060>

Max-Forwards: 69

User-Agent: www.sipsorcery.com

Content-Length: 334

Content-Type: application/sdp

v=0

o=root 16544 16544 IN IP4 66.54.140.46

s=session

c=IN IP4 66.54.140.46

t=0 0

m=audio 21864 RTP/AVP 0 8 3 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:3 GSM/8000

a=rtpmap:18 G729/8000

a=fmtp:18 annexb=no

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=silenceSupp:off - - - -

a=ptime:20

a=sendrecv

[05:51:06:11438] SIPTaskProcessSIPMessage: Line filter: Determining destination

line...

[05:51:06:11440] SIPTaskProcessSIPMessage: Line filter: Call ID match not found:

INVITE: free ccb index = 0.

[05:51:06:11441] Unknown address in Request URI

[05:51:06:11441] sipSPICheckRequest: Request URI Not Found

[05:51:06:11442] SIPTaskProcessSIPMessage: Error: sipSPICheckRequest() returned

error.

[05:51:06:11442] sipSPISendErrorResponse: Sending response 404...

[05:51:06:11444] sipRelDevCoupledMessageStore: Storing for reTx (cseq=1, method=

INVITE, to_tag=<>)

[05:51:06:11445] sipTransportSendMessage: Opened a one-time UDP send channel to

server <69.59.142.213>:<5060>, handle = 6 local port= 8061

[05:51:06:11446] sipTransportSendMessage:Sent SIP message to <69.59.142.213>:<50

60>, handle=<6>, length=<298>, message=

[05:51:06:11446] SIP/2.0 404 Not Found

Via: SIP/2.0/UDP 69.59.142.213:5060;branch=z9hG4bK4e958931769b4e32b97b84ecc457fe

f2;rport

From: "IRVING TX" <>;tag=1238637560

To: <>artisticcheese@sipsorcery.com>

Call-ID: 593fcd9141194c7d8898d534ccaddc08

CSeq: 1 INVITE

Content-Length: 0

[05:51:06:11447] sipTransportSendMessage: Closed a one-time UDP send channel han

dle = 6

[05:51:06:11452] SIPTaskProcessListEvent: cmd = 0x160200

[05:51:06:11453] SIPProcessUDPMessage: recv UDP message from <69.59.142.213>:<50

195>, length=<354>, message=

[05:51:06:11453] ACK sip:artisticcheese@192.168.1.80:8061;transport=udp SIP/2.0

Via: SIP/2.0/UDP 69.59.142.213:5060;branch=z9hG4bK4e958931769b4e32b97b84ecc457fe

f2;rport

To: <>artisticcheese@sipsorcery.com>

From: "IRVING TX" <>;tag=1238637560

Call-ID: 593fcd9141194c7d8898d534ccaddc08

CSeq: 1 ACK

Max-Forwards: 69

Content-Length: 0

[05:51:06:11455] SIPTaskProcessSIPMessage: Line filter: Determining destination

line...

[05:51:06:11457] SIPTaskProcessSIPMessage: Line filter: Previous Call ID. Messag

e not in reTx list.

[05:51:06:11457] SIPTaskProcessSIPMessage: Line filter: Call ID match not found:

Rejecting.

Mohsin Khan Feroz · ‎08-09-2011

Whats the firmware version of you 7960?

artisticcheese · ‎08-09-2011

Cisco IP phone MAC: 000b:beb2:5f93

Loadid: SW: P0S3-08-11-00 ARM: PAS3ARM1 Boot: PC030301 DSP: 4.0(5.0)[A0]

charbles2006 · ‎08-10-2011

Does the actual handset rings when you receive inbound call?

Sent from Cisco Technical Support iPad App

artisticcheese · ‎08-10-2011

No. It immediately gives busy signal back to caller.

charbles2006 · ‎08-10-2011

Can send dial peer de bugs

Sent from Cisco Technical Support iPad App

artisticcheese · ‎08-10-2011

? I don't understand. How do I fix it?

charbles2006 wrote:

Can send dial peer de bugs

Sent from Cisco Technical Support iPad App

jleehawkins · ‎08-10-2011

Does your 7960 have a directory number assigned to it?

What are you using as your call processor or registrar server?

It looks like what is happening is your phone is receiving an INVITE to artisticcheese@sipsorcery.com but the phone doesn't have a line to attached the call to.

artisticcheese · ‎08-10-2011

Entire configuration file is below. Failure happens when call comes to first number but rings fine if it comes to second one.

How do I make phone accept call on line 1 if it comes to "artisticcheese@sipsorcery.com"?

line1_displayname: "12063125984"

line1_name: "artisticcheese"

line1_authname: "artisticcheese"

line1_password: "mypass"

proxy1_address: "sipsorcery.com"

proxy1_port: 5070

line2_displayname: "17772702653"

line2_name: "17772702653"

line2_authname: "17772702653"

line2_password: "mypass"

proxy2_address: "callcentric.com"

proxy2_port: 5080

jleehawkins · ‎08-10-2011

Can you send a debug for a call that works on the second line?

artisticcheese · ‎08-10-2011

Here is log from successfull connection to line2

_STATE_RECV_INVITE_PROCEEDING <- E_CC_ALERTING

[15:52:34:29477] SIPSPISendInviteResponse: Sending response 180...

[15:52:34:29478] get_method_request_trx_index: Getting TRX for method(INVITE), s

ent = 0

[15:52:34:29478] get_method_request_trx_index: Got TRX(0) for recv method(INVITE

)

[15:52:34:29480] get_method_request_trx_index: Getting TRX for method(INVITE), s

ent = 0

[15:52:34:29480] get_method_request_trx_index: Got TRX(0) for recv method(INVITE

)

[15:52:34:29482] get_method_request_trx_index: Getting TRX for method(INVITE), s

ent = 0

[15:52:34:29483] get_method_request_trx_index: Got TRX(0) for recv method(INVITE

)

[15:52:34:29484] sipRelDevCoupledMessageStore: Storing for reTx (cseq=102, metho

d=INVITE, to_tag=<000bbeb25f93000879c60471-48abd6c0>)

[15:52:34:29486] sipTransportSendMessage: ccb <0>: config <204.11.192.23>:<5080>

- remote <204.11.192.23>:<5080>

[15:52:34:29487] sipTransportSendMessage: Got handle 3

[15:52:34:29487] sipTransportSendMessage: Opened a one-time UDP send channel to

server <204.11.192.23>:<5080>, handle = 8 local port= 5060

[15:52:34:29488] sipTransportSendMessage:Sent SIP message to <204.11.192.23>:<50

80>, handle=<8>, length=<645>, message=

[15:52:34:29488] SIP/2.0 180 Ringing

Via: SIP/2.0/UDP 204.11.192.23:5080;branch=z9hG4bK-f3f7641485ff0585c0d78897f3b14

a33

From: <9729872279>;tag=as4f0cb9d2

To: <>17772702653@ss.callcentric.com>;tag=000bbeb25f93000879c60471-48abd6c0

Call-ID: 039317b1746141a34cd428a61ec57e86@66.54.140.46

Date: Wed, 10 Aug 2011 19:52:34 GMT

CSeq: 102 INVITE

Server: Cisco-CP7960G/8.0

Contact: <17772702653>

Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE

Remote-Party-ID: "17772702653" <>17772702653@callcentric.com>;party=called;id

-type=subscriber;privacy=off;screen=yes

Content-Length: 0

[15:52:34:29490] sipTransportSendMessage: Closed a one-time UDP send channel han

dle = 8

[15:52:34:29490] LINE 0/2: sipTransportSendMessage : Stopping reTx ti

mer

[15:52:34:29490] CHANGE STATE: LINE 0/2: : St

ate change: SIP_STATE_RECV_INVITE_PROCEEDING -> SIP_STATE_RECV_INVITE_ALERTING

[15:52:41:30102] SIPTaskProcessListEvent: cmd = 0x0

[15:52:41:30102] LINE 7/2: --0x00071cdf-- : SIP_REG_STATE_RE

GISTERED <- E_SIP_REG_TMR_EXPIRE

[15:52:41:30102] LINE 7/2: sip_sm_call_cleanup : Cleaning up the

call

[15:52:41:30103] ccsip_register_send_msg: cmd=0x161c01

[15:52:41:30103] SIPTaskProcessListEvent: cmd = 0x161c01

[15:52:41:30104] LINE 7/2: --0x00071bc5-- : SIP_REG_STATE_ID

LE <- E_SIP_REG_REG_REQ

[15:52:41:30104] SIPSPISendRegister: Sending REGISTER...

[15:52:41:30105] get_next_request_trx_index: Getting next TRX index, sent = 1

[15:52:41:30106] get_next_request_trx_index: Got TRX(0) for sent req

[15:52:41:30106] get_last_request_trx_index: Getting last TRX index, sent = 1

[15:52:41:30106] get_last_request_trx_index: Got TRX(0) for sent req

[15:52:41:30108] get_last_request_trx_index: Getting last TRX index, sent = 1

[15:52:41:30108] get_last_request_trx_index: Got TRX(0) for sent req

[15:52:41:30110] get_last_request_trx_index: Getting last TRX index, sent = 1

[15:52:41:30111] get_last_request_trx_index: Got TRX(0) for sent req

[15:52:41:30112] sipTransportSendMessage: ccb <7>: config <204.11.192.23>:<5080>

- remote <204.11.192.23>:<5080>

[15:52:41:30113] sipTransportSendMessage: Got handle 3

[15:52:41:30113] sipTransportSendMessage: Opened a one-time UDP send channel to

server <204.11.192.23>:<5080>, handle = 8 local port= 5060

[15:52:41:30114] sipTransportSendMessage:Sent SIP message to <204.11.192.23>:<50

80>, handle=<8>, length=<570>, message=

[15:52:41:30114] REGISTER sip:callcentric.com SIP/2.0

Via: SIP/2.0/UDP 192.168.1.80:5060;branch=z9hG4bK55dc5072

From: <>17772702653@callcentric.com>;tag=000bbeb25f93000928ecd406-4fbba26e

To: <>17772702653@callcentric.com>

Call-ID: 000bbeb2-5f930003-228788c8-5067d40e@192.168.1.80

Max-Forwards: 70

Date: Wed, 10 Aug 2011 19:52:41 GMT

CSeq: 107 REGISTER

User-Agent: Cisco-CP7960G/8.0

Contact: <17772702653>;+sip.instance="

uid:00000000-0000-0000-0000-000bbeb25f93>";+u.sip!model.ccm.cisco.com="7"

Content-Length: 0

Expires: 600

[15:52:41:30116] sipTransportSendMessage: Closed a one-time UDP send channel han

dle = 8

[15:52:41:30116] LINE 7/2: sipTransportSendMessage : Stopping reTx ti

mer

[15:52:41:30117] LINE 7/2: sipTransportSendMessage : Starting reTx ti

mer (500 msec)

[15:52:41:30117] LINE 7/2: Registration state change: SIP_REG_STATE_IDLE ---> SI

P_REG_STATE_REGISTERING

[15:52:41:30120] SIPTaskProcessListEvent: cmd = 0x160200

[15:52:41:30121] SIPProcessUDPMessage: recv UDP message from <204.11.192.23>:<55

Z315>, length=<461>, message=

[15:52:41:30121] SIP/2.0 200 Ok

v: SIP/2.0/UDP 192.168.1.80:5060;branch=z9hG4bK55dc5072;rport=5060;received=71.2

52.223.116

f: <>17772702653@callcentric.com>;tag=000bbeb25f93000928ecd406-4fbba26e

t: <>17772702653@callcentric.com>

i: 000bbeb2-5f930003-228788c8-5067d40e@192.168.1.80

CSeq: 107 REGISTER

m: <17772702653>;+sip.instance="

000000-0000-0000-0000-000bbeb25f93>";+u.sip!model.ccm.cisco.com=7;expires=65

l: 0

[15:52:41:30123] SIPTaskProcessSIPMessage: Line filter: Determining destination

line...

[15:52:41:30124] get_method_request_trx_index: Getting TRX for method(REGISTER),

sent = 1

[15:52:41:30124] get_method_request_trx_index: Got TRX(0) for sent method(REGIST

ER)

[15:52:41:30125] sip_sm_ccb_match_branch_cseq: Matched branch_id & CSeq

[15:52:41:30125] SIPTaskProcessSIPMessage: Line filter: Call ID match: Destinat

ion line = <7/2>.

[15:52:41:30126] SIPTaskProcessSIPMessage: Received SIP response.

[15:52:41:30127] get_method_request_trx_index: Getting TRX for method(REGISTER),

sent = 1

[15:52:41:30127] get_method_request_trx_index: Got TRX(0) for sent method(REGIST

ER)

[15:52:41:30128] sipSPICheckResponse: Response match: callid=000bbeb2-5f930003-2

28788c8-5067d40e@192.168.1.80, cseq=107, cseq_method=REGISTER

[15:52:41:30128] SIPTaskProcessSIPMessage: Stopping any outstanding reTx timers.

..

[15:52:41:30130] LINE 7/2: sip_sm_check_retx_timers : Stopping reTx ti

mer.

(callid=000bbeb2-5f930003-228788c8-5067d40e@192.168.1.80, cseq=107, cseq_method=

REGISTER)

[15:52:41:30131] SIPTaskProcessSIPMessage: Recv 2xx message.

[15:52:41:30131] LINE 7/2: --0x00072199-- : SIP_REG_STATE_RE

GISTERING <- E_SIP_REG_2xx

[15:52:41:30132] LINE 7/2: Registration state change: SIP_REG_STATE_REGISTERING

---> SIP_REG_STATE_REGISTERED

[15:52:41:30133] ccsip_handle_ev_2xx ui_set_sip_registration_state to TRUE 2

[15:52:41:30133] clean_method_request_trx: Removing TRX for method(REGISTER), se

nt = 1

[15:52:41:30133] clean_method_request_trx: Removed TRX(0) for method(REGISTER)

[15:52:41:30134] LINE 7/2: ccsip_get_exp_time_2xx : Using proxy expi

res value

[15:52:41:30135] LINE 7/2: ccsip_handle_ev_2xx : Starting expires

timer (60 sec)

[15:52:41:30135] sip_regmgr_trigger_fallback_monitor: Looking to trigger fallbac

k if any available

[15:52:43:30392] SIPTaskProcessListEvent: cmd = 0x160200

[15:52:43:30392] SIPProcessUDPMessage: recv UDP message from <204.11.192.23>:<55

315>, length=<331>, message=

[15:52:43:30392] CANCEL sip:17772702653@192.168.1.80:5060;transport=udp SIP/2.0

v: SIP/2.0/UDP 204.11.192.23:5080;branch=z9hG4bK-f3f7641485ff0585c0d78897f3b14a3

3

f: <9729872279>;tag=as4f0cb9d2

t: <>17772702653@ss.callcentric.com>

i: 039317b1746141a34cd428a61ec57e86@66.54.140.46

CSeq: 102 CANCEL

Max-Forwards: 15

l: 0

jleehawkins · ‎08-10-2011

The problem is the proxy port on line one.

The SIP INVITE is being sent to port 5060, the default SIP port number.

Via: SIP/2.0/UDP 69.59.142.213:5060

Contact: <69.59.142.213:5060>

Notice what port calls are being sent to on line two.

Via: SIP/2.0/UDP 204.11.192.23:5080

So either change the proxy port on line one to 5060 or tell your SP to send calls to port 5070.

Let me know how it turns out.

Need help with Cisco phone and "Call ID match not found: Rejecting" message