Tuesday, October 19, 2010

One of the many reasons for the following OCS 2007 R2 MOC error: “Call was not completed or has ended.”

Unfortunately, the policy applied to my computer is set to overwrite logs which meant I wasn’t able to capture the local logs on my laptop in time to see what was written so the only error I have available is the screenshot I took when I encountered this problem.

Call was not completed or has ended.

image

While this error is pretty generic, one of the many reasons that you may receive this is as follows:

  1. You’ve recently reconfigured your location profiles by removing it, creating a new one, configure normalization rules and then assigning the location profile back to the pool and users.
  2. You’ve reconfigured a user’s extension (line URI) to something different.

I was at a client’s office integrating their Nortel CS1000, NET VX1200 gateway and OCS 2007 R2 yesterday when I decided to remove all the settings that were used for testing to get a fresh start. I completed the actions above and noticed that when we began testing, the user we were using to test were no longer able to make any calls.

Not knowing what I did was a problem, I went ahead and ran Snopper on the mediation server to do some traces and noticed the following:

-------------------------------------------------------------------------------------------------------------------------------------------------------------------

TL_INFO(TF_PROTOCOL) [1]0C04.0F40::10/18/2010-16:38:21.099.0074e98e (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(122))$$begin_record

Instance-Id: 00645A17

Direction: incoming

Peer: 10.1.128.87:51629

Message-Type: request

Start-Line: INVITE sip:+19059753636@gennum.com;user=phone SIP/2.0

From: <sip:simon_n@someDomain.com>;tag=7e7bd83948;epid=a61f8218fd

To: <sip:+1905975xxxx@someDomain.com;user=phone>

CSeq: 1 INVITE

Call-ID: 7b91955da3e04fa7b6c3e9c560d0d4ad

Via: SIP/2.0/TLS 10.1.128.87:51629

Max-Forwards: 70

Contact: <sip:simon_n@someDomain.com;opaque=user:epid:glVkpdHi8V6VOvizBdUXIgAA;gruu>

User-Agent: UCCAPI/3.5.6907.206 OC/3.5.6907.206 (Microsoft Office Communicator 2007 R2)

Ms-Conversation-ID: Actu4t/pk+fi9sf0TFKNXk9k1BED3A==

Supported: timer

Supported: histinfo

Supported: ms-safe-transfer

Supported: ms-sender

Supported: ms-early-media

Supported: Replaces

Supported: 100rel

ms-keep-alive: UAC;hop-hop=yes

Allow: INVITE, BYE, ACK, CANCEL, INFO, UPDATE, REFER, NOTIFY, BENOTIFY, OPTIONS

P-Preferred-Identity: <sip:simon_n@gennum.com>, <tel:+5556>

Supported: ms-conf-invite

Proxy-Authorization: Kerberos qop="auth", realm="SIP Communications Service", opaque="A04EF8A5", targetname="sip/ocsharfe01.ad.someDomain.com", crand="64b67ebb", cnum="585", response="602306092a864886f71201020201011100ffffffffb5e151d7d6ff7ef539ca2c757a65cd93"

Content-Type: multipart/alternative;boundary="----=_NextPart_000_01B8_01CB6EC1.5908E610"

Content-Length: 4725

Message-Body: ------=_NextPart_000_01B8_01CB6EC1.5908E610

Content-Type: application/sdp

Content-Transfer-Encoding: 7bit

Content-Disposition: session; handling=optional; ms-proxy-2007fallback

v=0

o=- 0 0 IN IP4 10.1.128.87

s=session

c=IN IP4 10.1.128.87

b=CT:23980

t=0 0

m=audio 5431 RTP/AVP 114 111 112 115 116 4 8 0 97 13 118 101

k=base64:DW7LbXqiX4L3wFp0Yx7UDbFo6ga/iScrOFDwYuvrAgyPB8N5mu8N7tdJgrN1

a=candidate:iJ5HDuKC50JErCVxp+He6UZNNLYBQFvmxvo10hT+VWs 1 LjCbg9tsC8JIhDEVBUoirQ UDP 0.830 10.1.128.87 5431

a=candidate:iJ5HDuKC50JErCVxp+He6UZNNLYBQFvmxvo10hT+VWs 2 LjCbg9tsC8JIhDEVBUoirQ UDP 0.830 10.1.128.87 14468

a=candidate:lXwkhyK+CVZpdmQmRlFC+XYeMavS4ilKTfVSInExgLg 1 okSN3l9oQSyBlyycYODxwQ UDP 0.840 192.168.88.1 30163

a=candidate:lXwkhyK+CVZpdmQmRlFC+XYeMavS4ilKTfVSInExgLg 2 okSN3l9oQSyBlyycYODxwQ UDP 0.840 192.168.88.1 12236

