Re: BToE pairing fails following upgrade to 4.4 - HP Support Community

JamesW7 · ‎06-15-2021

Pairing fails following an update to BToE 4.4. Reverting to 4.3 resolves the issue.

I've included logs below. Symantec Endpoint encryption does not reveal any blocked traffic.

This particular model is a VVX 500 - 5.9.6.2996 but the issue has also been observed on a VVX 501 - 6.2.0.4023 as well.

 -------------------------------------------------------------
|                  BToE APP Version    4.4.0.0                |
| OS Info: Windows 10          System Info: AMD64 64bit       |
 -------------------------------------------------------------
[06/15/21 : 11:31:08]  PBC: Read from Registry: LOG_LEVEL = 5
[06/15/21 : 11:31:08]  PBC: Read from Registry: PLAYBACK_MODE_EN = 1
[06/15/21 : 11:31:08]  PBC: Read from Registry: IP_PAIRING_EN = 0
Configs: Errors (1) Warnings (1) NI_Icons (1) NI_Msg (1)
Configs: Playback (1) Log ( 5) Limit (20) IPP (0) exit (1)
Configs: PairMode (Auto) Passcode cache (1) vdiSessionControlEnabled (0)
--------------------------------------------------------------
[06/15/21 : 11:31:08]  PBC: Registered network events handler successfully
[06/15/21 : 11:31:08]  PBC: SESSION SEQUENCE 1
[06/15/21 : 11:31:08]  PBC: Waiting for discovery thread to exit
[06/15/21 : 11:31:08]  PBC: Launching the discovery thread (PairMode: 1)...
[06/15/21 : 11:31:08]  PBC: discovery_server: 1097 Soft_device_state WAITING_FOR_CONNECTION
[06/15/21 : 11:31:08]  PBC: Waiting for IP-Phone Connection(on UDP).....
[06/15/21 : 11:31:11]  PBC: Received packet from 10.231.131.106(len 16)
[06/15/21 : 11:31:11]  PBC: Received packet from 0Xae7836a
[06/15/21 : 11:31:11]  PBC: VVX MAC ID 05:09:06:00:04:F2
[06/15/21 : 11:31:11]  PBC: Received VVX Version from IPP is 5.9.6
[06/15/21 : 11:31:11]  PBC: Received the BToE protocol(2)
[06/15/21 : 11:31:11]  PBC: Using newXmlFormat
[06/15/21 : 11:31:11]  PBC: Posting WM_DESTROY to all open Dlgs
[06/15/21 : 11:31:11]  PBC ERR: (discovery_server:1300) Discovery soft device state discovery for proto(2)
[06/15/21 : 11:31:11]  PBC: TLS: creating the context 
[06/15/21 : 11:31:11]  PBC: TLS: succesfully set your CAfile or CApath correctly
[06/15/21 : 11:31:11]  PBC: TLS: TCP connection successful (1416)
[06/15/21 : 11:31:11]  PBC: TLS: doing SSL_connect 
[06/15/21 : 11:31:11]  PBC: TLS: doing SSL_connect done(1) 
[06/15/21 : 11:31:11]  PBC: TLS: connected to DeskPhone successfully
[06/15/21 : 11:31:11]  PBC: Connected socket's local IP : 15x.1xx.1x.x
[06/15/21 : 11:31:11]  PBC: Connected socket's local port : 55469
[06/15/21 : 11:31:11]  PBC: Final IP Address : 15x.1xx.1x.x
[06/15/21 : 11:31:11]  PBC: Adapter Type: 6  Desc : Intel(R) Ethernet Connection (2) I219-LM
[06/15/21 : 11:31:11]  PBC: Adapter ID : {93742432-F5C4-4E65-9CB3-080484E637F5}
[06/15/21 : 11:31:11]  PBC: setConnectedInterface {93742432-F5C4-4E65-9CB3-080484E637F5}

