Guacamole VNC Throws 500 in Sunstone #6244

gbonfiglio · 2023-06-21T15:42:26Z

Description
If FireEdge endpoints are configured in Sunstone, Guacamole is used for VNC access and returns a 500 error. Note Guacamole in FireEdge, and legacy VNC in Sunstone are working as expected.

To Reproduce
Configure FireEdge endpoints in Sunstone:

:private_fireedge_endpoint: http://localhost:2618
:public_fireedge_endpoint: https://[redacted]

Try to open a VM's console - Sunstone will return It appears there was a server exception. Please check server's log. and server side logs will have a line such as:

[17/Jun/2023:08:31:51 +0000] "POST /vm/152/guac/vnc HTTP/1.1" 500 - 0.3126

Expected behavior
Console opens and I can see my VM's screen

Details

Affected Component: Sunstone
Hypervisor: KVM
Version: 6.6

Additional context
I've been unable to fetch more detailed logs, due to lack of familiarity with Sunstone. If there are hints on which debug to enable and where to look to figure this out, I'll be happy to support.

Progress Status

Code committed
Testing - QA
Documentation (Release notes - resolved issues, compatibility, known issues)

The text was updated successfully, but these errors were encountered:

tinova · 2023-06-21T15:51:15Z

let's check the sunstone configuration:

http://localhost:2618/ <--- can you telnet localhost 2618 in your front-end? note that in this case fireedge is expected to be running in a non default port , default is 2616
:public_fireedge_endpoint: https://[redacted] <-- can you reach this in your browser?

do you get any relevant entries in fireedge.{log,err}

gbonfiglio · 2023-06-21T15:56:18Z

Yes, I can use FireEdge no issues (moved to port 2618 since 2616 is the default for staticd). I can also use Guacamole directly in FireEdge no issues, so the problem seems somewhere in Sunstone before I'm even redirected there.

fireedge.error is empty, fireedge.log is a bit hard to read but no new line is added when I trigger the error.

tinova · 2023-06-21T16:00:05Z

"POST /vm/152/guac/vnc HTTP/1.1" 500 - 0.3126

someone is giving this 500 error, if it is not fireedge then is more likely your reverse proxy somehow.

can you try removing it from the equation?

tinova · 2023-06-21T16:02:37Z

closing until we can validate this is a bug, we can continue the conversation here.

gbonfiglio · 2023-06-21T16:06:00Z

I tried to reverse engineer the flow, but when I trigger the error no request is logged in my reverse proxy for the FireEdge hostname. The fact no new lines land in fireedge.log makes me suspect not even a direct request via private_fireedge_endpoint lands there - Sunstone is not invoking FireEdge at all I'd say.

So we know the request goes client -> nginx -> sunstone; Sunstone throws a 500 (I can see it in /var/log/one/sunstone.log). When and why specifically it does so I don't know.

Is there a debug mode I can enable somewhere to figure out what Sunstone does before throwing the 500?

tinova · 2023-06-21T16:08:29Z

you can run sunstone-server.rb from the CLI, this will show exceptions from the server that probably are producing this 500.

For that, check the process using "ps -ef", stop it and run it using "ruby -dw"

gbonfiglio · 2023-06-21T16:11:24Z

Got it, thanks!

Exception `ArgumentError' at /usr/lib/one/sunstone/models/sunstone_guac.rb:236 - key must be 32 bytes
Exception `ArgumentError' at /usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1062 - key must be 32 bytes
2023-06-21 16:10:50 - ArgumentError - key must be 32 bytes:
	/usr/lib/one/sunstone/models/sunstone_guac.rb:236:in `key='
	/usr/lib/one/sunstone/models/sunstone_guac.rb:236:in `encrypt_data'
	/usr/lib/one/sunstone/models/sunstone_guac.rb:85:in `proxy'
	/usr/lib/one/sunstone/models/SunstoneServer.rb:344:in `startguac'
	/usr/lib/one/sunstone/sunstone-server.rb:1215:in `block in <main>'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1691:in `call'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1691:in `block in compile!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1009:in `block (3 levels) in route!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1027:in `route_eval'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1009:in `block (2 levels) in route!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1058:in `block in process_route'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1056:in `catch'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1056:in `process_route'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1007:in `block in route!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1004:in `each'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1004:in `route!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1128:in `block in dispatch!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1099:in `catch'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1099:in `invoke'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1123:in `dispatch!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:939:in `block in call!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1099:in `catch'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1099:in `invoke'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:939:in `call!'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:928:in `call'
	/usr/share/one/gems-dist/gems/rack-2.2.4/lib/rack/common_logger.rb:38:in `call'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:261:in `call'
	/usr/share/one/gems-dist/gems/rack-2.2.4/lib/rack/deflater.rb:44:in `call'
	/usr/share/one/gems-dist/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:266:in `context'
	/usr/share/one/gems-dist/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:260:in `call'
	/usr/share/one/gems-dist/gems/rack-protection-3.0.4/lib/rack/protection/xss_header.rb:20:in `call'
	/usr/share/one/gems-dist/gems/rack-protection-3.0.4/lib/rack/protection/path_traversal.rb:18:in `call'
	/usr/share/one/gems-dist/gems/rack-protection-3.0.4/lib/rack/protection/json_csrf.rb:28:in `call'
	/usr/share/one/gems-dist/gems/rack-protection-3.0.4/lib/rack/protection/base.rb:53:in `call'
	/usr/share/one/gems-dist/gems/rack-protection-3.0.4/lib/rack/protection/base.rb:53:in `call'
	/usr/share/one/gems-dist/gems/rack-protection-3.0.4/lib/rack/protection/frame_options.rb:33:in `call'
	/usr/share/one/gems-dist/gems/rack-2.2.4/lib/rack/null_logger.rb:11:in `call'
	/usr/share/one/gems-dist/gems/rack-2.2.4/lib/rack/head.rb:12:in `call'
	/usr/share/one/gems-dist/gems/rack-2.2.4/lib/rack/method_override.rb:24:in `call'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:219:in `call'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:2002:in `call'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1561:in `block in call'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1777:in `synchronize'
	/usr/share/one/gems-dist/gems/sinatra-3.0.4/lib/sinatra/base.rb:1561:in `call'
	/usr/share/one/gems-dist/gems/thin-1.8.1/lib/thin/connection.rb:86:in `block in pre_process'
	/usr/share/one/gems-dist/gems/thin-1.8.1/lib/thin/connection.rb:84:in `catch'
	/usr/share/one/gems-dist/gems/thin-1.8.1/lib/thin/connection.rb:84:in `pre_process'
	/usr/share/one/gems-dist/gems/thin-1.8.1/lib/thin/connection.rb:50:in `block in process'
	/usr/share/one/gems-dist/gems/eventmachine-1.2.7/lib/eventmachine.rb:1077:in `block in spawn_threadpool'