a=candidate:F3iAzqhDj/k1gDWBaZHpw/pxH1fHLUL3cI7GnVS4ogk 1 yYzmfloIZpdmgd0hAtAqRA UDP 0.850 192.168.60.1 4670

a=candidate:F3iAzqhDj/k1gDWBaZHpw/pxH1fHLUL3cI7GnVS4ogk 2 yYzmfloIZpdmgd0hAtAqRA UDP 0.850 192.168.60.1 29278

a=candidate:2dL3FfLvG3YZ8W9etpCe6MtWoqDIjHMt3dGNOU203M4 1 nPzgXE6A83gld0eEHn//YA TCP 0.190 66.207.109.248 54113

a=candidate:2dL3FfLvG3YZ8W9etpCe6MtWoqDIjHMt3dGNOU203M4 2 nPzgXE6A83gld0eEHn//YA TCP 0.190 66.207.109.248 54113

a=candidate:3L6ERF2eJLQSA/SFI0ST2UaiyFlPzvuOmxng+vFi5jg 1 EP4FuvxSw6u8meQ9woXgjQ UDP 0.490 66.207.109.248 55952

a=candidate:3L6ERF2eJLQSA/SFI0ST2UaiyFlPzvuOmxng+vFi5jg 2 EP4FuvxSw6u8meQ9woXgjQ UDP 0.490 66.207.109.248 58955

a=candidate:c1q6qHeS6lR+1us1oIT2yp4Fi0Uo21Iq+89mOU4b+08 1 zEXq3NpANYQiHJXkGbUy3Q TCP 0.250 10.1.128.87 29912

a=candidate:c1q6qHeS6lR+1us1oIT2yp4Fi0Uo21Iq+89mOU4b+08 2 zEXq3NpANYQiHJXkGbUy3Q TCP 0.250 10.1.128.87 29912

a=cryptoscale:1 client AES_CM_128_HMAC_SHA1_80 inline:VMOZ+yOSBcWu3ls9isd5+huVlnPM0xmoE/t0PPn32^311:1

a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:35PBYr4+1BWkPDu7HmhFNtCEzIC4aBo0M7caFev72^311:1

a=maxptime:200

a=rtcp:14468

a=rtpmap:114 x-msrta/16000

a=fmtp:114 bitrate=29000

a=rtpmap:111 SIREN/16000

a=fmtp:111 bitrate=16000

a=rtpmap:112 G7221/16000

a=fmtp:112 bitrate=24000

a=rtpmap:115 x-msrta/8000

a=fmtp:115 bitrate=11800

a=rtpmap:116 AAL2-G726-32/8000

a=rtpmap:4 G723/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:97 RED/8000

a=rtpmap:13 CN/8000

a=rtpmap:118 CN/16000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=encryption:required

------=_NextPart_000_01B8_01CB6EC1.5908E610

Content-Type: application/sdp

Content-Transfer-Encoding: 7bit

Content-Disposition: session; handling=optional

v=0

o=- 0 0 IN IP4 10.1.128.87

s=session

c=IN IP4 10.1.128.87

b=CT:23980

t=0 0

m=audio 30611 RTP/AVP 114 111 112 115 116 4 8 0 97 13 118 101

k=base64:DW7LbXqiX4L3wFp0Yx7UDbFo6ga/iScrOFDwYuvrAgyPB8N5mu8N7tdJgrN1

a=ice-ufrag:KFCt

a=ice-pwd:YXkiSCOmAvr5ymaGshZheba7

a=candidate:1 1 UDP 2130706431 192.168.60.1 17431 typ host

a=candidate:1 2 UDP 2130705918 192.168.60.1 10079 typ host

a=candidate:2 1 UDP 2130705919 192.168.88.1 24869 typ host

a=candidate:2 2 UDP 2130705406 192.168.88.1 26551 typ host

a=candidate:3 1 UDP 2130705407 10.1.128.87 30611 typ host

a=candidate:3 2 UDP 2130704894 10.1.128.87 17915 typ host

a=candidate:4 1 TCP-PASS 6556159 66.207.109.248 51122 typ relay raddr 66.207.109.248 rport 51122

a=candidate:4 2 TCP-PASS 6556158 66.207.109.248 51122 typ relay raddr 66.207.109.248 rport 51122

a=candidate:5 1 UDP 16648703 66.207.109.248 56166 typ relay raddr 66.207.109.248 rport 56166

a=candidate:5 2 UDP 16648702 66.207.109.248 51169 typ relay raddr 66.207.109.248 rport 51169

a=candidate:6 1 TCP-ACT 7075839 66.207.109.248 51122 typ relay raddr 66.207.109.248 rport 51122

a=candidate:6 2 TCP-ACT 7075326 66.207.109.248 51122 typ relay raddr 66.207.109.248 rport 51122

a=candidate:7 1 TCP-ACT 1684796927 10.1.128.87 25983 typ srflx raddr 10.1.128.87 rport 25983

