Timeout and answering calls failures with VVX phones

Anonymous · ‎09-26-2017

Hi,

a customer reported some issues with VVX phones and answering incomming calls. I have had the same issues at the time the customer called me. Skype for Business logs do not show up an error whils this call, but I lost the incoming call from customer, then I answered this call via Skype Software.

The phone is a VVX 600 with a UC version 5.6.0.17325. My phone is a VVX 411 with the same version.

The VVX phone seemed to freeze and later the keyboard came back to react on presses. Here is the log that I have gathered:

0926115519|ec   |4|00|'calllogs' service did not received expected folder ids.
0926115519|ec   |2|00|Transaction processing completed for service 'calllogs'
0926115519|so   |2|00|In SoSystemTimerC::sysTimerReset()
0926115519|so   |2|00|In SoSystemTimerC::sysTimerReset() Set the Skip flag to TRUE for call back=0x5dccb8
0926115520|so   |2|00|SoSystemTimerC::notifyClients() Set the Skip Flag to FALSE
0926115525|btoe |2|00|BtoeAD timer expired
0926115529|sip  |2|00|Timeout500 to 'sip:My email address' state 'SubscirbeDialogStaticBLF' type 'CCallNoCall' (0x19aa3f0) expire 3600 Scheduling
0926115529|sip  |2|00|new UA Client Non-INVITE trans state 'callingTrying', timeout=0 (0x40ee75a8)
0926115529|sip  |2|00|CreateFailOverProxyList : Exit 'TLS' lookup with 1 IP Addresses
0926115529|sip  |2|00|CreateFailOverProxyList : IP 1 is '62.67.238.60' on tls port 443
0926115529|sip  |2|00|adjustRetransWhenTimerCreated UA Client Non-INVITE SUBSCRIBE state 'callingTrying' timeout=65 (0x40ee75a8)
0926115529|sip  |3|00|CTcpSocket::OnRecvData
0926115529|sip  |3|00|CTcpSocket::OnRecvData
0926115529|sip  |2|00|CCallBase::IsChallenged 'NOTIFY' Dialog Tag 'ED623F45-136801E2' pRequest Tag 'ED623F45-136801E2' state 'Confirmed'
0926115529|sip  |2|00|new UA Server Non-INVITE trans state 'callingTrying', timeout=0 (0x40eec248)
0926115529|sip  |3|00|CCallNoCall::calculateNewExpire new expires = 1
0926115529|sip  |3|00|UA Server Non-INVITE NOTIFY trans state 'callingTrying'->'completed' by 200 resp 65 timeout(0x40eec248)
0926115529|sip  |2|00|CTrans::InitRetrans for UA Server Non-INVITE NOTIFY state 'completed' Server 2 of 2 (0x40eec248)
0926115529|sip  |2|00|CCallNoCall::Notified full dialog-info 1 of 1 version rx 0 local -1
0926115529|sip  |2|00|CCallNoCall::Notified full dialog-info 1 set call state m_nVersion to 0
0926115529|sip  |2|00|UpdateAppOnStaticResource dest 'sip:My email address' nStaticRLSList 1
0926115529|sip  |2|00|UpdateAppOnStaticResource pBLFItem 1 Identity : 'sip:My email address'
0926115529|sip  |3|00|UpdateAppOnStaticResource pResource 'sip:My email address' matches
0926115529|sip  |3|00|CCallNoCall::UpdateAppOnStaticResource status has changed for 'sip:My email address'
0926115529|app1 |2|00|BLF::updateResource Total 1, refresh 0, frmApp 0
0926115529|app1 |2|00|BLF::updateResource Identity:sip:My email address Contact:sip:My email address Label:Lothar Status:0 Mode:0 Silent:0 Type:Normal
0926115529|sip  |2|00|New FULL DialogList for 'sip:My email address' state 'SubscirbeDialogStaticBLF' size 0
0926115540|sip  |3|00|CTcpSocket::OnRecvData
0926115540|sip  |2|00|CCallBase::IsChallenged 'NOTIFY' Dialog Tag '49146EAF-2BE4D3CC' pRequest Tag '49146EAF-2BE4D3CC' state 'Confirmed'
0926115540|sip  |2|00|new UA Server Non-INVITE trans state 'callingTrying', timeout=0 (0x40ef11a8)
0926115540|sip  |3|00|CCallNoCall::calculateNewExpire new expires = 21140
0926115540|sip  |3|00|UA Server Non-INVITE NOTIFY trans state 'callingTrying'->'completed' by 200 resp 65 timeout(0x40ef11a8)
0926115540|sip  |2|00|CTrans::InitRetrans for UA Server Non-INVITE NOTIFY state 'completed' Server 2 of 2 (0x40ef11a8)
0926115540|sip  |2|00|Buddy  Instance ID Container Version expireType        xsi:state availability
0926115540|sip  |2|00|Buddy            1         0       0    Unknown        Aggregate        15500
0926115540|sip  |2|00|Buddy presence calculated on Aggregate 15500 User 0 -> 'Away'
0926115540|sip  |3|00|CMicrosoftResourceList::handlePresenceUpdate: Unknown Presence Object My email address
0926115540|sip  |3|00|sendBulkContactPresenceList typeOfUpdate : 1, contactListSize : 1
0926115540|sip  |3|00|SipOnEvBulkContactsInfoUpdate action '1'
0926115540|app1 |3|00|BulkContactsInfoUpdate received, increasing the watchdogTimeOut
0926115540|app1 |2|00|AppPhoneC::OnEvBulkContactsInfoUpdate - Action: 1 , size [1]
0926115540|app1 |2|00|AppPhoneC::OnEvContactPresenceUpdate - szNumber: My email address, szDisplayName: , status: 3, ActivityToken: , CustomMessage: , HomNumb: ,  MobNumb: ,  WorkNumb  : , OtherTel:  voiceMail: bcontactcardupdate = 0 bOOOUpdate:0 bOOOStatus:0 isMostActive=0
0926115540|app1 |3|00|OnEvContactPresenceUpdate buddy My email address not found
0926115540|app1 |2|00|updatePresenceStatus number: My email address, displayname: , status: 3, bOOOUpdate: 0, bOOOStatus: 0
0926115540|app1 |2|00|appUi::updateLyncContacts - refresh 1
0926115540|app1 |2|00|compareEMLineKeys - lines are same - 0
0926115540|app1 |2|00|EM Line keys are equal hence not sending to EM
0926115540|sip  |2|00|Calling Blocked contact list from updateBulkPresenceList
0926115555|btoe |2|00|BtoeAD timer expired
0926115602|sip  |3|00|CTrans::TimeOut500ms Self Generated 480 Response
0926115602|sip  |2|00|CStkDialog::CStkDialog SetAddressLocal Config 'Customers name' <Customers email address:0>
0926115602|sip  |2|00|CStkDialog::CStkDialog AddressLocal set to Config
0926115602|sip  |3|00|CStkDialog::SetAddressLocal localTag set to ''
0926115602|sip  |3|00|CStkDialog::SetAddressLocal new address added of 1
0926115602|sip  |2|00|CStkDialog::CStkDialog TAG '51BBF6C4-406D4521' generated
0926115602|sip  |2|00|CStkDialog::CStkDialog local addr 'Customers name' <Customers email address:0> Tag '51BBF6C4-406D4521'
0926115602|sip  |2|00|CStkDialog::CStkDialog exit 0x19c3940 local list size 1
0926115602|sip  |3|00|CStkDialogList::OnEvResponse new Dialog 'id056785be' created
0926115602|sip  |2|00|new UA Client Non-INVITE trans state 'callingTrying', timeout=0 (0x40eeb368)
0926115602|sip  |3|00|UA Client Non-INVITE SUBSCRIBE trans state 'callingTrying'->'completed' by 480 resp 10 timeout(0x40eeb368)
0926115602|sip  |3|00|CCallNoCall::NewCallState 'SubscirbeDialogStaticBLF'->'Idle' (0x19aa3f0)
0926115602|sip  |3|00|CCallNoCall::NewCallState 'SubscirbeDialogStaticBLF' IDLE
0926115602|sip  |2|00|CStkDialog::CStkDialog SetAddressLocal Config 'Customers name' <Customers email address:0>
0926115602|sip  |2|00|CStkDialog::CStkDialog AddressLocal set to Config
0926115602|sip  |3|00|CStkDialog::SetAddressLocal localTag set to ''
0926115602|sip  |3|00|CStkDialog::SetAddressLocal new address added of 1
0926115602|sip  |2|00|CStkDialog::CStkDialog TAG '5040AEBE-A0AE039B' generated
0926115602|sip  |2|00|CStkDialog::CStkDialog local addr 'Customers name' <Customers email address:0> Tag '5040AEBE-A0AE039B'
0926115602|sip  |2|00|CStkDialog::CStkDialog exit 0x19c3cbc local list size 1
0926115602|sip  |2|00|CStkDialogList::CreateDialogObject localTarg usr 'Customers user'
0926115602|sip  |3|00|CCallNoCall::StaticBLF call Identity : 'sip:My email address'
0926115602|sip  |2|00|CCallNoCall::StaticBLF monitored resource Id 'sip:My email address'
0926115602|sip  |2|00|CCallNoCall::StaticBLF listFound 1
0926115602|sip  |2|00|New PARTIAL DialogList for 'sip:My email address' state 'SubscirbeDialogStaticBLF' size 0
0926115602|sip  |2|00|UpdateAppOnStaticResource dest 'sip:My email address' nStaticRLSList 1
0926115602|sip  |2|00|UpdateAppOnStaticResource pBLFItem 1 Identity : 'sip:My email address'
0926115602|sip  |3|00|UpdateAppOnStaticResource pResource 'sip:My email address' matches
0926115602|sip  |3|00|CCallNoCall::UpdateAppOnStaticResource status has changed for 'sip:My email address'
0926115602|app1 |2|00|BLF::updateResource Total 1, refresh 0, frmApp 0
0926115602|app1 |2|00|BLF::updateResource Identity:sip:My email address Contact:sip:My email address Label:Lothar Status:6 Mode:0 Silent:0 Type:Normal
0926115602|sip  |3|00|Subscribe failed - status code 480 Expires -1
0926115602|sip  |3|00|CStateSubscribeClient::OnEvResponse 480 for SubscirbeDialogStaticBLF
0926115602|sip  |3|00|CTrans::TimeOut500ms Self Generated 480 Response, m_nMainTimeoutCount 0  m_nExipres 16 method 'SUBSCRIBE'
0926115609|sip  |2|00|Timeout500 to 'sip:My email address' state 'SubscirbeDialogStaticBLF' type 'CCallNoCall' (0x19aa3f0) expire 3600 Scheduling
0926115609|sip  |2|00|new UA Client Non-INVITE trans state 'callingTrying', timeout=0 (0x40ee75a8)
0926115609|sip  |2|00|CreateFailOverProxyList : Exit 'TLS' lookup with 1 IP Addresses
0926115609|sip  |2|00|CreateFailOverProxyList : IP 1 is '62.67.238.60' on tls port 443
0926115610|sip  |3|00|CTcpSocket::OnRecvData
0926115610|sip  |3|00|CTcpSocket::OnRecvData
0926115610|sip  |2|00|CCallBase::IsChallenged 'NOTIFY' Dialog Tag '5040AEBE-A0AE039B' pRequest Tag '5040AEBE-A0AE039B' state 'Confirmed'
0926115610|sip  |2|00|new UA Server Non-INVITE trans state 'callingTrying', timeout=0 (0x40eec268)
0926115610|sip  |3|00|CCallNoCall::calculateNewExpire new expires = 1
0926115610|sip  |3|00|UA Server Non-INVITE NOTIFY trans state 'callingTrying'->'completed' by 200 resp 65 timeout(0x40eec268)
0926115610|sip  |2|00|CTrans::InitRetrans for UA Server Non-INVITE NOTIFY state 'completed' Server 2 of 2 (0x40eec268)
0926115610|sip  |2|00|CCallNoCall::Notified full dialog-info 1 of 1 version rx 0 local -1
0926115610|sip  |2|00|CCallNoCall::Notified full dialog-info 1 set call state m_nVersion to 0
0926115610|sip  |2|00|UpdateAppOnStaticResource dest 'sip:My email address' nStaticRLSList 1
0926115610|sip  |2|00|UpdateAppOnStaticResource pBLFItem 1 Identity : 'sip:My email address'
0926115610|sip  |3|00|UpdateAppOnStaticResource pResource 'sip:My email address' matches
0926115610|sip  |3|00|CCallNoCall::UpdateAppOnStaticResource status has changed for 'sip:My email address'
0926115610|app1 |2|00|BLF::updateResource Total 1, refresh 0, frmApp 0
0926115610|app1 |2|00|BLF::updateResource Identity:sip:My email address Contact:sip:My email address Label:Lothar Status:0 Mode:0 Silent:0 Type:Normal
0926115610|sip  |2|00|New FULL DialogList for 'sip:My email address' state 'SubscirbeDialogStaticBLF' size 0
0926115619|ec   |2|00|Fetching 'calllogs' service data using operation 'GetConvHistFolderId' and token type '2', length '0'
0926115619|ec   |3|00|Processing FindFolder response FOLDER_SIZE = [0]
0926115619|ec   |4|00|'calllogs' service did not received expected folder ids.
0926115619|ec   |2|00|Transaction processing completed for service 'calllogs'
0926115619|ec   |2|00|Fetching 'vvm' service data using operation 'FindVVMItems' and token type '2', length '0'
0926115620|ec   |4|00|'vvm' service is not available
0926115620|ec   |2|00|Transaction processing completed for service 'vvm'
0926115626|btoe |2|00|BtoeAD timer expired
0926115642|sip  |3|00|CTrans::TimeOut500ms Self Generated 480 Response
0926115642|sip  |2|00|CStkDialog::CStkDialog SetAddressLocal Config 'Customers name' <Customers email address:0>
0926115642|sip  |2|00|CStkDialog::CStkDialog AddressLocal set to Config
0926115642|sip  |3|00|CStkDialog::SetAddressLocal localTag set to ''
0926115642|sip  |3|00|CStkDialog::SetAddressLocal new address added of 1
0926115642|sip  |2|00|CStkDialog::CStkDialog TAG 'A65969A0-87379EFD' generated
0926115642|sip  |2|00|CStkDialog::CStkDialog local addr 'Customers name' <Customers email address:0> Tag 'A65969A0-87379EFD'
0926115642|sip  |2|00|CStkDialog::CStkDialog exit 0x19c3940 local list size 1
0926115642|sip  |3|00|CStkDialogList::OnEvResponse new Dialog 'id01a0a44e' created
0926115642|sip  |2|00|new UA Client Non-INVITE trans state 'callingTrying', timeout=0 (0x40eeb368)
0926115642|sip  |3|00|UA Client Non-INVITE SUBSCRIBE trans state 'callingTrying'->'completed' by 480 resp 10 timeout(0x40eeb368)
0926115642|sip  |3|00|CCallNoCall::NewCallState 'SubscirbeDialogStaticBLF'->'Idle' (0x19aa3f0)
0926115642|sip  |3|00|CCallNoCall::NewCallState 'SubscirbeDialogStaticBLF' IDLE
0926115642|sip  |2|00|CStkDialog::CStkDialog SetAddressLocal Config 'Customers name' <Customers email address:0>
0926115642|sip  |2|00|CStkDialog::CStkDialog AddressLocal set to Config
0926115642|sip  |3|00|CStkDialog::SetAddressLocal localTag set to ''
0926115642|sip  |3|00|CStkDialog::SetAddressLocal new address added of 1
0926115642|sip  |2|00|CStkDialog::CStkDialog TAG '983DAF9A-9D536B77' generated
0926115642|sip  |2|00|CStkDialog::CStkDialog local addr 'Customers name' <Customers email address:0> Tag '983DAF9A-9D536B77'
0926115642|sip  |2|00|CStkDialog::CStkDialog exit 0x19c4730 local list size 1
0926115642|sip  |2|00|CStkDialogList::CreateDialogObject localTarg usr 'Customers user'
0926115642|sip  |3|00|CCallNoCall::StaticBLF call Identity : 'sip:My email address'
0926115642|sip  |2|00|CCallNoCall::StaticBLF monitored resource Id 'sip:My email address'
0926115642|sip  |2|00|CCallNoCall::StaticBLF listFound 1
0926115642|sip  |2|00|New PARTIAL DialogList for 'sip:My email address' state 'SubscirbeDialogStaticBLF' size 0
0926115642|sip  |2|00|UpdateAppOnStaticResource dest 'sip:My email address' nStaticRLSList 1
0926115642|sip  |2|00|UpdateAppOnStaticResource pBLFItem 1 Identity : 'sip:My email address'
0926115642|sip  |3|00|UpdateAppOnStaticResource pResource 'sip:My email address' matches
0926115642|sip  |3|00|CCallNoCall::UpdateAppOnStaticResource status has changed for 'sip:My email address'
0926115642|app1 |2|00|BLF::updateResource Total 1, refresh 0, frmApp 0
0926115642|app1 |2|00|BLF::updateResource Identity:sip:My email address Contact:sip:My email address Label:Lothar Status:6 Mode:0 Silent:0 Type:Normal
0926115642|sip  |3|00|Subscribe failed - status code 480 Expires -1
0926115642|sip  |3|00|CStateSubscribeClient::OnEvResponse 480 for SubscirbeDialogStaticBLF
0926115642|sip  |3|00|CTrans::TimeOut500ms Self Generated 480 Response, m_nMainTimeoutCount 0  m_nExipres 32 method 'SUBSCRIBE'
0926115657|btoe |2|00|BtoeAD timer expired
0926115658|sip  |2|00|Timeout500 to 'sip:My email address' state 'SubscirbeDialogStaticBLF' type 'CCallNoCall' (0x19aa3f0) expire 3600 Scheduling
0926115658|sip  |2|00|new UA Client Non-INVITE trans state 'callingTrying', timeout=0 (0x40ee75a8)
0926115658|sip  |2|00|CreateFailOverProxyList : Exit 'TLS' lookup with 1 IP Addresses
0926115658|sip  |2|00|CreateFailOverProxyList : IP 1 is '62.67.238.60' on tls port 443
0926115658|sip  |2|00|adjustRetransWhenTimerCreated UA Client Non-INVITE SUBSCRIBE state 'callingTrying' timeout=65 (0x40ee75a8)
0926115658|sip  |3|00|CTcpSocket::OnRecvData
0926115658|sip  |3|00|CTcpSocket::OnRecvData
0926115658|sip  |2|00|CCallBase::IsChallenged 'NOTIFY' Dialog Tag '983DAF9A-9D536B77' pRequest Tag '983DAF9A-9D536B77' state 'Confirmed'
0926115658|sip  |2|00|new UA Server Non-INVITE trans state 'callingTrying', timeout=0 (0x40eec248)
0926115658|sip  |3|00|CCallNoCall::calculateNewExpire new expires = 1
0926115658|sip  |3|00|UA Server Non-INVITE NOTIFY trans state 'callingTrying'->'completed' by 200 resp 65 timeout(0x40eec248)
0926115658|sip  |2|00|CTrans::InitRetrans for UA Server Non-INVITE NOTIFY state 'completed' Server 2 of 2 (0x40eec248)
0926115658|sip  |2|00|CCallNoCall::Notified full dialog-info 1 of 1 version rx 0 local -1
0926115658|sip  |2|00|CCallNoCall::Notified full dialog-info 1 set call state m_nVersion to 0
0926115658|sip  |2|00|UpdateAppOnStaticResource dest 'sip:My email address' nStaticRLSList 1
0926115658|sip  |2|00|UpdateAppOnStaticResource pBLFItem 1 Identity : 'sip:My email address'
0926115658|sip  |3|00|UpdateAppOnStaticResource pResource 'sip:My email address' matches
0926115658|sip  |3|00|CCallNoCall::UpdateAppOnStaticResource status has changed for 'sip:My email address'
0926115658|app1 |2|00|BLF::updateResource Total 1, refresh 0, frmApp 0
0926115658|app1 |2|00|BLF::updateResource Identity:sip:My email address Contact:sip:My email address Label:Lothar Status:0 Mode:0 Silent:0 Type:Normal
0926115658|sip  |2|00|New FULL DialogList for 'sip:My email address' state 'SubscirbeDialogStaticBLF' size 0
0926115700|ec   |4|00|Re-syncing calendar events
0926115700|ec   |4|00|Calendar subscription state '0' Watermark state '0' Response code 'ErrorMissingEmailAddress'

