[GUACAMOLE-1924] Initiating new connections not possible

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Duplicate
• Affects Version/s: 1.5.4
• Component/s: guacd
• Assignee: Unassigned
• Reporter: ETES Support-Team
• Created: 08/Feb/24 15:15
• Updated: 08/Feb/24 15:27
• Resolved: 08/Feb/24 15:27

Description

Hello,

We have a problem in guacamole, with semi-regularly occurring connection issues, across multiple environments. This problem has occurred about every few days since the upgrade to guacamole 1.5.4.

We use the latest EPEL packages for guacamole in all our environments:

Environment 1: 
RHEL 8.9
openssl-1.1.1k-12.el8_9
freerdp-2.2.0-10

Environment 2: 
RHEL 8.9
openssl-1.1.1k-12.el8_9
freerdp-2.2.0-10

Environment 3: 
Centos 7
openssl-1.0.2k-26.el7_9
freerdp-2.1.1-5.el7_9

Environment 4: 
Rocky 9.3
openssl-3.0.7-24.el9
freerdp-2.4.1-5.el9

Guacamole seems to be working fine for multiple days, until suddenly no new connections can be established. This affects all users connecting to any machine defined in guacamole.
Already established connections by users seem to be unaffected, but new connections fail with the following errors:

RDP (RHEL 8.9):

Jan 31 15:24:58 guacd[965849]: User "@b87e8a69-fcac-4be9-830f-ecfa5a2ca8df" joined connection "$28329981-930d-4408-ad08-49188d5c4d68" (1 users now present)
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011primitives autodetect, using optimized
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011freerdp_tcp_is_hostname_resolvable:freerdp_set_last_error_ex resetting error state
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011freerdp_tcp_connect:freerdp_set_last_error_ex resetting error state
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011Protocol Security Negotiation Failure
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011rdp_client_connect:freerdp_set_last_error_ex ERRCONNECT_SECURITY_NEGO_CONNECT_FAILED [0x0002000C]
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011Error: protocol security negotiation or connection failure
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011SVC "rdpdr" disconnected.
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011SVC "rdpsnd" disconnected.
Jan 31 15:24:58 guacd[965849]: guacd[965849]: INFO:#011RDP server closed/refused connection: Security negotiation failed (wrong security type?)
Jan 31 15:24:58 guacd[965849]: RDP server closed/refused connection: Security negotiation failed (wrong security type?)
Jan 31 15:24:58 guacd[965849]: User "@b87e8a69-fcac-4be9-830f-ecfa5a2ca8df" disconnected (0 users remain)
Jan 31 15:24:58 guacd[965849]: Last user of connection "$28329981-930d-4408-ad08-49188d5c4d68" disconnected
Jan 31 15:24:58 guacd[965849]: guacd[965849]: DEBUG:#011Client terminated successfully.
Jan 31 15:24:58 guacd[959]: Connection "$28329981-930d-4408-ad08-49188d5c4d68" removed.
Jan 31 15:24:58 guacd[959]: guacd[959]: INFO:#011Connection "$28329981-930d-4408-ad08-49188d5c4d68" removed.
Jan 31 15:24:58 guacd[959]: guacd[959]: DEBUG:#011Unable to request termination of client process: No such process
Jan 31 15:24:58 guacd[959]: guacd[959]: DEBUG:#011All child processes for connection "$28329981-930d-4408-ad08-49188d5c4d68" have been terminated.

RDP (Rocky 9.3)

Feb 08 10:58:20 guacd[687]: Creating new client for protocol "rdp"
Feb 08 10:58:20 guacd[687]: guacd[687]: INFO:        Creating new client for protocol "rdp"
Feb 08 10:58:20 guacd[687]: Connection ID is "$26b19325-caff-4f1f-982c-59c6bab8b4c7"
Feb 08 10:58:20 guacd[687]: guacd[687]: INFO:        Connection ID is "$26b19325-caff-4f1f-982c-59c6bab8b4c7"
Feb 08 10:58:20 guacd[3631365]: Security mode: Negotiate (ANY)
Feb 08 10:58:20 guacd[3631365]: guacd[3631365]: INFO:        Security mode: Negotiate (ANY)
Feb 08 10:58:20 guacd[3631365]: guacd[3631365]: INFO:        Resize method: display-update
Feb 08 10:58:20 guacd[3631365]: guacd[3631365]: INFO:        Clipboard line ending normalization: Windows (CRLF)
Feb 08 10:58:20 guacd[3631365]: guacd[3631365]: INFO:        User "@ea2d15a5-1e6a-47df-9275-ebcfafa4e8e3" joined connection "$26b19325-caff-4f1f-982c-59c6bab8b4c7" (1 users now present)
Feb 08 10:58:20 guacd[3631365]: Resize method: display-update
Feb 08 10:58:20 guacd[3631365]: Clipboard line ending normalization: Windows (CRLF)
Feb 08 10:58:20 guacd[3631365]: User "@ea2d15a5-1e6a-47df-9275-ebcfafa4e8e3" joined connection "$26b19325-caff-4f1f-982c-59c6bab8b4c7" (1 users now present)
Feb 08 10:58:20 systemd-coredump[3631374]: Process 3631365 (guacd) of user 992 dumped core.

SSH (Centos 7):

Feb 07 11:01:02 guacd[3496]: Creating new client for protocol "ssh"
Feb 07 11:01:02 guacd[3496]: guacd[3496]: INFO:        Creating new client for protocol "ssh"
Feb 07 11:01:02 guacd[3496]: Connection ID is "$1effe6fb-264c-4247-ab25-0663d837305c"
Feb 07 11:01:02 guacd[3496]: guacd[3496]: INFO:        Connection ID is "$1effe6fb-264c-4247-ab25-0663d837305c"
Feb 07 11:01:02 guacd[3496]: GLib (gthread-posix.c): Unexpected error from C library during 'pthread_key_create': Resource temporarily unavailable.  Aborting.
Feb 07 11:01:02 guacd[3496]: Connection "$1effe6fb-264c-4247-ab25-0663d837305c" removed.
Feb 07 11:01:02 guacd[3496]: guacd[3496]: INFO:        Connection "$1effe6fb-264c-4247-ab25-0663d837305c" removed.

The Centos 7 environment stands out, in that both ssh and rdp connections are used there, however so far only ssh-connections were affected by this issue. 
Our other environments only use RDP connections.

What is consistent across all environments however, is that a restart of the guacd service will immediately resolve all issues and new connections will be initiated as expected.

There has been quite a bit of related discussion on the mailing list as well, with users having similar issues in different environments, all on guacamole 1.5.4. See https://lists.apache.org/thread/z8m7y5n0nco0smn1mscdn0fhyxjctrtt

Thank you

Finn, ETES support team

Issue Links

• duplicates: GUACAMOLE-1920 When the cumulative number of user connections reaches a certain amount, guacd will report an error. "RDP server closed/refused connection: Security negotiation failed (wrong security type?)”