0615113111|btoe |0|00|Going to establish a TLS connection
0615113111|btoe |4|00|BToE-TLS: SSL connection established with the client
0615113111|btoe |0|00|SSL Connect is successful
0615113111|btoe |1|00|BtoeAD Stop message being send
0615113111|btoe |3|00|Host(10.231.131.106) is connected from(157.1xx.1x.x)
0615113111|btoe |2|00|isNotSshConnection = 5
0615113111|btoe |3|00|m_nBtoeState soBtoeMgrAssocSuccess
0615113111|btoe |2|00|cBtoeAssociation Established new connection with PBC
0615113111|btoe |2|00|BtoeAD Stop
0615113111|btoe |5|00|4 Request Not Handled
0615113111|btoe |0|00|Recv request from PBC client len[304]
0615113111|btoe |0|00|Request processing complete

JamesW7 · ‎06-15-2021

See the same behavior with a VVX 501 and 6.3.1.11465

 -------------------------------------------------------------
|                  BToE APP Version    4.4.0.0                |
| OS Info: Windows 10          System Info: AMD64 64bit       |
 -------------------------------------------------------------
[06/15/21 : 15:34:37]  PBC: Read from Registry: LOG_LEVEL = 5
[06/15/21 : 15:34:37]  PBC: Read from Registry: PLAYBACK_MODE_EN = 1
[06/15/21 : 15:34:37]  PBC: Read from Registry: IP_PAIRING_EN = 0
Configs: Errors (1) Warnings (1) NI_Icons (1) NI_Msg (1)
Configs: Playback (1) Log ( 5) Limit (20) IPP (0) exit (1)
Configs: PairMode (Auto) Passcode cache (1) vdiSessionControlEnabled (0)
--------------------------------------------------------------
[06/15/21 : 15:34:37]  PBC: Registered network events handler successfully
[06/15/21 : 15:34:37]  PBC: SESSION SEQUENCE 1
[06/15/21 : 15:34:37]  PBC: Waiting for discovery thread to exit
[06/15/21 : 15:34:37]  PBC: Launching the discovery thread (PairMode: 1)...
[06/15/21 : 15:34:37]  PBC: discovery_server: 1097 Soft_device_state WAITING_FOR_CONNECTION
[06/15/21 : 15:34:37]  PBC: Waiting for IP-Phone Connection(on UDP).....
[06/15/21 : 15:34:47]  PBC: Received packet from 10.231.131.141(len 16)
[06/15/21 : 15:34:47]  PBC: Received packet from 0Xae7838d
[06/15/21 : 15:34:47]  PBC: VVX MAC ID 06:03:01:64:16:7F
[06/15/21 : 15:34:47]  PBC: Received VVX Version from IPP is 6.3.1
[06/15/21 : 15:34:47]  PBC: Received the BToE protocol(2)
[06/15/21 : 15:34:47]  PBC ERR: (discovery_server:1300) Discovery soft device state discovery for proto(2)
[06/15/21 : 15:34:47]  PBC: TLS: creating the context 
[06/15/21 : 15:34:47]  PBC: TLS: succesfully set your CAfile or CApath correctly
[06/15/21 : 15:34:47]  PBC: TLS: TCP connection successful (1432)
[06/15/21 : 15:34:47]  PBC: TLS: doing SSL_connect 
[06/15/21 : 15:34:47]  PBC: TLS: doing SSL_connect done(1) 
[06/15/21 : 15:34:47]  PBC: TLS: connected to DeskPhone successfully
[06/15/21 : 15:34:47]  PBC: Connected socket's local IP : 1xx.1xx.1x.x
[06/15/21 : 15:34:47]  PBC: Connected socket's local port : 58505
[06/15/21 : 15:34:47]  PBC: Final IP Address : 1xx.1xx.1x.x
[06/15/21 : 15:34:47]  PBC: Adapter Type: 6  Desc : Intel(R) Ethernet Connection (2) I219-LM
[06/15/21 : 15:34:47]  PBC: Adapter ID : {93742432-F5C4-4E65-9CB3-080484E637F5}
[06/15/21 : 15:34:47]  PBC: setConnectedInterface {93742432-F5C4-4E65-9CB3-080484E637F5}

