VNC is not working in Euwe (Server disconnected code 1006)


#1

Hi guys,

We just deployed the new Euwe GA release and it looks like VNC is not working anymore when connecting to our VMware VM’s.

I get the following error:
Server disconnected (code: 1006)

Nothing has changed on the VMware vSphere environment. With the Darga release (still running and connected to the same vSphere enviromnent), we are still able to connect to the console of the VM’s.

Used different browsers (Firefox v49, IE11 and Chrome v54). None of te browsers works.

There are no errors in /var/log/manageiq/production.log

Any suggestions? Thanks a lot!


#2

Hi @Taeke,…sorry your having difficulties. Can you provide the evm.log. The evm.log is found here:
/var/www/miq/vmdb/log


#3

Hi John,

Below the relevant part of the evm.log:

[----] I, [2017-01-09T17:03:09.297549 #3221:6ab134]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2017-01-09 16:03:09 UTC]...Complete
[----] I, [2017-01-09T17:03:10.027997 #3221:6ab134]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2017-01-09T17:03:10.454611 #3408:6ab134]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [1000000447187], MiqWorker id: [1000000000848], Zone: [default], Role: [], Server: [be758cce-ccf7-11e6-ab3d-0050569bab2d], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [2.365914085] seconds
[----] I, [2017-01-09T17:03:10.454823 #3408:6ab134]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1000000447187], Delivering...
[----] I, [2017-01-09T17:03:10.496628 #3408:6ab134]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1000000447187], State: [ok], Delivered in [0.041818477] seconds
[----] I, [2017-01-09T17:03:13.892421 #3390:6ab134]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1000000447134], State: [ok], Delivered in [122.930483462] seconds
[----] I, [2017-01-09T17:03:23.095567 #3417:6ab134]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
[----] I, [2017-01-09T17:03:38.099008 #3417:6ab134]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
[----] I, [2017-01-09T17:03:40.752752 #3221:6ab134]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2017-01-09 16:03:40 UTC]...
[----] I, [2017-01-09T17:03:40.761984 #3221:6ab134]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2017-01-09 16:03:40 UTC]...Complete
[----] I, [2017-01-09T17:03:53.102526 #3417:6ab134]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
[----] I, [2017-01-09T17:03:57.017987 #3513:ec4ac8]  INFO -- : MIQ(MiqQueue.put) Message id: [1000000447206],  id: [], Zone: [Zone Amsterdam], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [1000000000022], Task id: [], Command: [ManageIQ::Providers::Vmware::InfraManager::Vm.remote_console_acquire_ticket], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: ["t.boersma@other.local", 1000000000002, :vnc]
[----] I, [2017-01-09T17:03:57.018144 #3513:ec4ac8]  INFO -- : MIQ(MiqTask.generic_action_with_callback) Task: [1000000001073] Queued the action: [acquiring Vm DI9-VM-0010 VNC remote console ticket for user t.boersma@other.local] being run for user: [t.boersma@other.local]
[----] I, [2017-01-09T17:04:08.105969 #3417:6ab134]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2017-01-09T17:04:08.114299 #3417:6ab134]  INFO -- : MIQ(MiqQueue.put) Message id: [1000000447211],  id: [], Zone: [default], Role: [], Server: [be758cce-ccf7-11e6-ab3d-0050569bab2d], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2017-01-09T17:04:12.207126 #3221:6ab134]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2017-01-09 16:04:12 UTC]...
[----] I, [2017-01-09T17:04:12.216916 #3221:6ab134]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2017-01-09 16:04:12 UTC]...Complete
[----] I, [2017-01-09T17:04:12.941387 #3221:6ab134]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2017-01-09T17:04:13.018882 #3399:6ab134]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [1000000447211], MiqWorker id: [1000000000847], Zone: [default], Role: [], Server: [be758cce-ccf7-11e6-ab3d-0050569bab2d], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [4.907616025] seconds
[----] I, [2017-01-09T17:04:13.019079 #3399:6ab134]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1000000447211], Delivering...
[----] I, [2017-01-09T17:04:13.065095 #3399:6ab134]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1000000447211], State: [ok], Delivered in [0.046013165] seconds
[----] I, [2017-01-09T17:04:22.957537 #3221:6ab134]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2017-01-09T17:04:23.077442 #3390:6ab134]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1000000447219], MiqWorker id: [1000000000846], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Job.check_jobs_for_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [0.210060892] seconds
[----] I, [2017-01-09T17:04:23.077667 #3390:6ab134]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1000000447219], Delivering...
[----] I, [2017-01-09T17:04:23.081406 #3390:6ab134]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1000000447219], State: [ok], Delivered in [0.003767294] seconds
[----] I, [2017-01-09T17:04:23.118256 #3417:6ab134]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
[----] I, [2017-01-09T17:04:28.660857 #3221:6ab134]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2017-01-09T17:04:29.108827 #3390:6ab134]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1000000447237], MiqWorker id: [1000000000846], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqTask.destroy], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [[]], Dequeued in: [3.440498773] seconds
[----] I, [2017-01-09T17:04:29.108997 #3390:6ab134]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1000000447237], Delivering...
[----] I, [2017-01-09T17:04:29.109719 #3390:6ab134]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1000000447237], State: [ok], Delivered in [0.00071673] seconds
[----] I, [2017-01-09T17:04:38.121919 #3417:6ab134]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.

#4

I think I looked in the wrong logging. We have multiple MIQ systems (frontend/UI and backend). Below a part of the evm.log logging of the backend system. It looks like a proxy server is started for VNC traffic (see below).

[----] I, [2017-01-10T10:19:30.321794 #16631:b47134]  INFO -- : MIQ(SystemConsole.launch_proxy) Running socat proxy command: /usr/bin/socat TCP-LISTEN:6034,fork TCP:ctesxt-vn102.otaphoenix.local:5933
[----] I, [2017-01-10T10:19:30.338141 #16631:b47134]  INFO -- : MIQ(SystemConsole.launch_proxy_if_not_local) Proxy server started: 10.165.120.143:6034 <--> ctesxt-vn102.otaphoenix.local:5933
[----] I, [2017-01-10T10:19:30.338275 #16631:b47134]  INFO -- : MIQ(SystemConsole.launch_proxy_if_not_local) Proxy process PID: 13479

Based on a TCPdump I made, I notited that no traffic is received on the proxy port on the backend system, when opening the console on the frontend/UI system. The frontend/UI system has IP 10.165.120.32 and the backend system has IP 10.165.120.143.

When debugging in Firefox, it shows me the following error:

Firefox can’t establish a connection to the server at wss://10.165.120.32/ws/console/d8afaa4cdb26d2c425fe1d66c9ac17b6

I would like to upload more logging, however as a new user I am not able to upload logfiles :confused:

Anyone who can give me some guidance, where to look next?


#5

Another piece of the puzzle…

When we connect directly to the the backend system (with Firefox), thus bypassing the frontend system. Everything works!

Issue seems to be on the frontend system or in the communication from frontend to backend