I am having a similar issue, I tried removing the trusted root certificates as this actually caused issues with the LPE handsets we have, although there was another workaround that I used to fix that previously.
I can see in the log on the client that the registration appears to complete but that the client interface never updates to reflect the fact. I can then even see call signalling in the logs when I receive an inbound call via enterprise
voice.
After several unauthorised request and then sending back the proper header I get this:
03/28/2013|13:24:37.705 2370:2744 INFO :: Sending Packet - X.X.X.X:5061 (From Local Address: 192.168.10.9:53909) 930 bytes:
03/28/2013|13:24:37.705 2370:2744 INFO :: REGISTER sip:domainx.co.uk SIP/2.0
Via: SIP/2.0/TLS 192.168.10.9:53909
Max-Forwards: 70
From: <sip:james.cook@domainx.co.uk>;tag=e2a470264a;epid=713dd99476
To: <sip:james.cook@domainx.co.uk>
Call-ID: 7dc612e9f2f6440da732aff6ea54959c
CSeq: 4 REGISTER
Contact: <sip:192.168.10.9:53909;transport=tls;ms-opaque=03359cb7f3>;proxy=replace;+sip.instance="<urn:uuid:C4D6979B-1082-5774-8279-AAC37472D25A>"
User-Agent: UCCAPIIMM/15.0.4481.1503 LyncImm/15.0.4481.1503 (Microsoft Lync)
Supported: gruu-10, adhoclist, msrtc-event-categories
Supported: ms-forking
Supported: ms-cluster-failover
ms-keep-alive: UAC;hop-hop=yes;timeout=1140
Expires: 7200
Event: registration
Proxy-Authorization: TLS-DSK qop="auth", realm="SIP Communications Service", opaque="32DB1D52", targetname="LYNCENTFE2.vo.domainx.co.uk", crand="8fdff044", cnum="1", response="5523c190a4a0b963b828edfd3ebd12dbe7a6cf9b"
Content-Length: 0
03/28/2013|13:24:37.705 2370:2744 INFO :: End of Sending Packet - X.X.X.X:5061 (From Local Address: 192.168.10.9:53909) 930 bytes
03/28/2013|13:24:37.705 2370:2744 TRACE :: CSIPAsyncSocket::Send this 0592D1B0, sending pbSendBuf 0584AF78, dwSendBufSize = 930
03/28/2013|13:24:37.705 2370:2744 TRACE :: CSIPAsyncSocket::SendHelper - [0x0592D1B0]
03/28/2013|13:24:37.705 2370:2744 INFO :: WriteCompletionHandler::WriteCompletionHandler opening txn for write 0A071D40
03/28/2013|13:24:37.706 2370:2744 INFO :: CAsyncSocketWinRT::Send WriteOperation started 03093F50
03/28/2013|13:24:37.706 2370:2574 INFO :: WriteCompletionHandler::Invoke WriteOperation completion 03093F50
03/28/2013|13:24:37.706 2370:2574 INFO :: WriteCompletionHandler::~WriteCompletionHandler closing txn for write 00000000
03/28/2013|13:24:37.706 2370:2744 INFO :: ~Out trxn corr-id (0586D988)
03/28/2013|13:24:37.709 2370:2744 INFO :: Bytes Written 930
03/28/2013|13:24:37.761 2370:2040 INFO :: PushNotificationBackgroundTask::Run - Push notification task ended. ID: {F37B798D-6ABD-4320-8352-51DC57AF47E1}, name: [SignalingNotificationChannel05316FC8], suspended count: 0
03/28/2013|13:24:37.769 2370:2574 INFO :: ReadCompletionHandler::Invoke ReadOperation completion 03093CB0
03/28/2013|13:24:37.769 2370:2574 INFO :: CAsyncSocketWinRT::OnReadCompletion entry
03/28/2013|13:24:37.769 2370:2574 INFO :: CAsyncSocketWinRT::OnReadCompletion opening txn for read to be processed (02A91D00)
03/28/2013|13:24:37.769 2370:2744 INFO :: CAsyncSocketWinRT::ProcessRead closing read txn (02A91D00), result 0x0, bytesRecv: 2210
03/28/2013|13:24:37.770 2370:2744 TRACE :: CSIPTransportLayerNotify::OnRecv - [0x0592D1B8]
03/28/2013|13:24:37.770 2370:2744 TRACE :: CSIPTransportLayerNotify::OnRecv - [0x0572A090]
03/28/2013|13:24:37.770 2370:2744 TRACE :: CSIPTransportLayerNotify::OnRecv - [0x02A51328]
03/28/2013|13:24:37.770 2370:2744 INFO :: Data Received -X.X.X.X:5061 (To Local Address: 192.168.10.9:53909) 2210 bytes:
03/28/2013|13:24:37.770 2370:2744 INFO :: SIP/2.0 200 OK
ms-user-logon-data: RemoteUser
ms-keep-alive: UAS; tcp=no; hop-hop=yes; end-end=no; timeout=900
Authentication-Info: TLS-DSK qop="auth", opaque="32DB1D52", srand="29E650DF", snum="1", rspauth="839a6c6c6877af9ad0ab92773e244a4abeb7d8e9", targetname="LYNCENTFE2.vo.domainx.co.uk", realm="SIP Communications Service", version=4
From: "James Cook"<sip:james.cook@domainx.co.uk>;tag=e2a470264a;epid=713dd99476
To: <sip:james.cook@domainx.co.uk>;tag=D061BA09B9EAE648B063548837C5907E
Call-ID: 7dc612e9f2f6440da732aff6ea54959c
CSeq: 4 REGISTER
Via: SIP/2.0/TLS 192.168.10.9:53909;received=92.233.38.40;ms-received-port=53909;ms-received-cid=C9400
Record-Route: <sip:sip.maindomain.com:5061;transport=tls;opaque=state:Ci.Dc9400;lr;ms-route-sig=gcBftGN9J-m4yBpvQnIfw6l1fScLju5wM_jrFWpoMbDlkSpuGvL9a2zwAA>
Path: <sip:edgepool1.lync.vo.domainx.co.uk:50792;transport=tls;maddr=10.95.141.10;opaque=state:Ee.gcqRWWfxX29I1tIitV1vy2dQAA;lr;ms-received-cid=7C9300>;tag=871644DDB52A403EAFD10A8EAEFCABB7
Contact: <sip:5.133.20.155:56882;transport=tls;ms-opaque=2c803d3fe4;ms-received-cid=A6100>;expires=170;+sip.instance="<urn:uuid:22f9df52-cd66-5589-9fee-dd53aa475f2d>";gruu="sip:james.cook@domainx.co.uk;opaque=user:epid:Ut_5ImbNiVWf7t1TqkdfLQAA;gruu"
Contact: <sip:92.233.38.40:53909;transport=tls;ms-opaque=03359cb7f3;ms-received-cid=C9400>;expires=900;+sip.instance="<urn:uuid:c4d6979b-1082-5774-8279-aac37472d25a>";gruu="sip:james.cook@domainx.co.uk;opaque=user:epid:m5fWxIIQdFeCearDdHLSWgAA;gruu"
Contact: <sip:92.233.38.40:53450;transport=tls;ms-opaque=ff8c7fedb9;ms-received-cid=A2B00>;expires=512;+sip.instance="<urn:uuid:00120ecb-edd2-5b88-ba83-94b291a3e4cd>";gruu="sip:james.cook@domainx.co.uk;opaque=user:epid:yw4SANLtiFu6g5SykaPkzQAA;gruu"
presence-state: register-action="added"
Expires: 900
Allow-Events: vnd-microsoft-provisioning,vnd-microsoft-roaming-contacts,vnd-microsoft-roaming-ACL,presence,presence.wpending,vnd-microsoft-roaming-self,vnd-microsoft-provisioning-v2
Supported: adhoclist
Server: RTC/4.0
Supported: msrtc-event-categories
Supported: ms-keepalive-deregister
Supported: ms-userservices-state-notification
Content-Length: 0
03/28/2013|13:24:37.770 2370:2744 INFO :: End of Data Received -X.X.X.X:5061 (To Local Address: 192.168.10.9:53909) 2210 bytes
03/28/2013|13:24:37.770 2370:2744 TRACE :: CSIPMessageCollator::AsyncProcessSipMsg - [0x05728210]
03/28/2013|13:24:37.770 2370:2744 TRACE :: CSIPTransportLayerNotify::OnRecv - [0x05728210]
03/28/2013|13:24:37.771 2370:2744 TRACE :: verified buffer: <TLS-DSK><29E650DF><1><SIP Communications Service><LYNCENTFE2.vo.domainx.co.uk><7dc612e9f2f6440da732aff6ea54959c><4><REGISTER><sip:james.cook@domainx.co.uk><e2a470264a><sip:james.cook@domainx.co.uk><D061BA09B9EAE648B063548837C5907E><><><900><200>-length-258.
signature:839a6c6c6877af9ad0ab92773e244a4abeb7d8e9
03/28/2013|13:24:37.771 2370:2744 TRACE :: SA(5491b28) Established
03/28/2013|13:24:37.771 2370:2744 TRACE :: SA(5491b28) state change(3)=(4)
03/28/2013|13:24:37.771 2370:2744 INFO :: SIP_AUTH(0536ECAC) AsyncNotify SA Established
03/28/2013|13:24:37.771 2370:2744 INFO :: Trxn corr-id (0586D778), SIP msg corr-id (976abd6f)
03/28/2013|13:24:37.771 2370:2744 INFO :: CRegistrationRefreshScheduler::OnRegistrationSucceeded - Marked a successful regn refresh.
03/28/2013|13:24:37.771 2370:2744 TRACE :: CUccPrincipalServerEndpoint::ProcessSetProviderPropertyUINT - SIP_PROVIDER_PROPERTY_CLUSTER, 0
03/28/2013|13:24:37.771 2370:2744 TRACE :: CUccPrincipalServerEndpoint::ProcessSetProviderPropertyUINT - SIP_PROVIDER_PROPERTY_CONN_TO_PRIMARY, 0
03/28/2013|13:24:37.771 2370:2744 TRACE :: CUccPrincipalServerEndpoint::ProcessSetProviderPropertyUINT - SIP_PROVIDER_PROPERTY_USC, 0
03/28/2013|13:24:37.772 2370:2744 ERROR :: REGISTER_CONTEXT::HandleRegistrationSuccess - ParseMsUserLogonDataHeader - hr=0x00000000, bRemoteUser=1
03/28/2013|13:24:37.772 2370:2744 TRACE :: CSIPTransportLayerNotify::CSIPTransportLayerNotify - [0x0584A908]
03/28/2013|13:24:37.772 2370:2744 TRACE :: CSIPWhiteSpaceKeepAlive::CSIPWhiteSpaceKeepAlive - [0x0584A908]
03/28/2013|13:24:37.772 2370:2744 TRACE :: CSIPWhiteSpaceKeepAlive::Initialize - [0x0584A908]
03/28/2013|13:24:37.774 2370:2744 TRACE :: CSIPWhiteSpaceKeepAlive::StartTimerHelper Not using regular timer, this 0584A908
03/28/2013|13:24:37.774 2370:2744 INFO :: REGISTER_CONTEXT(586ae48) SetAndNotify Recv(1) at State (1)
03/28/2013|13:24:37.774 2370:2744 INFO :: Function: SIP_CALLMGR::RefreshRouteForAllDialogs
03/28/2013|13:24:37.774 2370:2744 ERROR :: HRESULT API failed: 80004005 = pSipMsgProc->InternalRefreshRoute()
03/28/2013|13:24:37.774 2370:2744 WARN :: CUccPrincipalServerEndpoint::NotifySuspended suspended [no], no change, this 0574C370
03/28/2013|13:24:37.774 2370:2744 TRACE :: OUTGOING_REGISTER_TRANSACTION::ProcessSuccessfulResponse received 200 Registration SUCCEEDED
03/28/2013|13:24:37.774 2370:2744 INFO :: ~Out trxn corr-id (0586D778)
03/28/2013|13:24:37.774 2370:2744 INFO :: SIP_AUTH(536ecac) SetState (1) => (2)
03/28/2013|13:24:37.786 2370:2040 INFO :: PushNotificationBackgroundTask::Run - Push notification task invoked. ID: {F37B798D-6ABD-4320-8352-51DC57AF47E1}, name: [SignalingNotificationChannel05316FC8], suspended count: 0
03/28/2013|13:24:37.787 2370:2040 INFO :: PushNotificationBackgroundTask::Run - Push notification task ended. ID: {F37B798D-6ABD-4320-8352-51DC57AF47E1}, name: [SignalingNotificationChannel05316FC8], suspended count: 0
03/28/2013|13:28:36.555 2370:19D4 INFO :: KeepAliveBackgroundTask::Run - Keep alive task invoked. ID: {9F76E760-AD0E-4E4F-83F6-5DD10488EBC4}, name: [42], suspended count: 0
03/28/2013|13:28:36.559 2370:2744 TRACE :: CSipTlsDskSecAssociationImm::OnWhiteSpaceTimerExpire - Entered
03/28/2013|13:28:36.560 2370:2744 INFO :: CSipTlsDskSecAssociationImm::IsSARefreshNeeded - IsSARefreshNeeded: 0
03/28/2013|13:28:36.562 2370:2744 INFO :: this(0536ECAC) - SA(05491B28) reported OnWhiteSpaceTimerExpire(240000l)
03/28/2013|13:28:36.563 2370:2744 INFO :: CRegistrationRefreshScheduler::IsRegistrationNeeded - IsRegistrationNeeded: 0
03/28/2013|13:28:36.564 2370:2744 INFO :: CSIPWhiteSpaceKeepAlive::OnTimerExpire 0584A908
03/28/2013|13:28:36.565 2370:2744 TRACE :: CRegistrationRefreshScheduler::OnMessage - Received event WM_REGISTRATION_REFRESH_EVENT
03/28/2013|13:28:36.566 2370:2744 INFO :: Out trxn corr-id (0586C1D0)
03/28/2013|13:28:36.567 2370:2744 ERROR :: SIP_MSG_PROCESSOR::GetLocalConnectionAddrSubnet get subnetmask failed
03/28/2013|13:28:36.568 2370:2744 INFO :: SIP_MSG_PROCESSOR::GetSubnetHeader Invalid subnet -1
03/28/2013|13:28:36.570 2370:2744 INFO :: Trxn corr-id (0586C1D0), SIP msg corr-id (976abd6f)
03/28/2013|13:28:36.571 2370:2744 INFO :: Sending Packet - X.X.X.X:5061 (From Local Address: 192.168.10.9:53909) 930 bytes:
03/28/2013|13:28:36.572 2370:2744 INFO :: REGISTER sip:domainx.co.uk SIP/2.0
Via: SIP/2.0/TLS 192.168.10.9:53909
Max-Forwards: 70
From: <sip:james.cook@domainx.co.uk>;tag=e2a470264a;epid=713dd99476
To: <sip:james.cook@domainx.co.uk>
Call-ID: 7dc612e9f2f6440da732aff6ea54959c
CSeq: 5 REGISTER
Contact: <sip:192.168.10.9:53909;transport=tls;ms-opaque=03359cb7f3>;proxy=replace;+sip.instance="<urn:uuid:C4D6979B-1082-5774-8279-AAC37472D25A>"
User-Agent: UCCAPIIMM/15.0.4481.1503 LyncImm/15.0.4481.1503 (Microsoft Lync)
Supported: gruu-10, adhoclist, msrtc-event-categories
Supported: ms-forking
Supported: ms-cluster-failover
ms-keep-alive: UAC;hop-hop=yes;timeout=1140
Expires: 7200
Event: registration
Proxy-Authorization: TLS-DSK qop="auth", realm="SIP Communications Service", opaque="32DB1D52", targetname="LYNCENTFE2.vo.domainx.co.uk", crand="ffb06f29", cnum="2", response="7c410fcc2489c6c252faac0fdc435e6282ad2f6d"
Content-Length: 0
03/28/2013|13:28:36.576 2370:2744 INFO :: End of Sending Packet - X.X.X.X:5061 (From Local Address: 192.168.10.9:53909) 930 bytes
03/28/2013|13:28:36.577 2370:2744 TRACE :: CSIPAsyncSocket::Send this 0592D1B0, sending pbSendBuf 0572E2D0, dwSendBufSize = 930
03/28/2013|13:28:36.578 2370:2744 TRACE :: CSIPAsyncSocket::SendHelper - [0x0592D1B0]
03/28/2013|13:28:36.580 2370:2744 INFO :: WriteCompletionHandler::WriteCompletionHandler opening txn for write 0572E098
03/28/2013|13:28:36.582 2370:2744 INFO :: CAsyncSocketWinRT::Send WriteOperation started 0527A730
03/28/2013|13:28:36.583 2370:2744 INFO :: WriteCompletionHandler::Invoke WriteOperation completion 0527A730
03/28/2013|13:28:36.585 2370:2744 INFO :: WriteCompletionHandler::~WriteCompletionHandler closing txn for write 00000000
03/28/2013|13:28:36.586 2370:2744 INFO :: REGISTER_CONTEXT(586ae48) SetAndNotify Recv(4) at State (1)
03/28/2013|13:28:36.587 2370:2744 TRACE :: CSIPWhiteSpaceKeepAlive::StartTimerHelper Not using regular timer, this 0584A908
03/28/2013|13:28:36.588 2370:2744 INFO :: Bytes Written 930
03/28/2013|13:28:36.590 2370:19D4 INFO :: KeepAliveBackgroundTask::Run - Keep alive task ended. ID: {9F76E760-AD0E-4E4F-83F6-5DD10488EBC4}, name: [42], suspended count: 0
03/28/2013|13:28:36.842 2370:1AC4 INFO :: ReadCompletionHandler::Invoke ReadOperation completion 0565AB98
03/28/2013|13:28:36.844 2370:1AC4 INFO :: CAsyncSocketWinRT::OnReadCompletion entry
03/28/2013|13:28:36.846 2370:1AC4 INFO :: CAsyncSocketWinRT::OnReadCompletion opening txn for read to be processed (02A91AC0)
03/28/2013|13:28:36.848 2370:2744 INFO :: CAsyncSocketWinRT::ProcessRead closing read txn (02A91AC0), result 0x0, bytesRecv: 2518
03/28/2013|13:28:36.849 2370:2744 TRACE :: CSIPTransportLayerNotify::OnRecv - [0x0592D1B8]
03/28/2013|13:28:36.851 2370:2744 TRACE :: CSIPTransportLayerNotify::OnRecv - [0x0572A090]
03/28/2013|13:28:36.853 2370:2744 TRACE :: CSIPTransportLayerNotify::OnRecv - [0x02A51328]
03/28/2013|13:28:36.854 2370:2744 INFO :: Data Received -X.X.X.X:5061 (To Local Address: 192.168.10.9:53909) 2518 bytes:
03/28/2013|13:28:36.856 2370:2744 INFO :: SIP/2.0 200 OK
ms-user-logon-data: RemoteUser
ms-keep-alive: UAS; tcp=no; hop-hop=yes; end-end=no; timeout=900
Authentication-Info: TLS-DSK qop="auth", opaque="32DB1D52", srand="C93EE7C0", snum="2", rspauth="5da86ebf8571d115be21dc16405b22b0a3fceda2", targetname="LYNCENTFE2.vo.domainx.co.uk", realm="SIP Communications Service", version=4
From: "James Cook"<sip:james.cook@domainx.co.uk>;tag=e2a470264a;epid=713dd99476
To: <sip:james.cook@domainx.co.uk>;tag=D061BA09B9EAE648B063548837C5907E
Call-ID: 7dc612e9f2f6440da732aff6ea54959c
CSeq: 5 REGISTER
Via: SIP/2.0/TLS 192.168.10.9:53909;received=92.233.38.40;ms-received-port=53909;ms-received-cid=C9400
Record-Route: <sip:sip.maindomain.com:5061;transport=tls;opaque=state:Ci.Rc9400;lr;ms-route-sig=gc8qvm8Y8hLpEgOSXM1JjWbhz7k9lVTovUN4IlGtzxx92BEtB3L9a2zwAA>
Path: <sip:edgepool1.lync.vo.domainx.co.uk:50792;transport=tls;maddr=10.95.141.10;opaque=state:Ee.gc1uBXWRDBEnFKMTnYcKozTgAA;lr;ms-received-cid=7C9300>;tag=871644DDB52A403EAFD10A8EAEFCABB7
Contact: <sip:frontendpool1.lync.vo.domainx.co.uk:5087;ms-fe=LYNCENTFE2.vo.domainx.co.uk;transport=Tls;ms-opaque=0e08ffbcc8875452>;expires=1578;+sip.instance="<urn:uuid:2fa20129-7ce0-5769-ba7a-f3c8af7ece4f>";gruu="sip:james.cook@domainx.co.uk;opaque=user:epid:KQGiL-B8aVe6evPIr37OTwAA;gruu"
Contact: <sip:5.133.20.155:56882;transport=tls;ms-opaque=2c803d3fe4;ms-received-cid=A6100>;expires=404;+sip.instance="<urn:uuid:22f9df52-cd66-5589-9fee-dd53aa475f2d>";gruu="sip:james.cook@domainx.co.uk;opaque=user:epid:Ut_5ImbNiVWf7t1TqkdfLQAA;gruu"
Contact: <sip:92.233.38.40:53909;transport=tls;ms-opaque=03359cb7f3;ms-received-cid=C9400>;expires=900;+sip.instance="<urn:uuid:c4d6979b-1082-5774-8279-aac37472d25a>";gruu="sip:james.cook@domainx.co.uk;opaque=user:epid:m5fWxIIQdFeCearDdHLSWgAA;gruu"
Contact: <sip:92.233.38.40:53450;transport=tls;ms-opaque=ff8c7fedb9;ms-received-cid=A2B00>;expires=273;+sip.instance="<urn:uuid:00120ecb-edd2-5b88-ba83-94b291a3e4cd>";gruu="sip:james.cook@domainx.co.uk;opaque=user:epid:yw4SANLtiFu6g5SykaPkzQAA;gruu"
presence-state: register-action="refreshed"
Expires: 900
Allow-Events: vnd-microsoft-provisioning,vnd-microsoft-roaming-contacts,vnd-microsoft-roaming-ACL,presence,presence.wpending,vnd-microsoft-roaming-self,vnd-microsoft-provisioning-v2
Supported: adhoclist
Server: RTC/4.0
Supported: msrtc-event-categories
Supported: ms-keepalive-deregister
Supported: ms-userservices-state-notification
Content-Length: 0
03/28/2013|13:28:36.861 2370:2744 INFO :: End of Data Received -X.X.X.X:5061 (To Local Address: 192.168.10.9:53909) 2518 bytes
Does the above logging mean that it was successfully registered against the server?
Also just after this I can see INVITE sip requests for inbound calls.
Has anyone else come across this?