0615154015|btoe |3|00|PpsBtoeC::cfgParamBtoeCallBack: BTOE config parameter is changed
0615154015|btoe |2|00|PpsBtoeC::handleBtoeStartStopPairing(): m_bEnabled [1], m_ePairingMode:[1] (1-Auto, 2-Manual), bPCPortUP [1]
0615154015|btoe |2|00|Another pairing mode is selected (1). So stop the current pairing mode (2) and start pairing in new mode
0615154015|btoe |2|00|stopPairing(2142)
0615154015|btoe |2|00|PpsBtoeC::handleBtoeStartStopPairing(): m_bEnabled [1], m_ePairingMode:[1] (1-Auto, 2-Manual), bPCPortUP [1]
0615154015|btoe |2|00|Another pairing mode is selected (1). So stop the current pairing mode (2) and start pairing in new mode
0615154015|btoe |2|00|stopPairing(2142)
0615154015|btoe |1|00|PpsBtoeC::ppsProcMsg MsgPpsAssocTaskStop
0615154015|btoe |3|00|BTOE state is soBtoeMgrDiscovery, not informing to the app!!
0615154015|btoe |2|00|AutoSignin/signoff status:0  m_nCredType=1 SignRequested=0 User mode = [1]
0615154015|btoe |0|00|BToE-TLS: cleanupTLS
0615154015|btoe |1|00|cBToEAssociation rtosTaskDelete StartAssociationTask Result = 0
0615154015|btoe |1|00|cBToEAssociation rtosTaskDelete ProcessReceivedRequest Result = 0
0615154015|btoe |3|00|ppsProcMsgStopThreads:1870 m_nBtoeState soBtoeMgrStopped
0615154015|btoe |4|00|stopCall ppsBtoe.hSoCall handle is NULL
0615154015|btoe |2|00|stopCall Send End Call Request to LC and assign hsoCall handle to NULL
0615154015|btoe |2|00|PpsBtoeC::handleBtoeStartStopPairing(): m_bEnabled [1], m_ePairingMode:[1] (1-Auto, 2-Manual), bPCPortUP [1]
0615154015|btoe |2|00|Start Pairing (Auto Mode)
0615154015|btoe |2|00|startPairing(2123)
0615154015|btoe |1|00|PpsBtoeC::ppsProcMsg MsgPpsAssocTaskStop
0615154015|btoe |3|00|BTOE is already stopped.
0615154015|btoe |1|00|PpsBtoeC::ppsProcMsg MsgPpsStartBtoeAssocTask
0615154015|btoe |2|00|PC port status is UP. Start BToE manager
0615154015|btoe |2|00|Starting the ssh sever
0615154015|btoe |3|00|m_nBtoeState soBtoeMgrDiscovery
0615154015|btoe |2|00|cBToEAssociation Launched processReceivedRequest
0615154015|btoe |0|00|StartAssociationTask 4.3
0615154015|btoe |2|00|cBToEAssociation Launched StartAssociationTask
0615154015|btoe |3|00|cBtoeAssociation Waiting for connection from PBC
0615154015|btoe |0|00|BToE-TLS:initTLS
0615154015|btoe |2|00|cBToEAutoDiscovery launched StartAutoDiscovery task
0615154015|btoe |0|00|Going to establish a TLS connection
0615154016|btoe |4|00|BToE-TLS: SSL connection established with the client
0615154016|btoe |0|00|SSL Connect is successful
0615154016|btoe |1|00|BtoeAD Stop message being send
0615154016|btoe |3|00|Host(10.231.131.141) is connected from(1xx.1xx.1x.x)
0615154016|btoe |3|00|m_nBtoeState soBtoeMgrAssocSuccess
0615154016|btoe |2|00|cBtoeAssociation Established new connection with PBC
0615154016|btoe |2|00|BtoeAD Stop
0615154016|btoe |5|00|4 Request Not Handled
0615154016|btoe |0|00|Recv request from PBC client len[303]
0615154016|btoe |0|00|Request processing complete

