Hello all,
this FAQ should help to easily troubleshoot Skype for Business / Office 365 sign-in issues.
July 31. 2019 Question: How can I report Issues with Teams running on a Poly Trio in Native mode?
Resolution: Please collect the Logs as shown here => here <= and submit them to our Partner Microsoft. You will need to work with Microsoft for this.
The original FAQ => here <= should be consulted as well.
The Phone logs can help to troubleshoot issues found via Diagnostics > View & Download Logs
Changing of Logging Levels:
Warning: Logging parameter changes can impair system operation. Do not change any logging parameters without prior consultation with your Polycom Reseller or Polycom Technical Support.
The <level/> Parameters control the logging detail level for individual components. These are the input filters into the internal memory-based log system.
The factory default level for all logging parameters is "4" or Minor Error.
- Debug = 0
- Event 1 = 1
- Event 2 = 2
- Event 3 = 3
- Minor Error = 4
- Major Error = 5
- Fatal Error = 6
NOTE: In order to set the lowest Level of logging this Parameter may be used
Web Interface:
Settings > Logging > Global Settings > Global Log Level Limit > Log File Size (Kbytes) >
| Phone Model | Size |
| SoundStation IP | Leave as is |
| SoundPoint IP | Leave as is |
| VVX prior to 5.5.0 | 180 |
| VVX from 5.5.0 | 1000 |
| Polycom Trio | 10240 |
Lack of NTP Server causing unable to sign in:
002137.009|sip |4|00|Server certificate verification failed, Untrusted Certificate 002137.010|sip |4|00|MakeTlsConnection: SSL_connect error 1
The above is the phone missing an NTP Time server !
The red highlighted Area shows the phone not having a valid time as shown => here <=
Without the time the phone cannot verify the Certificate. The Time should display as MMDDHHMMSS
0123120329|log |5|00|Skipped uploading of failed log file because no of failures are > 4 or last upload failed time is < 60 seconds.
The above shows the January the 23 and the time as 12:03:29
DNS:
182141.243|sip |4|00|doDnsListLookup(tcp): doDnsSrvLookupForARecordList 'xxxxxxxxxx.onmicrosoft.com' found no records
182141.243|sip |4|00|doDnsListLookup(tcp): doDnsSrvLookupForARecordList 'xxxxxxxxxx.onmicrosoft.com' found no records
182141.243|sip |4|00|doDnsListLookup(tcp): doDnsSrvLookupForARecordList 'xxxxxxxxxx.onmicrosoft.com' found no records
182141.243|sip |4|00|doDnsListLookup(tls): doDnsSrvLookupForARecordList 'sipinternal.xxxxxxxxxx.onmicrosoft.com' found no records
182141.243|sip |4|00|doDnsListLookup(tcp): doDnsSrvLookupForARecordList 'sipinternal.xxxxxxxxxx.onmicrosoft.com' found no records
182141.243|sip |4|00|doDnsListLookup(tls): doDnsSrvLookupForARecordList 'sipexternal.xxxxxxxxxx.onmicrosoft.com' found no records
182141.243|sip |4|00|doDnsListLookup(tcp): doDnsSrvLookupForARecordList 'sipexternal.xxxxxxxxxx.onmicrosoft.com' found no records
182141.243|sip |4|00|MakeTlsConnection: SSL_connect error 1
182141.243|sip |4|00|MakeTlsConnection: connection failed error -1
182141.243|sip |4|00|Registration failed User: Username, Error Code:480 Temporarily not available
The above is the phone missing an NTP Time server and in addition cannot resolve the DNS.
Without the DNS the phone is unable to connect to the server. You need to fix your DNS
Certificate:
Change the logging
- Settings > Logging > Global Settings > Global Log Level Limit > Set to DEBUG
- Settings > Logging > Log File Size (Kbytes) > VVX 1000 or on a Trio 10240
- Settings > Logging > Module Log Level Limits > SIP > Set to DEBUG
0213083902|sip |3|63442|[TLS] Validating Subject Alternative Name(s) (SAN) and Common Name (CN) against the following: 0213083902|sip |3|63442|[TLS] Hostname: microsoft.com 0213083902|sip |3|63442|[TLS] Outbound Proxy: microsoft.com 0213083902|sip |3|63442|[TLS] Hostname connection: sipfed0M.online.lync.com 0213083902|sip |1|63442|[TLS] Comparing certificate SAN type DNS: 'sipfed.online.lync.com' 0213083902|sip |1|63442|[TLS] Comparing certificate SAN type DNS: '*.online.lync.com' 0213083902|sip |1|63442|[TLS] Comparing certificate SAN type DNS: '*.infra.lync.com' 0213083902|sip |1|63442|[TLS] Comparing certificate SAN type DNS: '*.lync.com' 0213083902|sip |3|63442|[TLS] None of the SAN(s) matched 0213083902|sip |3|63442|[TLS] Attempting to validate certificate Common Name (CN) 0213083902|sip |4|63442|[TLS] Server Certificate Common Name 'sipfed.online.lync.com' doesn't match any of the following: 0213083902|sip |4|63442|[TLS] Hostname: microsoft.com 0213083902|sip |4|63442|[TLS] Outbound Proxy: microsoft.com 0213083902|sip |4|63442|[TLS] Hostname connection: 0213083902|sipfed0M.online.lync.com 0213083902|sip |4|63442|[TLS] Server Certificate SAN or CN validation failed 0213083902|sip |2|63442|MakeTlsConnection: post connect check of hostname(s) failed, original SSL verification result was: (0: ok)
In the above example the Server Certificate SAN or CN validation failed. Please check your certificate.
Or
- Settings > Logging > Global Settings > Global Log Level Limit > Set to DEBUG
- Settings > Logging > Log File Size (Kbytes) > VVX 1000 or on a Trio 10240
- Settings > Logging > Module Log Level Limits > CURL > Set to Event 3
0123134226|curl |3|00|Connected to xxx.xxx.com (xx.xx.xx.xx) port 443 (#0) 0123134226|curl |3|00|successfully set certificate verify locations: 0123134226|curl |3|00| CAfile: /data/polycom/ffs0/ca3.crt CApath: none 0123134226|curl |3|00|SSLv3, TLS handshake, Client hello (1): 0123134226|curl |0|00|SSL DATA_OUT: Data of len 87 not displayed 0123134226|curl |3|00|SSLv3, TLS handshake, Server hello (2): 0123134226|curl |0|00|SSL DATA_IN: Data of len 85 not displayed 0123134226|curl |3|00|SSLv3, TLS handshake, CERT (11): 0123134226|curl |0|00|SSL DATA_IN: Data of len 2878 not displayed 0123134226|curl |3|00|SSLv3, TLS alert, Server hello (2): 0123134226|curl |0|00|SSL DATA_OUT: Data of len 2 not displayed 0123134226|curl |3|00|SSL certificate problem, verify that the CA cert is OK. Details: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed 0123134226|curl |3|00|Closing connection #0
Again check your certificate
Username or Password:
- Settings > Logging > Global Settings > Global Log Level Limit > Set to DEBUG
- Settings > Logging > Log File Size (Kbytes) > VVX 1000 or on a Trio 10240
- Settings > Logging > Module Log Level Limits > CURL > Set to Event 1
0125071627|curl |3|00| SSL certificate verify ok. 0125071627|curl |1|00|HEADER_OUT: POST /adfs/services/trust/2005/usernamemixed HTTP/1.1 ... 0125071627|curl |1|00|HEADER_IN : HTTP/1.1 100 Continue 0125071627|curl |1|00|HEADER_IN : HTTP/1.1 500 Internal Server Error 0125071627|curl |1|00|HEADER_IN : Content-Length: 1000 0125071627|curl |1|00|HEADER_IN : Content-Type: application/soap+xml; charset=utf-8 0125071627|curl |1|00|HEADER_IN : Server: Microsoft-HTTPAPI/2.0 Microsoft-HTTPAPI/2.0 0125071627|curl |1|00|HEADER_IN : Date: Wed, 25 Jan 2017 07:16:26 GMT 0125071627|curl |1|00|HEADER_IN : 0125071627|curl |3|00|Connection #0 to host sts.<obscured>.com left intact 0125071627|curl |3|00|Closing connection #0
Exchange:
VVX:
- Settings > Logging > Global Settings > Global Log Level Limit > Set to DEBUG
- Settings > Logging > Log File Size (Kbytes) > VVX 1000
- Settings > Logging > Module Log Level Limits > Exchange Client > Set to DEBUG
- Settings > Logging > Module Log Level Limits > Presentation > Set to DEBUG
1222180154|pgui |4|00|'vvm' Service CSoapTransaction network error = Operation canceled (5) 1222180154|pgui |4|00|Visual Voice Mail service network error 5. 1222180154|pgui |4|00|EWS SOAP service network error 5.
and later
1222180634|pgui |4|00|CSoapTransaction error = Socket operation timed out (4) 1222180634|pgui |4|00|'ews' Service CSoapTransaction network error = Socket operation timed out (4) 1222180634|pgui |4|00|Calendar: Network error occured 4
Trio:
- Settings > Logging > Global Settings > Global Log Level Limit > Set to DEBUG
- Settings > Logging > Log File Size (Kbytes) > 10240
- Settings > Logging > Module Log Level Limits > CURL > Set to DEBUG
- Settings > Logging > Module Log Level Limits > Presentation > Set to DEBUG
- Settings > Logging > Module Log Level Limits > SIP > Set to DEBUG
Option 43 & 120 for Extension & Pin troubleshooting:
Since UC Software 5.6.0:
or
log.render.level="0"
log.render.file.size="1000"
log.level.change.pps="1"
log.level.change.service.auth="0"
log.level.change.auth="0"
And the received STS URI will be displayed:
0202141143|pps |1|00|PpsHybridC::OnEvFetchSTSURI the sts-uri received is https://csslopoolweb.polycom.com:443/CertProv/CertProvisioningService.svc 0202141143|pps |1|00|PpsHybridC::OnEvFetchSTSURI the sts-uri received is https://csslopoolweb.polycom.com:443/CertProv/CertProvisioningService.svc 0202141143|pps |1|00|PpsHybridC::OnEvFetchSTSURI the sts-uri received is https://sfbpool01.plcmlabs.com:443/CertProv/CertProvisioningService.svc
In the above scenario the Phone was in a Network that had multiple DHCP Servers respond to the DHCP Inform.
0202141147|auth |0|00|Policy Dest:(201)AuthServicePolicyServiceKey:(103)AuthServiceRCMsgKey:(205)AuthSvcAOServiceRequestKey Caller Service(-1):IndicationCode(0) ,TransactionID(-1)Data:SD:Key Data(User Key/Operation Key/Url Key):Uri: User/Guest/Domain:,False, Url: Operation:(103)AuthServiceRCMsgKey,Caller Service:(-1)Url,TransactionId:,-1 UrlKey(Operation,CallerService,Url):(-1),(-1),https://sfbpool01.plcmlabs.com:443/CertProv/CertProvisioningService.svc
and
...2141157|curl |1|00|HEADER_OUT: POST /CertProv/CertProvisioningService.svc/anon HTTP/1.1
Prior to UC Software 5.6.0
Incorrect or incomplete:
0918144405|tickt|1|00|soWebTicketServersGet: request URI is /mex
Correct example:
0919080727|cfg |3|00|Prov|[CfgLyncSipSrvDiscover::cbFoundOption] Received STS-URI is 'https://lyncfe01.t3voipuk.lab:443/CertProv/CertProvisioningService.svc'
202646.012|tickt|1|00|soWebTicketServersGet: request URI is https://lyncfe01.t3voipuk.lab:443/CertProv/CertProvisioningService.svc/mex
Adding a Favorite:
Adding a LYNC / Skype for Business Favorite should appear instantaneous on the Phone once added by the Client.
- Settings > Logging > Log File Size (Kbytes) > 1000
- Settings > Logging > Module Log Level Limits > SIP > Set to Event 1
- Settings > Logging > Module Log Level Limits > Application > Set to Event 2
0206171740|sip |2|00|Received modifiedContact 0206171740|sip |2|00|(1)groupId for contact 'stefftrioroom01@t2voice.co.uk' - 1 0206171740|sip |2|00|(2)groupId for contact 'stefftrioroom01@t2voice.co.uk' - 2 0206171740|sip |3|00|SipOnEvContactsUpdate action '0' address 'SteffTrioRoom01@t2voice.co.uk' subscribed 1 0206171740|app1 |2|00|AppPhoneC::OnEvContactsUpdate - Action: 0, szNumber: SteffTrioRoom01@t2voice.co.uk, szDisplayName: SteffTrioRoom01@t2voice.co.uk, subscribed 1, bRefresh 1 0206171740|app1 |2|00|BuddyListC::Delete (Directory not updated) 0206171740|app1 |2|00|BuddyListC::AddItem2 name:SteffTrioRoom01 number:SteffTrioRoom01@t2voice.co.uk status:20 0206171740|app1 |2|00|appUi::updateLyncContacts - refresh 1 0206171740|app1 |2|00|compareEMLineKeys - EM Line key 6 name is different 0206171740|app1 |2|00|compareEMLineKeys - lines are same - 1 0206171740|sip |2|00|SipOnEvContactPresenceUpdate user 'SteffTrioRoom01@t2voice.co.uk' 'Steff Trio Room 01' status 'Away' customMsg ActToken [] ContactCardUpdate[1] EmailId[Steff.TrioRoom01@t2voice.co.uk] MostActiveDevice[0] 0206171740|app1 |2|00|AppPhoneC::OnEvContactPresenceUpdate - szNumber: SteffTrioRoom01@t2voice.co.uk, szDisplayName: Steff Trio Room 01, status: 3, ActivityToken: , CustomMessage: , HomNumb: , MobNumb: , WorkNumb : , OtherTel: voiceMail: bcontactcardupdate = 1 bOOOUpdate:1 bOOOStatus:0 isMostActive=0
Removing the Favorite:
0206173020|sip |1|00|MsgSipTcpPacket
0206173020|sip |3|00|CTcpSocket::OnRecvData
0206173020|sip |1|00|signatureBuffer: <TLS-DSK><78AEA425><21><SIP Communications Service><LS13FE01.voice.lab><9bd159d2bec570186720b63d94ac89bb><2><BENOTIFY><sip:steff-vvx4@t2voice.co.uk><F835CE57><sip:steff-vvx4@t2voice.co.uk><CE9B96E5-9E0A6818><sip:steff-vvx4@t2voice.co.uk><tel:+441753431726;ext=31726><>
0206173020|sip |1|00|TLS-DSK:VerifySignature Succeeded
0206173020|sip |2|00|CCallBase::IsChallenged 'BENOTIFY' Dialog Tag 'CE9B96E5-9E0A6818' pRequest Tag 'CE9B96E5-9E0A6818' state 'Confirmed'
0206173020|sip |3|00|CCallNoCall::calculateNewExpire new expires = 27833
0206173020|sip |2|00|Received modifiedContact
0206173020|sip |2|00|(1)groupId for contact 'stefftrioroom01@t2voice.co.uk' - 1
0206173020|sip |3|00|SipOnEvContactsUpdate action '0' address 'SteffTrioRoom01@t2voice.co.uk' subscribed 1
0206173020|sip |2|00|SipOnEvContactPresenceUpdate user 'SteffTrioRoom01@t2voice.co.uk' 'Steff Trio Room 01' status 'Inactive' customMsg ActToken [] ContactCardUpdate[1] EmailId[Steff.TrioRoom01@t2voice.co.uk] MostActiveDevice[0]
0206173020|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 1, szNumber [(null)] subscribed 0
0206173020|sip |3|00|sendBulkContactPresenceList typeOfUpdate : 0, contactListSize : 0
Rebooting the Phone:
0206172349|sip |2|00|Received group 0206172349|sip |3|00|SipOnEvContactGroupUpdate action '0' groupId '1' groupName '~' groupEmail '' 0206172349|sip |2|00|Received group 0206172349|sip |3|00|SipOnEvContactGroupUpdate action '0' groupId '2' groupName 'Pinned Contacts' groupEmail '' 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [VVX600-7A6C@t2voice.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [Steff-vvx1@t2voice.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [Steff-vvx2@t2voice.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [Steff-VVX3@t2voice.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [steff-vvx5@t2voice.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [steff-vvx6@t2voice.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [iic1@t2voice.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [steff-vvx3@t2voice.co.co.uk] subscribed 0 0206172349|sip |1|00|CUser::updateBulkContactList : bSendBulkListToApp 0, szNumber [SteffTrioRoom01@t2voice.co.uk] subscribed 0 0206172349|sip |2|00|CRoamingContactsSubscriptionMgr::handleSubscribeRoamingContacts- Processed roaming contacts 0206172349|sip |2|00|CRoamingContactsSubscriptionMgr::handleSubscribeRoamingContacts Total roaming contacts are: 9
Determine the general LYNC / Skype for Business status:
Diagnostics > Lync Status or Diagnostics > Skype for Business Status
You can expand the various sections to check the individual status
Unable to sign into Skype for Business Online:
- Settings > Logging > Global Log Level Limit > Debug
- Settings > Logging > Log File Size (Kbytes) > VVX 1000 or on a Trio 10240
- Settings > Logging > Module Log Level Limits > Web Ticket > Debug
- Settings > Logging > Module Log Level Limits > SIP > Event 1
0314114138|sip |1|00|CTrans::TimeOut500ms m_nMainTimeoutCount == 0. Call SndMsgFail 0314114138|sip |3|00|CTrans::TimeOut500ms Self Generated 480 Response 0314114138|sip |3|00|UA Client Non-INVITE REGISTER trans state 'callingTrying'->'completed' by 480 resp 10 timeout(0x4129f548)
and
0210085012|tickt|1|00|[StdRet soWebTicketO365Info::soWebTicketFetchADFSToken()]:[7115] 0210085012|tickt|1|00|Provisioning:Cipher suite = ALL:!aNULL:!eNULL:!DSS:!SEED:!ECDSA:!IDEA:!MEDIUM:!LOW:!EXP:!ADH:!ECDH:!PSK:!MD5:!RC4:@STRENGTH 0210085013|tickt|3|00|[StdRet soWebTicketO365Info::soWebTicketParseSoapError(UtilRapidxmlParserC*, S_SOAP_ERR_INFO*)]:[7857] Start 0210085013|tickt|1|00|[StdRet soWebTicketO365Info::soWebTicketParseSoapError(UtilRapidxmlParserC*, S_SOAP_ERR_INFO*)]:[7949] csFaultCode [] csReasonText [] csDetailErrorValue [] csInternalErrorCode [] csInternalErrorText [] 0210085013|tickt|1|00|[StdRet soWebTicketO365Info::soWebTicketFetchADFSToken()]:[7189] curlReturn [0] resCode[415] pResponse[ ] bRetVal[-1] 0210085013|tickt|0|00|soWebTicket: msg 7003 0 4b 44d4308 0210085013|tickt|1|00| FSM : Input = (FSM_INPUT_EVENT_ERROR) (23) 0210085013|tickt|1|00| FSM : Old State = (FSM_STATE_SIGNIN_O365_FEDERATED) (5) 0210085013|tickt|1|00| FSM : New State = (FSM_STATE_IDLE) (0) 0210085013|tickt|1|00| FSM : Action = (ACT_Error) (23)
In the above example Modern Authentication was enabled which is not yet supported on a RealPresence Trio
Contact Search:
- Settings > Logging > Global Settings > Global Log Level Limit > Debug
- Settings > Logging > Global Settings > Global Log Level Limit > Log File Size (Kbytes) > VVX 1000 or on a Trio 10240
- Settings > Logging > Module Log Level Limits > Web Ticket > Debug
- Settings > Logging > Module Log Level Limits > Skype for Business ABS or LYNC ABS > Debug
We are searching for the name baier
0626161405|abs |0|00|[CAbsDirectory::getContacts] 0626161405|abs |1|00|[CAbsDirectory::getContacts] sending message to abs task 0626161405|abs |1|00|[CAbsDirectory::processFetchTaskMsg] recieved message of type 1 0626161405|abs |0|00|[CAbsDirectory::getContactsFromServer] 0626161405|abs |1|00|[CAbsDirectory::getContactsFromServer] invoking so webticket api for fetching contacts for Baier search string 0626161405|cfg |5|00|Prm|Parameter feature.lync.abs.enabled requested type 2 (SInt) but is of type 7 (Bool) 0626161405|tickt|0|00|soWebTicket: msg deadbeaf 0 0 2b68530 0626161405|tickt|1|00|soWebTicketABSMexDocGet: request URI is https://cssloweb.polycom.com:443/groupexpansion/service.svc/mex 0626161405|tickt|0|00|Ntlm Version Mode = 2:NTLMv2 0626161405|tickt|1|00|Provisioning:Cipher suite = ALL:!aNULL:!eNULL:!DSS:!SEED:!ECDSA:!IDEA:!MEDIUM:!LOW:!EXP:!ADH:!ECDH:!PSK:!MD5:!RC4:@STRENGTH 0626161406|tickt|1|00|soWebTicketABSMexDocGet: Got response 1 code 200 0626161406|tickt|0|00|Got response 1 code 200 data: <?xml version="1.0" encoding="utf-8"?><wsdl:definitions name="Service" targetNamespace="DistributionListExpander" xmlns:wsdl="http://schemas.xmlsoap.org/wsdl/" xmlns:wsx="http://schemas.xmlsoap.org/ws/2004/09/mex" xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:wsa10="http://www.w3.org/2005/08/addressing" xmlns:wsp="http://schemas.xmlsoap.org/ws/2004/09/policy" xmlns:wsap="http://schemas.xmlsoap.org/ws/2004/08/addressing/p 0626161406|tickt|3|00|soWebTicketLISMexDocGet: WebTicketMexAddress is https://cssloweb.polycom.com/WebTicket/WebTicketService.svc 0626161406|tickt|1|00|soWebTicketABSMexDocGet: request URI is https://cssloweb.polycom.com:443/groupexpansion/service.svc/mex 0626161406|tickt|0|00|Ntlm Version Mode = 2:NTLMv2 0626161406|tickt|1|00|Provisioning:Cipher suite = ALL:!aNULL:!eNULL:!DSS:!SEED:!ECDSA:!IDEA:!MEDIUM:!LOW:!EXP:!ADH:!ECDH:!PSK:!MD5:!RC4:@STRENGTH 0626161406|tickt|1|00|soWebTicketABSMexDocGet: Got response 1 code 200 0626161406|tickt|0|00|Got response 1 code 200 data: <?xml version="1.0" encoding="utf-8"?><wsdl:definitions name="Service" targetNamespace="DistributionListExpander" xmlns:wsdl="http://schemas.xmlsoap.org/wsdl/" xmlns:wsx="http://schemas.xmlsoap.org/ws/2004/09/mex" xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:wsa10="http://www.w3.org/2005/08/addressing" xmlns:wsp="http://schemas.xmlsoap.org/ws/2004/09/policy" xmlns:wsap="http://schemas.xmlsoap.org/ws/2004/08/addressing/p 0626161406|tickt|3|00|soWebTicketLISMexDocGet: WebTicketMexAddress is //cssloweb.polycom.com/groupexpansion/service.svc/WebTicket_Bearer 0626161406|tickt|1|00|soWebticketGetAllUserInfo: hack prepended https: to the web ticket PIN service URL 0626161406|tickt|1|00|soWebTicketABSCertURIGet: request URI is https://cssloweb.polycom.com/WebTicket/WebTicketService.svc/mex 0626161406|tickt|0|00|Ntlm Version Mode = 2:NTLMv2 0626161406|tickt|1|00|Provisioning:Cipher suite = ALL:!aNULL:!eNULL:!DSS:!SEED:!ECDSA:!IDEA:!MEDIUM:!LOW:!EXP:!ADH:!ECDH:!PSK:!MD5:!RC4:@STRENGTH 0626161406|tickt|1|00|soWebTicketABSCertURIGet: Got response 1 code 200 0626161406|tickt|0|00|Got response 1 code 200 data: <?xml version="1.0" encoding="utf-8"?><wsdl:definitions name="WebTicketService" targetNamespace="http://tempuri.org/" xmlns:wsdl="http://schemas.xmlsoap.org/wsdl/" xmlns:wsx="http://schemas.xmlsoap.org/ws/2004/09/mex" xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:wsa10="http://www.w3.org/2005/08/addressing" xmlns:wsp="http://schemas.xmlsoap.org/ws/2004/09/policy" xmlns:wsap="http://schemas.xmlsoap.org/ws/2004/08/addressi 0626161406|tickt|3|00|soWebTicketABSCertURIGet: WebTicketMexAddress is //cssloweb.polycom.com/WebTicket/WebTicketService.svc/cert 0626161406|tickt|1|00|soWebticketGetAllUserInfo: hack prepended https: to the web ticket PIN service URL 0626161406|tickt|0|00|soWebTicket: msg deadbeaf 0 0 2a785c8 0626161406|tickt|1|00|soWebTicketAuthHeaderAddWithClientCert: Added digest(#timestamp) len 89 val unTGSy/hLL6o5lX2+4tMqOPmuT4= 0626161406|tickt|1|00|soWebTicketAuthHeaderAddWithClientCert: Added digest(#to) len 89 val uVOuPd6Pa7PniHnWsFDxJ7kpiP4= 0626161406|tickt|0|00|soWebTicketTicketGetWithclientCert: Request is: <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/"> <soap:Header><wsa:To xmlns:wsa="http://www.w3.org/2005/08/addressing" xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" wsu:Id="to">https://cssloweb.polycom.com/WebTicket/WebTicketService.svc/cert</wsa:To><wsa:ReplyTo xmlns:wsa="http://www.w3.org/2005/08/addressing"><wsa:Address>http://www.w3.org/2005/08/addressing/anonymous</wsa:Address></wsa: 0626161406|tickt|1|00|Provisioning:Cipher suite = ALL:!aNULL:!eNULL:!DSS:!SEED:!ECDSA:!IDEA:!MEDIUM:!LOW:!EXP:!ADH:!ECDH:!PSK:!MD5:!RC4:@STRENGTH 0626161406|tickt|2|00|soWebTicketTicketGetWithclientCert 1-200 result 0626161406|tickt|0|00|soWebTicketTicketGetWithclientCert: Response is: <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" xmlns:a="http://www.w3.org/2005/08/addressing" xmlns:u="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd"><s:Header><a:Action s:mustUnderstand="1">http://docs.oasis-open.org/ws-sx/ws-trust/200512/RSTRC/IssueFinal</a:Action><o:Security s:mustUnderstand="1" xmlns:o="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd"><u:Timestamp u:I 0626161406|tickt|3|00|soWebTicketTicketGetWithclientCert: AssertionID is SamlSecurityToken-e8dadc35-7a7e-4603-bb8f-dc796707352b 0626161406|tickt|0|00|utilPSha1: params 45fdca9c 32 45fdcabc 32 12bf09c 32 2c49ab0 52 0626161406|tickt|0|00|utilPSha1: wrote 20 bytes, 12 remaining. 0626161406|tickt|0|00|utilPSha1: wrote 20 bytes, -8 remaining. 0626161406|tickt|0|00|Lync ABS Request:<?xml version="1.0" encoding="utf-8"?> <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> <soap:Header><wsa:To xmlns:wsa="http://www.w3.org/2005/08/addressing" xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" wsu:Id="to">https://cssloweb.polycom.com/groupexpansion/service.svc/WebTicket_Bearer</wsa:To><wsa:ReplyTo xmlns:wsa="http://www.w3.org/2005/08/addressing"><wsa:Add 0626161406|tickt|1|00|Provisioning:Cipher suite = ALL:!aNULL:!eNULL:!DSS:!SEED:!ECDSA:!IDEA:!MEDIUM:!LOW:!EXP:!ADH:!ECDH:!PSK:!MD5:!RC4:@STRENGTH 0626161407|tickt|0|00|Lync ABS Response:[<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" xmlns:a="http://www.w3.org/2005/08/addressing"><s:Header><a:Action s:mustUnderstand="1">DistributionListExpander/IAddressBook/QueryAbContactsResponse</a:Action></s:Header><s:Body xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><QueryAbContactsResponse xmlns="DistributionListExpander"><QueryAbContactsResult><ResponseState>Success</ResponseState><ResultInfo/><AbContacts><AbCon 0626161407|abs |0|00|[CAbsDirectory::parseContacts] 0626161407|abs |0|00|[CAbsDirectory::updateContacts] 0626161407|cfg |5|00|Prm|Parameter feature.lync.abs.maxResult requested type 2 (SInt) but is of type 0 (UInt) 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=proxyaddresses, AttributeValues=smtp: 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=description, AttributeValues= 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=department, AttributeValues= 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=mail, AttributeValues=steffen.baier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=msrtcsip-primaryuseraddress, AttributeValues=sip:Steffen.Baier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=physicaldeliveryofficename, AttributeValues=Slough, England 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=company, AttributeValues=Polycom EMEA 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=mailnickname, AttributeValues=sbaier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=title, AttributeValues=Senior 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=displayname, AttributeValues=Baier, Steffen 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=sn, AttributeValues=Baier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=givenname, AttributeValues=Steffen 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=proxyaddresses, AttributeValues=smtp: 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=description, AttributeValues= 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=department, AttributeValues= 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=mail, AttributeValues=steffen.baier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=msrtcsip-primaryuseraddress, AttributeValues=sip:Steffen.Baier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=physicaldeliveryofficename, AttributeValues=Slough, England 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=company, AttributeValues=Polycom EMEA 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=mailnickname, AttributeValues=sbaier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=title, AttributeValues= 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=displayname, AttributeValues=Baier, Steffen 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=sn, AttributeValues=Baier 0626161407|abs |1|00|[CAbsDirectory::updateContacts] AttributeName=givenname, AttributeValues=Steffen 0626161407|abs |3|00|[CAbsDirectory::updateContacts] duplicate contact recieved from server 0626161407|abs |1|00|[CAbsDirectory::processFetchTaskMsg] waiting for message
Favorite Status Update or Change:
- Settings > Logging > Global Settings > Global Log Level Limit > Debug
- Settings > Logging > Global Settings > Global Log Level Limit > Log File Size (Kbytes) > VVX 1000 or on a Trio 10240
- Settings > Logging > Module Log Level Limits > Application 1 > Event 2
- Settings > Logging > Module Log Level Limits > SIP > Debug
0908094122|sip |0|00| NOTIFY sip:steffen.baier@176.26.207.10:57056;transport=tls;ms-received-cid=6700;grid SIP/2.0 0908094122|sip |0|00| ms-user-logon-data: RemoteUser 0908094122|sip |0|00| Via: SIP/2.0/TLS 140.242.213.5:443;branch=z9hG4bK8CD5E4B2.D975D6AC11DC89AD;branched=FALSE;ms-internal-info="diNqT3OX_5WGBCuyTohrVYEeB_5rUBKYOvzH2s4ktCgsus1nXZifEiUQAA" 0908094122|sip |0|00| Max-Forwards: 69 0908094122|sip |0|00| Via: SIP/2.0/TLS 10.252.79.31:57246;branch=z9hG4bKFA0BC867.9A9907A4FB1649AF;branched=FALSE;ms-received-port=57246;ms-received-cid=700 0908094122|sip |0|00| Authentication-Info: TLS-DSK qop="auth", opaque="710AF36B", srand="03D7BAB6", snum="117", rspauth="9d39a1d575ed52d893de3c0ce33ff1650d72eebc", targetname="SLOWPSFBFE02P.polycom.com", realm="SIP Communications Service", version=4 0908094122|sip |0|00| To: <sip:steffen.baier@polycom.com>;tag=759DFB6D-6C440958;epid=64167f0306e6 0908094122|sip |0|00| Content-Length: 797 0908094122|sip |0|00| From: <sip:steffen.baier@polycom.com>;tag=74440080 0908094122|sip |0|00| Call-ID: 519ee07adb0c276330503e1da00306e6 0908094122|sip |0|00| CSeq: 751 NOTIFY 0908094122|sip |0|00| Require: eventlist 0908094122|sip |0|00| Content-Type: application/msrtc-event-categories+xml 0908094122|sip |0|00| Event: presence 0908094122|sip |0|00| subscription-state: active;expires=5561 0908094122|sip |0|00| Supported: ms-dialog-route-set-update 0908094122|sip |0|00| 0908094122|sip |0|00| <categories xmlns="http://schemas.microsoft.com/2006/09/sip/categories" uri="sip:Test.User@polycom.com"><category xmlns="http://schemas.microsoft.com/2006/09/sip/categories" name="state" instance="1" publishTime="2017-09-08T08:41:19.570"> 0908094122|sip |0|00| <state xsi:type="aggregateState" lastActive="2017-09-08T08:41:19" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://schemas.microsoft.com/2006/09/sip/state"><availability>15500</availability><delimiter xmlns="http://schemas.microsoft.com/2006/09/sip/commontypes" /><timeZoneBias>-60</timeZoneBias><timeZoneName>GMT Daylight Time</timeZoneName><timeZoneAbbreviation>GMT Daylight Time</timeZoneAbbreviation><device>computer</device><end xmlns="http://schemas.microsoft.com/2006/09/sip/commont 0908094122|sip |0|00| ypes" /></state> 0908094122|sip |0|00| </category> 0908094122|sip |0|00| </categories> ... 0908094122|app1 |2|00|AppPhoneC::OnEvContactPresenceUpdate - szNumber: Test.User@polycom.com, szDisplayName: , status: 3, ActivityToken: , CustomMessage: , HomNumb: , MobNumb: , WorkNumb : , OtherTel: voiceMail: bcontactcardupdate = 0 bOOOUpdate:0 bOOOStatus:0 isMostActive=0
| Status App1 | SIP Availability | S4B Status |
| 0 | 3500 | Available |
| 1 | 6500 | Busy |
| 2 | 12500 | Be right back |
| 3 | 15500 | Away or Off Work |
| 4 | ||
| 5 | ||
| 6 | ||
| 7 | 9500 | Do not Disturb |
| 8 |
Authentication issue due unable to fall back to NTLM:
0829153849|sip |0|00|<<< Data received TLS 0829153849|sip |0|00| SIP/2.0 401 Unauthorized 0829153849|sip |0|00| ms-user-logon-data: RemoteUser 0829153849|sip |0|00| Date: Tue, 29 Aug 2017 21:38:50 GMT 0829153849|sip |0|00| WWW-Authenticate: TLS-DSK realm="SIP Communications Service", targetname="xxx.xxx.lync.com", version=4, sts-uri="https://xxx.com:443/CertProv/CertProvisioningService.svc" 0829153849|sip |0|00| From: "sfbline" <sip:sfbline@testaccount.com>;tag=34B8135F-6CA3A8DB;epid=0004f2fcd2b9 0829153849|sip |0|00| To: <sip:sfbline@testaccount.com>;tag=7B564ACDBBADF261E619089C93E08B81 0829153849|sip |0|00| Call-ID: 123456-42906b51-1d255d1a@xxx.xxx.xxx.xxx 0829153849|sip |0|00| CSeq: 1 REGISTER 0829153849|sip |0|00| Via: SIP/2.0/TLS 10.232.161.46:54716;branch=z9hG4bKe09f717354994A10;received=xx.xxx.x.xxx;ms-received-port=32031;ms-received-cid=F8E4A500 0829153849|sip |0|00| ms-telemetry-id: 36E8E4C6-CF00-50B8-A145-CAEB67D92A0B 0829153849|sip |0|00| Server: RTC/7.0 0829153849|sip |0|00| Content-Length: 0
We only receive TLS-DSK in the 401 Unauthorized
0829153849|tickt|2|00|soWebTicketUserCertInfo: Index 0 was not valid 0829153849|sip |3|00|m_nTLSDSKState = TLSDSK_INIT soWebTicketUserCertGet() rc:-1 0829153849|sip |3|00|Cert validityDuration is 0 0829153849|sip |3|00|Cert Valid Until 0 0829153849|sip |2|00|CStkTlsDsk:ParseMsgHdr Cert Valid=0,Credential Type=2 0829153849|sip |2|00|CStkTlsDsk:ParseMsgHdr Invalid Certificate..Forcing a re-sgin 0829153849|sip |0|00|m_nTLSDSKState = TLSDSK_INIT bAutoKickStartTLSDSK:1. rc -1 expires 0 0829153849|sip |3|00|TLS-
In this case we cannot attempt to failover to NTLM registrations because TLS-DSK was the only authentication mechanism in the offer.
Firewall Issue:
Bad example:
0125105413|afe |2|00|6: Server Store 101: ServerInfo: From application AFE got TURN server info: public 52.112.64.142 3478 udp 100 7 16;public 52.112.64.142 443 tcp 500; 0125105413|afe |3|00|3: Channel 79 rtp: -------------AfChannel: Sending Allocation request to 52.112.64.142:3478 0125105413|afe |1|00|9: Try no: 1, timeout: 500 0125105413|afe |2|00|6: Timeout while waiting for allocation response 0125105413|afe |1|00|9: Try no: 2, timeout: 500 0125105414|afe |2|00|6: Timeout while waiting for allocation response 0125105414|afe |4|00|4: Channel 79 rtp: AfChannel: --- turn port allocation failed --- 0125105414|afe |2|00|6: Channel 79 rtp: @ CAfChannel::GatherUdpRelayCandidate() # Gathering of UDP relayed candidates failed. 0125105414|afe |4|00|5: Channel 79 rtp: Failed to detect server reflexive address and port 0125105414|afe |2|00|6: Channel 79 rtp: Connecting to TCP TURN server at 52.112.64.142:443 0125105414|afe |2|00|6: WaitForConnect timed out for timeout value 500 0125105414|afe |4|00|4: Channel 79 rtp: Timed out connecting to TCP TURN via TCP 0125105414|afe |3|00|3: Channel 79 rtp: -------------AfChannel: Sending Allocation request to 52.112.64.142:443 0125105415|afe |2|00|6: WaitForConnect timed out for timeout value 500 0125105415|afe |4|00|4: Channel 79 rtp: AfChannel: --- turn port allocation failed ---
Good Example:
0126103504|afe |2|00|6: Server Store 101: ServerInfo: From application AFE got TURN server info: public 52.112.64.142 3478 udp 100 7 16;public 52.112.64.142 443 tcp 500; 0126103504|afe |3|00|3: Channel 97 rtp: -------------AfChannel: Sending Allocation request to 52.112.64.142:3478 0126103504|afe |1|00|9: Try no: 1, timeout: 500 0126103505|afe |2|00|6: Timeout while waiting for allocation response 0126103505|afe |1|00|9: Try no: 2, timeout: 500 0126103505|afe |2|00|6: Timeout while waiting for allocation response 0126103505|afe |4|00|4: Channel 97 rtp: AfChannel: --- turn port allocation failed --- 0126103505|afe |2|00|6: Channel 97 rtp: @ CAfChannel::GatherUdpRelayCandidate() # Gathering of UDP relayed candidates failed. 0126103505|afe |4|00|5: Channel 97 rtp: Failed to detect server reflexive address and port 0126103505|afe |2|00|6: Channel 97 rtp: Connecting to TCP TURN server at 52.112.64.142:443 0126103505|afe |3|00|1: Channel 97 rtp: @AfChannel::GetTurnPorts() TCP Connection successful in TCP TURN server 0126103505|afe |3|00|3: Channel 97 rtp: -------------AfChannel: Sending Allocation request to 52.112.64.142:443 0126103505|afe |1|00|9: Try no: 1, timeout: 2000 0126103505|afe |2|00|6: @ ESocket::UpdateTurnState() # Error response with no MESSAGE-INTEGRITY 0126103505|afe |2|00|6: @ ESocket::UpdateTurnState() # TURN allocte success response with Message Integrity 0126103505|afe |1|00|9: Channel 97 rtp: Returned TurnAllocate() with ESocket turn detected local ip (IPv4) 52.112.1.26, (IPv6) 2603:1037:0:82::1e
Checking the Skype for Business Dial Plan aka Digitmap:
Usually Skype for Business inbound provisions the Dial Plan and this can be checked via Diagnostics > Skype for Business Status > Miscellaneous Info
The above page shows a succesfully provisioned Skype for Business Dialplan.
Troubleshooting can be done via changing the Log Levels:
- Settings > Logging > Global Settings > Global Log Level Limit > Log File Size > VVX after UC Software 5.5.0 = 1000 or Trio 10240
- Settings > Logging > Module Log Level Limits > Support Objects > Event 3
I dialed 03456070809 (logs trunkated)
0318111112|so |3|00|[CSoRegexDigitMapElement]: Checking 0 against ^(1(47\d|70\d|800\d|1[68]\d{3}|\d\d)|999|[\*\#][\*\#\d]*\#)$
0318111112|so |3|00|[CSoRegexDigitMapElement]: Disabling ^(1(47\d|70\d|800\d|1[68]\d{3}|\d\d)|999|[\*\#][\*\#\d]*\#)$ - No match possible (0)
0318111112|so |3|00|[CSoRegexDigitMapElement]: Checking 0 against ^(4357)$
0318111112|so |3|00|[CSoRegexDigitMapElement]: Disabling ^(4357)$ - No match possible (0)
.....
0318111112|so |3|00|[CSoRegexDigitMapElement]: Checking 03 against ^(?:20)?(0318)$
0318111112|so |3|00|[CSoRegexDigitMapElement]: Checking 03 against ^(?:20)?(0599)$
0318111112|so |3|00|[CSoRegexDigitMapElement]: Disabling ^(?:20)?(0599)$ - No match possible (03)
...
0318111123|so |2|00|[SoDigitMapC]: Map Element Rt Match 97 (0xb1085d50 - ^0((1[1-9]\d{7,8}|2[03489]\d{8}|3[0347]\d{8}|5[56]\d{8}|8((4[2-5]|70)\d{7}|45464\d)))\d*(\D+\d+)?$ - 0 - +443456070809) declared timeout match (99) result (4)
0318111123|so |3|00|[SoDigitMapC::dial] ^0((1[1-9]\d{7,8}|2[03489]\d{8}|3[0347]\d{8}|5[56]\d{8}|8((4[2-5]|70)\d{7}|45464\d)))\d*(\D+\d+)?$ (0) Declared waited match 03456070809 -> +443456070809 - waitFor 1 - Status 1 - Line -1
Microsoft Tools:
You can use Microsoft's own Remote Connectivity Analyzer => here <=
The above can be utilized to Troubleshoot Office 365 issues.