PCoIP Session Unexpectedly Disconnects

cgronewold · ‎09-07-2021

We have a user that has their PCoIP Session randomly disconnected. It happens once a day, give or take, at random times. We have replaced her thin client (10zig) and moved her to a different VM (W10). The issue still persists. Incase it was or is a hardware issue, we also replaced her IP phone (Cisco 7945), all patch cables (wall to phone, phone to 10zig), and moved her to another location so she is not plugged into the same port on the switch... It is only happening to 1 user.. It is happening when she is using the machine. We are running Horizon View 7.

I can see in the logs when the issue starts but cannot narrow down what is causing it. Any help would be appreciated.

021-09-07T08:20:00.094-05:00> LVL:1 RC:-504 MGMT_PCOIP_DATA :Unable to communicate with peer on PCoIP media channels (data manager ping timer expired)
2021-09-07T08:20:00.094-05:00> LVL:2 RC:   0 MGMT_PCOIP_DATA :mgmt_pcoip_data_set_media_activation: URBoIP is not used
2021-09-07T08:20:00.094-05:00> LVL:2 RC:   0          COMMON :SOCKET_TRACE: tera_sock_socket_close() closed socket 2084 - currently 0 sockets.
2021-09-07T08:20:00.094-05:00> LVL:2 RC:   0       MGMT_SSIG :Request to reset session (PRI: 0)
2021-09-07T08:20:00.094-05:00> LVL:2 RC:   0        MGMT_HDA :tera_mgmt_hda_reset: soft_hda_host_reset() called.
2021-09-07T08:20:00.094-05:00> LVL:2 RC:   0        MGMT_HDA :soft_hda_host thread exit
2021-09-07T08:20:00.095-05:00> LVL:2 RC:   0      MGMT_VCHAN :active_processing: Processing EVENT_VCHAN_RESET. [pri = 0]
2021-09-07T08:20:00.095-05:00> LVL:2 RC:   0      MGMT_VCHAN :app_reset: Session has been dropped. Forcing all channels to close!
2021-09-07T08:20:00.095-05:00> LVL:2 RC:   0      MGMT_VCHAN :Calling connect callback 0: event=CONN state=DISCONNECTED (null)
2021-09-07T08:20:00.095-05:00> LVL:1 RC:   0        MGMT_DDC :mgmt_ddc_fcc_callback: queuing TERA_MGMT_FCC_EVENT_RESET [pri=0]
2021-09-07T08:20:00.096-05:00> LVL:2 RC:   0      MGMT_VCHAN :Calling connect callback 1: event=CONN state=DISCONNECTED (null)
2021-09-07T08:20:00.099-05:00> LVL:2 RC:   0      MGMT_VCHAN :mgmt_vchan_transport_callback: queuing MGMT_VCHAN_TRASPORT_EVENT_RESET [pri=0]
2021-09-07T08:20:00.099-05:00> LVL:2 RC:   0      MGMT_VCHAN :reset_pending_processing: Processing EVENT_VCHAN_TRANSPORT_RESET. [pri = 0]
2021-09-07T08:20:01.114-05:00> LVL:2 RC:   0        MGMT_IMG :Image stats: Elapsed session time = 2477.27 seconds
2021-09-07T08:20:01.114-05:00> LVL:2 RC:   0        MGMT_IMG :Image stats [MBits/s]: Total=0.100961 Lossy=0.0165771 Lossless=0.0820489 Build=0.00604644 (Lossy 0.00233472) Cache=0.00939416
2021-09-07T08:20:01.114-05:00> LVL:2 RC:   0        MGMT_IMG :Image stats [MPPS]: Lossy=0.00640314 Txt=0.0426726 Bkgnd=0 Motion=0 TileCache=0.12246 - deprecated - values duplicated below
2021-09-07T08:20:01.114-05:00> LVL:2 RC:   0        MGMT_IMG :Image stats [MPPS]: Changed=0.162042     LS(txt+bkg)=0.0426726     LY(chg)=0.00640314     LY(bld)=0.00260432     LY(LS_res)=0 
2021-09-07T08:20:01.114-05:00> LVL:2 RC:   0        MGMT_IMG :Image stats [MPPS]: Motion=0     zero_offset_tile_cache_hits=0.0869115     offset_tile_cache_hits=0.035549     temporal_cache_hits=0
2021-09-07T08:20:01.114-05:00> LVL:2 RC:   0        MGMT_IMG :Image stats [MPPS]: LY_mec_restart=0.000179424     LY_txt_restart=0
2021-09-07T08:20:01.115-05:00> LVL:0 RC:   0    IMG_FRONTEND :close_displays: reset SVGADevTap.
2021-09-07T08:20:01.137-05:00> LVL:0 RC:   0          EXTERN :svga_devtap ==> svgadevtap: DisplayStop for ID 1, name \\.\DISPLAY1 
2021-09-07T08:20:01.137-05:00> LVL:0 RC:   0          EXTERN :svga_devtap ==> svgadevtap: DisplayStop ID 1 complete 
2021-09-07T08:20:01.137-05:00> LVL:0 RC:   0          EXTERN :svga_devtap ==> svgadevtap: DisplayCleanup ID 1 complete 
2021-09-07T08:20:01.137-05:00> LVL:0 RC:   0          EXTERN :svga_devtap ==> svgadevtap: DisplayStop for ID 2, name \\.\DISPLAY2 
2021-09-07T08:20:01.138-05:00> LVL:0 RC:   0          EXTERN :svga_devtap ==> svgadevtap: DisplayStop ID 2 complete 
2021-09-07T08:20:01.138-05:00> LVL:0 RC:   0          EXTERN :svga_devtap ==> svgadevtap: DisplayCleanup ID 2 complete 
2021-09-07T08:20:01.138-05:00> LVL:2 RC:   0        MGMT_IMG :CODEC: State change from CODEC_CFG_EXCHANGE to CODEC_DISABLED
2021-09-07T08:20:01.138-05:00> LVL:0 RC:   0        MGMT_IMG :mgmt_img_codec_reset: Detected System teardown.
2021-09-07T08:20:01.138-05:00> LVL:2 RC:   0        MGMT_IMG :CODEC: State change from CODEC_DISABLED to CODEC_DISABLED
2021-09-07T08:20:01.138-05:00> LVL:0 RC:   0        MGMT_IMG :mgmt_img_codec_reset: Detected System teardown.
2021-09-07T08:20:01.138-05:00> LVL:1 RC:   0           VGMAC :Stat frms: R=000000/000000/086852  T=005040/052363/027383 (A/I/O) Loss=0.00%/0.00% (R/T)
2021-09-07T08:20:01.138-05:00> LVL:2 RC:   0          COMMON :TERA_PCOIP: SESSION_EVENT=TERA_MGMT_SYS_SESS_EVENT_LOST, disconnect cause (0x0)
2021-09-07T08:20:01.138-05:00> LVL:2 RC:   0          SERVER :server main: cb_notify_session_status called (mask 0x80) with tera_disconnect_cause (0x0)
2021-09-07T08:20:01.138-05:00> LVL:2 RC:   0          SERVER :server main: TERA_MGMT_SYS_SESS_EVENT_LOST.

