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/>. >>>> >>>> >>>