tinova · 2023-06-22T08:09:22Z

Sunstone it's complaining (not very elegantly, I have to admit) about fireedge_key not containing a proper 32 key.

You can find this file in /var/lib/one/.one, it should be generated by fireedge on first run.

gbonfiglio · 2023-06-22T09:10:08Z

File exists but it's empty, seems to be untouched for years:

root@za:~# stat /var/lib/one/.one/fireedge_key 
  File: /var/lib/one/.one/fireedge_key
  Size: 0         	Blocks: 0          IO Block: 4096   regular empty file
Device: fd00h/64768d	Inode: 534047      Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 9869/oneadmin)   Gid: ( 9869/oneadmin)
Access: 2023-06-21 15:55:01.872623415 +0000
Modify: 2021-05-01 11:41:40.014058237 +0000
Change: 2021-05-01 11:41:40.014058237 +0000
 Birth: 2021-05-01 11:32:31.948179169 +0000

Do you have an hint on how to generate the key? I tried to slap 32 hex bytes in it but I get the same error (openssl rand -hex 32).

tinova · 2023-06-22T11:31:23Z

this file is automatically generated by fireedge , you can delete it and restart fireedge service to recreate it

gbonfiglio · 2023-06-22T12:08:52Z

This worked! Thanks a lot.

Should whatever check you make at startup also validate the file is not empty? I've never fiddled with it so this file has clearly broken at some update or similar. Unfortunately my apt log doesn't go back to 2021 so can't confirm what happened on that day or which version was installed then.

tinova · 2023-06-27T08:44:01Z

Certainly we can add a check, we'll do it as part of the campaign for the new Fireedge Sunstone #5422

gbonfiglio added the Type: Bug label Jun 21, 2023

tinova closed this as completed Jun 21, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Guacamole VNC Throws 500 in Sunstone #6244

Guacamole VNC Throws 500 in Sunstone #6244

gbonfiglio commented Jun 21, 2023

tinova commented Jun 21, 2023

gbonfiglio commented Jun 21, 2023

tinova commented Jun 21, 2023

tinova commented Jun 21, 2023

gbonfiglio commented Jun 21, 2023 •

edited

Loading

tinova commented Jun 21, 2023

gbonfiglio commented Jun 21, 2023 •

edited

Loading

tinova commented Jun 22, 2023

gbonfiglio commented Jun 22, 2023

tinova commented Jun 22, 2023

gbonfiglio commented Jun 22, 2023

tinova commented Jun 27, 2023

Guacamole VNC Throws 500 in Sunstone #6244

Guacamole VNC Throws 500 in Sunstone #6244

Comments

gbonfiglio commented Jun 21, 2023

Progress Status

tinova commented Jun 21, 2023

gbonfiglio commented Jun 21, 2023

tinova commented Jun 21, 2023

tinova commented Jun 21, 2023

gbonfiglio commented Jun 21, 2023 • edited Loading

tinova commented Jun 21, 2023

gbonfiglio commented Jun 21, 2023 • edited Loading

tinova commented Jun 22, 2023

gbonfiglio commented Jun 22, 2023

tinova commented Jun 22, 2023

gbonfiglio commented Jun 22, 2023

tinova commented Jun 27, 2023

gbonfiglio commented Jun 21, 2023 •

edited

Loading

gbonfiglio commented Jun 21, 2023 •

edited

Loading