fabio1975 · ‎09-09-2021

Ciao

PCoIP Logs Explained: "-504 MGMT_PCOIP_DATA Unable to communicate with peer on PCoIP media channels ...

Check if there are any errors in the event viewer where the agent you connect to is installed.
Trivially try to set a ping to the VDI VM and a ping to the thin client to check if you have any packet losses.
Check that you are not using a duplicate IP on the network.

Do you always have the problem of even connecting the client directly to the network without going through the IP Phone?

Fabio

Visit vmvirtual.blog
If you're satisfied give me a kudos

cgronewold · ‎09-09-2021

We have not tried without the ip phone but we have replaced the phone. Everything has been replaced at this point with the exception of the monitors, keyboard, and mouse. Could the monitors cause the issue? If they had issues disconnecting from the machine.

fabio1975 · ‎09-09-2021

CIao

it is not possible that the monitor, mouse or Keyboard create the disconnect problem.
It is more possible that is an agent problem on the VM or network problem. how to suggested the Teradici KB. Do you have errors on the event viewer or Horizon Agent Log on the VDI OS?

Fabio

Visit vmvirtual.blog
If you're satisfied give me a kudos

fabio1975 · ‎09-09-2021

and what is the Horizon version, Horizon Agent Version and teradici Firmware/horizon client version?

Fabio

Visit vmvirtual.blog
If you're satisfied give me a kudos

cgronewold · ‎09-13-2021

Horizon 7.13.0 build - 16962788, Horizon Agent Version 7.13.0-16975066

fabio1975 · ‎09-14-2021

Ciao

What Teradici firmware version do you have on the 10Zig thin client?
Have you then tried disconnecting the phone and using only the thin client?
Do you then find errors in the log on the Horizon Agent?

Fabio