Thanks,

Lothar

SteffenBaierUK · ‎09-26-2017

Hello Lothar,

welcome to the Polycom Community.

I see a 480 issue:

0926115602|sip  |3|00|CTrans::TimeOut500ms Self Generated 480 Response

The call itself is in your logging level shown when it fails as

0926115602|sip  |3|00|UA Client Non-INVITE SUBSCRIBE trans state 'callingTrying'->'completed' by 480 resp 10 timeout(0x40eeb368)

There could be a multitude of issues as this could be a routing issue etc. aka as it takes 22 seconds from the last message.

Prior to this we report 200OK

0926115540|sip  |3|00|UA Server Non-INVITE NOTIFY trans state 'callingTrying'->'completed' by 200 resp 65 timeout(0x40ef11a8)

We would SIP logs in debug to check if all the messages come in the right timings and are all answered.

This is outside the scope of the community from a Polycom employee's perspective aka needs to be a support ticket.

Please ensure to provide some feedback if this reply has helped you so other users can profit from your experience.

Best Regards

Steffen Baier

Polycom Global Services

------------------------------------------------
Notice: I am an HP Poly employee but all replies within the community are done as a volunteer outside of my day role. This community forum is not an official HP Poly support resource, thus responses from HP Poly employees, partners, and customers alike are best-effort in attempts to share learned knowledge.
If you need immediate and/or official assistance for former Poly\Plantronics\Polycom please open a service ticket through your support channels
For HP products please check HP Support.

