Hi Shaun, I think the best JIRA issue for this is the one you opened previously:
https://issues.apache.org/jira/browse/GUACAMOLE-1283 I'll be updating that in a bit with the result of my investigation, but overall: - There was a thread-safety issue in FreeRDP that looks to have been intended to be addressed. - It doesn't look like it's 100% addressed in practice. - It's possible for things to work correctly if we add locking on the Guacamole side. Michael Jumper CEO, Lead Developer Glyptodon Inc <https://glyp.to/>. On Thu, Apr 1, 2021 at 5:17 AM Shaun Tarves <[email protected]> wrote: > Hey Mike, > > Checking back in as we pass another week+. Is there any other data I can > gather for you? If there's a Jira issue for this bug, please let me know so > I can track progress. > > - Shaun > > On Wed, Mar 24, 2021 at 12:37 PM Mike Jumper <[email protected]> > wrote: > >> Hi Shaun, >> >> I recently received a report about that "ERRINFO_DECRYPT_FAILED" error a >> few days ago via my day job. I should soon have access to a test RDP >> instance that reproduces the issue reliably. Assuming things are reliably >> reproducible when I start testing on my end, I have hopes I'll be able to >> trace this down. In this case, the issue was encountered while using audio >> input, but from your report I suspect this might be thread-related and may >> occur for just about any virtual channel given the right conditions. >> >> Thanks, >> >> Michael Jumper >> CEO, Lead Developer >> Glyptodon Inc <https://enterprise.glyptodon.com/>. >> >> >> On Wed, Mar 24, 2021 at 9:23 AM Shaun Tarves >> <[email protected]> wrote: >> >>> Hello, >>> >>> It's been 2 weeks now and I haven't seen any response to this. Just a >>> bump to see if there's been any progress made. >>> >>> This is creating some real issues for us as we aren't able to just go >>> into the remote machines and change settings. >>> >>> Thanks again, >>> Shaun >>> >>> On Wed, Mar 10, 2021 at 10:29 AM Shaun Tarves < >>> [email protected]> wrote: >>> >>>> Hi Mike, >>>> >>>> I've spent a lot of time with this issue, and here's a summary of where >>>> I am (long story short, this has never worked with freerdp2). I've tried to >>>> be as thorough as possible, but if there's other data you need/want, let me >>>> know. >>>> >>>> Going through the git history (in chronological order), here's what >>>> I've found: >>>> >>>> *381ff1a* is the last version of guacd on freerdp1 - I've been able to >>>> build a docker image off of this commit and I do NOT experience the issue >>>> moving files from the virtual drive to the physical drive when in >>>> negotiated encryption (which ends up using RDP) mode >>>> >>>> I built this image using: >>>> docker build -t guacd:bisect --build-arg DEBIAN_VERSION=9.8 (as this is >>>> the debian version in the published guacamole/guacd:1.0.0 image) >>>> >>>> >>>> *7b93b3d* is the first version of guacd I could get to build properly >>>> *and* have the virtual drive even show on the remote machine. This >>>> version experiences the issue moving files from the virtual drive to the >>>> physical drive when in negotiated encryption (which ends up using RDP) mode >>>> >>>> I built this image using: >>>> docker build -t guacd:bisect --build-arg DEBIAN_VERSION=10.6 (as this >>>> is the debian version in the published guacamole/guacd:1.1.0 image) >>>> >>>> >>>> There have been some subtle differences in the guacd DEBUG logs around >>>> the failures with 7b93b3d and the tagged 1.1.0 and 1.2.0 images. All of >>>> them kind of look the same, but differ in details, especially around the >>>> connection closing. And every time, the file being transferred from the >>>> virtual drive to the host's physical file system is 50MB. >>>> >>>> >>>> *With guacd 7b93b3d (note extra guac_rdpdr_fs_process_read statements - >>>> almost like it retried after the first failure):* >>>> >>>> guacd[10]: DEBUG: Clipboard data received. Reporting availability of >>>> clipboard data to RDP server. >>>> guacd[10]: DEBUG: guac_rdp_fs_open: path="\tempfile", access=0x120089, >>>> file_attributes=0x0, create_disposition=0x1, create_options=0x200064 >>>> guacd[10]: DEBUG: guac_rdp_fs_open: Normalized path "\tempfile" to >>>> "\tempfile". >>>> guacd[10]: DEBUG: guac_rdp_fs_open: Translated path "\tempfile" to >>>> "/shares/a92552f6-1c43-4459-b338-c506a72a04c5-starves/tempfile". >>>> guacd[10]: DEBUG: guac_rdp_fs_open: native open: >>>> real_path="/shares/a92552f6-1c43-4459-b338-c506a72a04c5-starves/tempfile", >>>> flags=0x0 >>>> guacd[10]: DEBUG: guac_rdp_fs_open: Opened "\tempfile" as file_id=0 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_create: [file_id=0] >>>> desired_access=0x120089, file_attributes=0x0, create_disposition=0x1, >>>> create_options=0x200064, path="\tempfile" >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_query_basic_info: [file_id=0] >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=0] >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=0] >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=0] >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=0 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=52396032 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=32768 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=65536 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=94208, >>>> offset=98304 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=188416, offset=192512 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=376832, offset=380928 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=753664, offset=757760 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=585728, offset=1511424 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=2097152 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=3145728 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=4194304 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=5242880 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=6291456 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=7340032 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=8388608 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=9437184 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=10485760 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=11534336 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=12582912 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=13631488 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=14680064 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=15728640 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=16777216 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=16809984 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=65536, >>>> offset=16842752 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=131072, offset=16908288 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=262144, offset=17039360 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=524288, offset=17301504 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=17825792 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=18874368 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=19922944 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=20971520 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=22020096 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=23068672 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=24117248 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=25165824 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=26214400 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=27262976 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=28311552 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=29360128 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=30408704 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=31457280 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=32505856 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=33554432 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=33587200 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=65536, >>>> offset=33619968 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=131072, offset=33685504 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=262144, offset=33816576 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=524288, offset=34078720 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=34603008 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=35651584 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=36700160 >>>> guacd[10]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=37748736 >>>> [10:22:30:050] [10:14] [ERROR][com.freerdp.core.transport] - >>>> BIO_should_retry returned a system error 104: Connection reset by peer >>>> [10:22:30:051] [10:14] [ERROR][com.freerdp.core.transport] - BIO_read >>>> returned a system error 104: Connection reset by peer >>>> guacd[10]: ERROR: Connection closed. >>>> >>>> >>>> *With guacd 1.1.0 (BIO_read returned a system error 32: Broken pipe):* >>>> >>>> guacd[23]: DEBUG: guac_rdp_fs_open: path="\tempfile", access=0x120089, >>>> file_attributes=0x0, create_disposition=0x1, create_options=0x200064 >>>> guacd[23]: DEBUG: guac_rdp_fs_open: Normalized path "\tempfile" to >>>> "\tempfile". >>>> guacd[23]: DEBUG: guac_rdp_fs_open: Translated path "\tempfile" to >>>> "/shares/a92552f6-1c43-4459-b338-c506a72a04c5-starves/tempfile". >>>> guacd[23]: DEBUG: guac_rdp_fs_open: native open: >>>> real_path="/shares/a92552f6-1c43-4459-b338-c506a72a04c5-starves/tempfile", >>>> flags=0x0 >>>> guacd[23]: DEBUG: guac_rdp_fs_open: Opened "\tempfile" as file_id=1 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_create: [file_id=1] >>>> desired_access=0x120089, file_attributes=0x0, create_disposition=0x1, >>>> create_options=0x200064, path="\tempfile" >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_query_basic_info: [file_id=1] >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=1] >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=1] >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=1] >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] length=32768, >>>> offset=0 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] length=32768, >>>> offset=52396032 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] length=32768, >>>> offset=32768 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] length=32768, >>>> offset=65536 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] length=94208, >>>> offset=98304 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] >>>> length=188416, offset=192512 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] >>>> length=376832, offset=380928 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] >>>> length=753664, offset=757760 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] >>>> length=585728, offset=1511424 >>>> guacd[23]: DEBUG: guac_rdpdr_fs_process_read: [file_id=1] >>>> length=1048576, offset=2097152 >>>> guacd[23]: DEBUG: BIO_should_retry returned a system error 104: >>>> Connection reset by peer >>>> guacd[23]: DEBUG: BIO_should_retry returned a system error 32: Broken >>>> pipe >>>> guacd[23]: DEBUG: ERRINFO_DECRYPT_FAILED (0x00001192):(a) Decryption >>>> using Standard RDP Security mechanisms (section 5.3.6) failed. >>>> (b) Session key creation using Standard RDP Security mechanisms >>>> (section 5.3.5) failed. >>>> guacd[23]: DEBUG: BIO_read returned a system error 32: Broken pipe >>>> guacd[23]: ERROR: Connection closed. >>>> >>>> *With guacd 1.2.0 (BIO_read returned a system error 104: Connection >>>> reset by peer):* >>>> >>>> guacd[11]: DEBUG: guac_rdp_fs_open: path="\tempfile", access=0x120089, >>>> file_attributes=0x0, create_disposition=0x1, create_options=0x200064 >>>> guacd[11]: DEBUG: guac_rdp_fs_open: Normalized path "\tempfile" to >>>> "\tempfile". >>>> guacd[11]: DEBUG: guac_rdp_fs_open: Translated path "\tempfile" to >>>> "/shares/a92552f6-1c43-4459-b338-c506a72a04c5-starves/tempfile". >>>> guacd[11]: DEBUG: guac_rdp_fs_open: native open: >>>> real_path="/shares/a92552f6-1c43-4459-b338-c506a72a04c5-starves/tempfile", >>>> flags=0x0 >>>> guacd[11]: DEBUG: guac_rdp_fs_open: Opened "\tempfile" as file_id=0 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_create: [file_id=0] >>>> desired_access=0x120089, file_attributes=0x0, create_disposition=0x1, >>>> create_options=0x200064, path="\tempfile" >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_query_basic_info: [file_id=0] >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=0] >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=0] >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_query_standard_info: [file_id=0] >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=0 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=52396032 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=32768 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=32768, >>>> offset=65536 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] length=94208, >>>> offset=98304 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=188416, offset=192512 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=376832, offset=380928 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=753664, offset=757760 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=585728, offset=1511424 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=2097152 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=3145728 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=4194304 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=5242880 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=6291456 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=7340032 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=8388608 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=9437184 >>>> guacd[11]: DEBUG: guac_rdpdr_fs_process_read: [file_id=0] >>>> length=1048576, offset=10485760 >>>> guacd[11]: DEBUG: BIO_should_retry returned a system error 104: >>>> Connection reset by peer >>>> guacd[11]: DEBUG: ERRINFO_DECRYPT_FAILED (0x00001192):(a) Decryption >>>> using Standard RDP Security mechanisms (section 5.3.6) failed. >>>> (b) Session key creation using Standard RDP Security mechanisms >>>> (section 5.3.5) failed. >>>> guacd[11]: DEBUG: BIO_read returned a system error 104: Connection >>>> reset by peer >>>> guacd[11]: ERROR: Connection closed. >>>> >>>> >>>> On Fri, Mar 5, 2021 at 1:31 PM Mike Jumper <[email protected]> >>>> wrote: >>>> >>>>> On Fri, Mar 5, 2021 at 6:06 AM Shaun Tarves >>>>> <[email protected]> wrote: >>>>> >>>>>> Hey again Mike, >>>>>> >>>>>> It's been a bit slow for us to get through the myriad commits between >>>>>> 1.0.0 and 1.1.0, ... >>>>>> >>>>> >>>>> git bisect should still search that at roughly O(log n) thanks to its >>>>> binary search through those commits but ... >>>>> >>>>> >>>>>> ... but the most obvious thing that jumps out at me is that you went >>>>>> from freerdp to freerdp2 so that seems like a very likely cause. Should >>>>>> we >>>>>> continue to try to narrow it down or do you want to explore whether this >>>>>> is >>>>>> a freerdp2 issue? >>>>>> >>>>> >>>>> ... I agree that this is the most likely culprit. I suspect you'll end >>>>> up having to tell git bisect to skip a few unbuildable commits, but the >>>>> route forward sounds like: >>>>> >>>>> * Identify a known-good FreeRDP 2.x >>>>> * Identify a known-bad FreeRDP 2.x >>>>> * git bisect between those (hopefully not more than a dozen-ish steps) >>>>> to determine which broke things >>>>> >>>>> As guacamole-server will likely need to be rebuilt for each of those >>>>> tests, scripting the rebuild of both guacamole-server and FreeRDP should >>>>> make this less crazy. >>>>> >>>>> Michael Jumper >>>>> CEO, Lead Developer >>>>> Glyptodon Inc <https://enterprise.glyptodon.com/>. >>>>> >>>>> >>>>