4.3 works as expected with the same VVX

-------------------------------------------------------------
|                  BToE APP Version    4.3.0.0                |
| OS Info: Windows 10          System Info: AMD64 64bit       |
 -------------------------------------------------------------
[06/15/21 : 15:45:56]  PBC: Read from Registry: LOG_LEVEL = 5
[06/15/21 : 15:45:56]  PBC: Read from Registry: PLAYBACK_MODE_EN = 1
[06/15/21 : 15:45:56]  PBC: Read from Registry: IP_PAIRING_EN = 0
Configs: Errors (1) Warnings (1) NI_Icons (1) NI_Msg (1)
Configs: Playback (1) Log ( 5) Limit (20) IPP (0) exit (1)
Configs: PairMode (Auto) Passcode cache (1) vdiSessionControlEnabled (0)
--------------------------------------------------------------
[06/15/21 : 15:45:56]  PBC: Registered network events handler successfully
[06/15/21 : 15:45:56]  PBC: SESSION SEQUENCE 1
[06/15/21 : 15:45:56]  PBC: Waiting for discovery thread to exit
[06/15/21 : 15:45:56]  PBC: Launching the discovery thread (PairMode: 1)...
[06/15/21 : 15:45:56]  PBC: discovery_server: 1091 Soft_device_state WAITING_FOR_CONNECTION
[06/15/21 : 15:45:56]  PBC: Waiting for IP-Phone Connection(on UDP).....
[06/15/21 : 15:46:11]  PBC: Received packet from 10.231.131.141(len 16)
[06/15/21 : 15:46:11]  PBC: Received packet from 0Xae7838d
[06/15/21 : 15:46:11]  PBC: VVX MAC ID 06:03:01:64:16:7F
[06/15/21 : 15:46:11]  PBC: Received VVX Version from IPP is 6.3.1
[06/15/21 : 15:46:11]  PBC: Received the BToE protocol(2)
[06/15/21 : 15:46:11]  PBC ERR: (discovery_server:1291) Discovery soft device state discovery for proto(2)
[06/15/21 : 15:46:11]  PBC: TLS: creating the context 
[06/15/21 : 15:46:11]  PBC: TLS: succesfully set your CAfile or CApath correctly
[06/15/21 : 15:46:11]  PBC: TLS: TCP connection successful (1408)
[06/15/21 : 15:46:11]  PBC: TLS: doing SSL_connect 
[06/15/21 : 15:46:11]  PBC: TLS: doing SSL_connect done(1) 
[06/15/21 : 15:46:11]  PBC: TLS: connected to VVX successfully
[06/15/21 : 15:46:11]  PBC: setsockopt is success
[06/15/21 : 15:46:11]  PBC: Connected socket's local IP : 1xx.1xx.1x.x
[06/15/21 : 15:46:11]  PBC: Connected socket's local port : 61554
[06/15/21 : 15:46:11]  PBC: Final IP Address : 1xx.1xx.1x.x
[06/15/21 : 15:46:11]  PBC: Adapter Type: 6  Desc : Intel(R) Ethernet Connection (2) I219-LM
[06/15/21 : 15:46:11]  PBC: Adapter ID : {93742432-F5C4-4E65-9CB3-080484E637F5}
[06/15/21 : 15:46:11]  PBC: setConnectedInterface {93742432-F5C4-4E65-9CB3-080484E637F5}
[06/15/21 : 15:46:11]  PBC: TLS: readTLSPacket was successful ret (143)
(<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<response  protocolVersion="1" requestId="2">
<Passcode>Success</Passcode>
</response>
) ..... 
[06/15/21 : 15:46:11]  PBC: Seeking gruu from IPP
[06/15/21 : 15:46:11]  PBC: TLS: readTLSPacket was successful ret (129)
(<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<response  protocolVersion="1" requestId="2">
<Gruu>
</Gruu>
</response>
) ..... 
[06/15/21 : 15:46:11]  PBC ERR: (start_assoc_client: 611) IP Phone not signed in, On-behalf of IP-Phone send sign in request to LC
[06/15/21 : 15:46:11]  PBC: Seeking Media Port from IPP
[06/15/21 : 15:46:11]  PBC: TLS: readTLSPacket was successful ret (143)
(<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<response  protocolVersion="1" requestId="2">
<MediaPort>24802</MediaPort>
</response>
) ..... 
[06/15/21 : 15:46:11]  PBC ERR: (start_assoc_client: 680) Received Media Port from IPP is 24802
[06/15/21 : 15:46:11]  PBC: Notifying PBC Version 4.3.0.0
[06/15/21 : 15:46:11]  PBC: Notifying PC IP Address 1xx.1xx.1x.x
[06/15/21 : 15:46:11]  PBC: Notifying PC Lock status 0
[06/15/21 : 15:46:11]  PBC: Matched the name
[06/15/21 : 15:46:11]  PBC: plugged usb device(03AAEA0C) successfully
[06/15/21 : 15:46:11]  PBC: opened the BToE driver node.....
[06/15/21 : 15:46:11]  PBC: discovery_server: 1548 Soft_device_state ENUMERATING
[06/15/21 : 15:46:11]  PBC: Waiting for audio_render_thread function to initialize.....
[06/15/21 : 15:46:11]  PBC: attach_soft_device thread started
[06/15/21 : 15:46:11]  PBC: btoe_audio_render_playback starting ...
[06/15/21 : 15:46:11]  PBC: Softdevice thread: Recevied gruu:  len 0
[06/15/21 : 15:46:11]  PBC: $$$ Successfully launched BToE Audio Playback thread $$$
[06/15/21 : 15:46:11]  PBC: Not valid gruu
[06/15/21 : 15:46:11]  PBC: btoe_th_link_soft_device: 3273 GRUU_SEND_STATUS NOT_SENT
[06/15/21 : 15:46:11]  PBC: In btoe_read_device_data_and_process:2876
[06/15/21 : 15:46:11]  PBC: Playback Render Thread is Running ............. 320