Please also ensure you always check the General VoIP , Video Endpoint , UC Platform (Microsoft) , PSTN

Anonymous · ‎09-28-2017

Hi,

according to the requirement to log sip at debug level, I tried to add the corresponding parameter within my provisioning file for the two devices that I want to gather these logs from.

The value log.level.change.sip="0" has been set and deployed, but the phone in my case my phone did not reflect the changes if I have a look into the web page displaying the log settings.

What else must I set to activate the entry to become debug?

I am using device.set="1".

I only determite a log line claiming something about this:

0928134453|cfg |5|00|Prm|Parameter log.level.change.sip requested type 2 but is of type 0

Thanks, Lothar

SteffenBaierUK · ‎09-28-2017

Hello Lothar,

The community's VoIP FAQ and in addition the Skype for Business FAQ contains these posts here:

Jan 19, 2012 Question: How to troubleshoot Polycom VoIP related Issues?

Resolution: Please check => here <=

and

Jan 17, 2017 Question:How can I troubleshoot simple Skype for Business, LYNC or Office365 issues?

Resolution: Have a look => here <=

Both of these show details for logging and explain the Global Log Level Limit needs to be set as well.

Please ensure you always check the community FAQ and/or utilize the community search before posting any new topics or follow up post’s.

Please ensure to provide some feedback if this reply has helped you so other users can profit from your experience.

Best Regards

Steffen Baier

Polycom Global Services

------------------------------------------------
Notice: I am an HP Poly employee but all replies within the community are done as a volunteer outside of my day role. This community forum is not an official HP Poly support resource, thus responses from HP Poly employees, partners, and customers alike are best-effort in attempts to share learned knowledge.
If you need immediate and/or official assistance for former Poly\Plantronics\Polycom please open a service ticket through your support channels
For HP products please check HP Support.

Please also ensure you always check the General VoIP , Video Endpoint , UC Platform (Microsoft) , PSTN

Create an account on the HP Community to personalize your profile and ask a question