Visit vmvirtual.blog
If you're satisfied give me a kudos

cgronewold · ‎09-14-2021

I am working on figuring out the Teradici firmware version. I am rather new to these and not to versed.

We have not tried completely removing the phone. There is only one port in that office and it is a poe phone. The phone has been replaced along with all of the patch cables. The user has also been moved to a different location.

Yes there were errors in the agent. See below.

2021-09-07T08:20:01.138-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::agent_receiver_callback: message from A:srvr2;B:srvr0002 to A:srvr2, message = 0c 00 00 00, len=16
2021-09-07T08:20:01.152-05:00> LVL:2 RC: 0 AGENT :monitor_soft_hosts: {s_tag:0x2547a547419815f4} MBX_CON_CLOSED
2021-09-07T08:20:01.152-05:00> LVL:2 RC: 0 AGENT :tera_agent_disconnect [soft host]: agent close code: 3, disconnect reason: 0
2021-09-07T08:20:01.152-05:00> LVL:2 RC: 0 AGENT :tera_agent_disconnect: {s_tag:0x2547a547419815f4} disconnect is ** NOT ** pending (hndl: 2, pid: 4048, process handle: 000002e0)
2021-09-07T08:20:01.152-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0x2547a547419815f4} 16 bytes
2021-09-07T08:20:01.392-05:00> LVL:2 RC: 0 AGENT :tera_agent_finish_disconnect_thread: connection_closed 3
2021-09-07T08:20:02.408-05:00> LVL:2 RC: 0 AGENT :mb_send_acknowledgement: {s_tag:0x2547a547419815f4} Sending ack.
2021-09-07T08:20:02.408-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0x2547a547419815f4} 8 bytes
2021-09-07T08:20:02.408-05:00> LVL:1 RC: 38 MAILBOX :cTERA_MAILBOX_SENDER::send_message: Write failed.
2021-09-07T08:20:02.408-05:00> LVL:1 RC:-500 AGENT :mb_send_acknowledgement: {s_tag:0x2547a547419815f4} Failed to write to mailbox srvr0002
2021-09-07T08:20:02.409-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::~sSERVER_SESSION: {s_tag:0x2547a547419815f4} Closing pcoip server process handle 00000000000002E0
2021-09-07T08:20:31.390-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: ==========> New connection request <===========
2021-09-07T08:20:31.390-05:00> LVL:2 RC: 0 AGENT :tera_agent_read_external_udp_address: RegOpenKeyEx could not find the Software\Policies\Teradici\PCoIP\pcoip_admin_defaults key, sending no value to server.
2021-09-07T08:20:31.390-05:00> LVL:2 RC: 0 AGENT :Client address is 0.0.0.0:0 (host order)
2021-09-07T08:20:31.392-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: For Soft Host: Using Version 1 Tag
2021-09-07T08:20:31.392-05:00> LVL:2 RC: 0 PRI :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} Session ID for Soft Host: Tag:'871SMDRSlfUA' Value:f3bd5230345295f5
2021-09-07T08:20:31.392-05:00> LVL:2 RC: 0 AGENT :server_listen_on_addr is 0.0.0.0:0 (host order)
2021-09-07T08:20:31.392-05:00> LVL:1 RC: 0 AGENT :pcoip_agent_connect_req: type = 2
2021-09-07T08:20:31.392-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} Session ID = 3; codec = 2.
2021-09-07T08:20:31.392-05:00> LVL:1 RC: 0 AGENT :pcoip_agent_connect_req: debug trace log 1
2021-09-07T08:20:31.397-05:00> LVL:2 RC: 0 AGENT :tera_agent_launch_server: {s_tag:0xf3bd5230345295f5} Launching pcoip_server_win32
2021-09-07T08:20:31.397-05:00> LVL:2 RC: 0 AGENT :tera_agent_launch_server: {s_tag:0xf3bd5230345295f5} Optional log file path specified as "C:\ProgramData\VMware\VDM\logs\"
2021-09-07T08:20:31.397-05:00> LVL:2 RC: 0 AGENT :tera_agent_launch_server: {s_tag:0xf3bd5230345295f5} use_vmware_launcher = true.
2021-09-07T08:20:31.438-05:00> LVL:2 RC: 0 AGENT :create_session_process: Opened pcoip server process handle 0000000000000824
2021-09-07T08:20:31.438-05:00> LVL:2 RC: 0 AGENT :tera_agent_launch_server: {s_tag:0xf3bd5230345295f5} Using VMWare's launcher code: worked [system is vista or newer, windows session id: 0x1, pid: 0x1ddc, proc handle: 0x824].
2021-09-07T08:20:31.591-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::agent_receiver_callback: message from A:srvr3;B:srvr0003 to A:srvr3, message = 00 00 00 00, len=144
2021-09-07T08:20:32.443-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req : PCoIP Server launch succeeded - 0 attempt retry
2021-09-07T08:20:32.443-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Waiting for ready message.
2021-09-07T08:20:32.563-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Got ready message.
2021-09-07T08:20:32.563-05:00> LVL:2 RC: 0 AGENT :selected server_addr is 0.0.0.0:4172 (host order)
2021-09-07T08:20:32.563-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Connecting to server's mailbox.
2021-09-07T08:20:32.563-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Sending session tag.
2021-09-07T08:20:32.563-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0xf3bd5230345295f5} 136 bytes
2021-09-07T08:20:32.563-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Sending session option #0 key='pcoip.enable_tera2800' value='1'.
2021-09-07T08:20:32.564-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0xf3bd5230345295f5} 48 bytes
2021-09-07T08:20:32.564-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Sending session option #1 key='pcoip.priority_level' value='4'.
2021-09-07T08:20:32.564-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0xf3bd5230345295f5} 47 bytes
2021-09-07T08:20:32.564-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Sending session option #2 key='pcoip.server_fqdn' value='WIN10VM-49.FBTS.local'.
2021-09-07T08:20:32.564-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0xf3bd5230345295f5} 64 bytes
2021-09-07T08:20:32.564-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] End of options: sending null-option message
2021-09-07T08:20:32.564-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0xf3bd5230345295f5} 26 bytes
2021-09-07T08:20:33.064-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::agent_receiver_callback: message from A:srvr3;B:srvr0003 to A:srvr3, message = 05 00 00 00, len=136
2021-09-07T08:20:33.090-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Adding session to list.
2021-09-07T08:20:33.090-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Total number of active sessions = 1
2021-09-07T08:20:33.090-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] Sending connection response ok.
2021-09-07T08:20:33.090-05:00> LVL:2 RC: 0 AGENT :pcoip_agent_connect_req: {s_tag:0xf3bd5230345295f5} [3] connection_response (end), 0
2021-09-07T08:20:34.636-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::agent_receiver_callback: message from A:srvr3;B:srvr0003 to A:srvr3, message = 0b 00 00 00, len=16
2021-09-07T08:20:34.722-05:00> LVL:2 RC: 0 AGENT :monitor_soft_hosts: {s_tag:0xf3bd5230345295f5} MBX_CON_COMPLETE
2021-09-07T08:20:34.722-05:00> LVL:2 RC: 0 AGENT :monitor_soft_hosts: {s_tag:0xf3bd5230345295f5} connection_complete: SOFT - MBX_CON_COMPLETE
2021-09-07T08:20:37.705-05:00> LVL:2 RC: 0 AGENT :monitor_soft_hosts: {s_tag:0xf3bd5230345295f5} monitor thread: connection_complete(MBX_CON_COMPLETE) callback is successful
2021-09-07T08:20:37.706-05:00> LVL:2 RC: 0 AGENT :mb_send_acknowledgement: {s_tag:0xf3bd5230345295f5} Sending ack.
2021-09-07T08:20:37.706-05:00> LVL:2 RC: 0 AGENT :sSERVER_SESSION::send_message: {s_tag:0xf3bd5230345295f5} 8 bytes
2021-09-07T08:20:37.820-05:00> LVL:2 RC: 0 AGENT :mb_send_acknowledgement: {s_tag:0xf3bd5230345295f5} Succeeded to srvr0003

pbarrett1 · ‎04-06-2022

I know this is an older post but just seeing it now. The zero client log kind of tells the issue - Unable to communicate with peer. This is basically a networking issue as communication is lost between the zero client and the host VM.

Only to tell exactly what is going on is to review the entire zero client log file and the pcoip_server_xxxx.txt file located in -

C:\ProgramData\Vmware\VDM\logs

Each time a new session starts there is a new pcoip_server file created. May be difficult to get this log if using instant clones but still key to understanding exactly what is going on.

Right now I suspect an issue with the phone as you probably have QoS set for VoIP and if network gets congested the PCoIP traffic will be treated as scavenger class traffic so may need to set QoS policy for PCoIP. This is very easy to eliminate the phone just use a different direct connection to the core switch and by pass the IP phone.

Paul

All

PCoIP Session Unexpectedly Disconnects

We