SteffenBaierUK · ‎06-16-2021

Hello @JamesW7 ,

Welcome back to the Poly community.

Some or a couple of your old post(s) or reply(s) to them => here <= are still open/pending as you have not marked these as "Accept as a solution" or at least provide some form of feedback or answer.

If they are in this state nobody finding them via a community search will know if an answer or advice provided was useful and has maybe helped you.

Could you therefore kindly go over them and mark or answer as appropriate?

If they are marked as "Accept as a solution" other users can find these easier and it helps them to utilize the community more efficiently.

Please do not simply mark them without any type of feedback.

For your new issue, we would most likely need to see a Wireshark trace and the whole log. The latest BToE log and the Phone log are about 6 minutes time difference.

Other volunteers are welcome to comment but official support can only be provided via the well-outlined methods.

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

Best Regards

Steffen Baier

------------------------------------------------
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

SteffenBaierUK · ‎06-16-2021

Hello @JamesW7 ,

I am actually dealing with a customer escalation in my day job so I update this post once I find the other users' issue. Same FW and BToE version as yours. I cannot replicate it in my lab.

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

Best Regards

Steffen Baier

------------------------------------------------
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

JamesW7 · ‎06-22-2021

At least I'm not alone.

Does your lab have the 'SchUseStrongCrypto' key set?

Hive	HKEY_LOCAL_MACHINE
Key path	SOFTWARE\Wow6432Node\Microsoft\.NETFramework\v4.0.30319\
Value name	SchUseStrongCrypto
Value type	REG_DWORD
Value data	0x1 (1)

JamesW7 · ‎06-22-2021

Further testing today revealed that VVX firmware 5.9.0.9373 (SSH only for pairing) works as expected with BtoE 4.4. Firmware 6.4.0.11527 exhibits the same behaviour as 6.3.1.11465.

JamesW7 · ‎07-13-2021

@SteffenBaierUK

Were you able to resolve this escalation?

BToE pairing fails following upgrade to 4.4

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