a=candidate:7 2 TCP-ACT 1684796414 10.1.128.87 25983 typ srflx raddr 10.1.128.87 rport 25983

a=cryptoscale:1 client AES_CM_128_HMAC_SHA1_80 inline:VMOZ+yOSBcWu3ls9isd5+huVlnPM0xmoE/t0PPn32^311:1

a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:35PBYr4+1BWkPDu7HmhFNtCEzIC4aBo0M7caFev72^311:1

a=maxptime:200

a=rtcp:17915

a=rtpmap:114 x-msrta/16000

a=fmtp:114 bitrate=29000

a=rtpmap:111 SIREN/16000

a=fmtp:111 bitrate=16000

a=rtpmap:112 G7221/16000

a=fmtp:112 bitrate=24000

a=rtpmap:115 x-msrta/8000

a=fmtp:115 bitrate=11800

a=rtpmap:116 AAL2-G726-32/8000

a=rtpmap:4 G723/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:97 RED/8000

a=rtpmap:13 CN/8000

a=rtpmap:118 CN/16000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=encryption:required

------=_NextPart_000_01B8_01CB6EC1.5908E610--

$$end_record

image

-------------------------------------------------------------------------------------------------------------------------------------------------------------------

TL_INFO(TF_DIAG) [1]0C04.0F7C::10/18/2010-16:38:21.099.0074eed3 (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(144))$$begin_record

LogType: diagnostic

Severity: information

Text: Response successfully routed

SIP-Start-Line: SIP/2.0 403 Forbidden

SIP-Call-ID: 7b91955da3e04fa7b6c3e9c560d0d4ad

SIP-CSeq: 1 INVITE

Peer: 10.1.128.87:51629

Data: destination="simon_n@someDomain.com"

$$end_record

image

-------------------------------------------------------------------------------------------------------------------------------------------------------------------

TL_INFO(TF_PROTOCOL) [1]0C04.0F7C::10/18/2010-16:38:21.099.0074ef0a (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(122))$$begin_record

Instance-Id: 00645A18

Direction: outgoing;source="local"

Peer: 10.1.128.87:51629

Message-Type: response

Start-Line: SIP/2.0 403 Forbidden

From: <sip:simon_n@someDomain.com>;tag=7e7bd83948;epid=a61f8218fd

To: <sip:+1905975xxxx@someDomain.com;user=phone>;tag=1D7964AA08EF80E592492B443E6238E7

CSeq: 1 INVITE

Call-ID: 7b91955da3e04fa7b6c3e9c560d0d4ad

Proxy-Authentication-Info: Kerberos rspauth="602306092A864886F71201020201011100FFFFFFFF87381448EA9A9037FDDDDBA3B5C297AC", srand="60721B98", snum="788", opaque="A04EF8A5", qop="auth", targetname="sip/ocsharfe01.ad.someDomain.com", realm="SIP Communications Service"

Via: SIP/2.0/TLS 10.1.128.87:51629;ms-received-port=51629;ms-received-cid=13AAE00

ms-diagnostics: 4035;reason="Phone identity is not authorized - associated user entity not found in DB";source="ocsharfe01.ad.someDomain.com"

Content-Length: 0

Message-Body: –

$$end_record

image

-------------------------------------------------------------------------------------------------------------------------------------------------------------------

TL_INFO(TF_PROTOCOL) [1]0C04.0F40::10/18/2010-16:38:21.115.0074efd1 (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(122))$$begin_record

Instance-Id: 00645A19

Direction: incoming

Peer: 10.1.128.87:51629

Message-Type: request

Start-Line: ACK sip:+19059753636@gennum.com;user=phone SIP/2.0

From: <sip:simon_n@someDomain.com>;tag=7e7bd83948;epid=a61f8218fd

To: <sip:+1905975xxxx@someDomain.com;user=phone>;tag=1D7964AA08EF80E592492B443E6238E7

CSeq: 1 ACK

Call-ID: 7b91955da3e04fa7b6c3e9c560d0d4ad

Via: SIP/2.0/TLS 10.1.128.87:51629

Max-Forwards: 70

User-Agent: UCCAPI/3.5.6907.206 OC/3.5.6907.206 (Microsoft Office Communicator 2007 R2)

Proxy-Authorization: Kerberos qop="auth", realm="SIP Communications Service", opaque="A04EF8A5", targetname="sip/ocsharfe01.ad.someDomain.com", crand="47cfdb8e", cnum="586", response="602306092a864886f71201020201011100ffffffffb01a4fe34cfa1d8795f15a5485e9f3bc"

Content-Length: 0

Message-Body: –

$$end_record

image

-------------------------------------------------------------------------------------------------------------------------------------------------------------------

So after fiddling around with the user’s location profiles a few times (unassign, reassign) the user was then able to make calls.

Hope this helps anyone out there who may experience this problem and needs a quick answer.

No comments: