search

neutrinolabs / xrdp

xrdp: an open source RDP server
http://www.xrdp.org/
Apache License 2.0
5.7k stars 1.73k forks source link

xrdp drive redirection: File open refused #2041

Closed saddy001 closed 2 years ago

saddy001 commented 2 years ago

This is xrdp 0.9.16 with guacamole. I found drive redirection within the /home/user/thinclient_drives/GUACFS/Download folder working 99% of the time. However, if it decides to not work, the user must logout and back in to make it work again. To analyze the remaining 1%, I did some tests. Unfortunately I could not reproduce the "permanently failing for a session" bug, but I found another issue that might help fixing the original bug.

Reproduction:

  1. Copy a file from anywhere to /home/user/thinclient_drives/GUACFS/Download (I'm using Python: shutil.copy2(src, dst))
  2. The Firefox file download dialog opens
  3. Now you must be fast: Close the dialog (ESC) within 3 seconds or so
  4. Copy the same file again also within the 3 seconds from above
  5. No new file download dialog appears

Workarounds:

  1. If you wait more than 3 seconds, a new file download dialog appears (as it should)
  2. If you remove the file before copying, it also works (os.unlink(dst))

Logs

When the dialog appears as it should the guacamole log lists the following:

$ /var/log/syslog | grep guacd
Oct 31 12:08:21 guacd[20724]: File open refused (-2): "\Download\file.pdf"
Oct 31 12:08:21 guacd[1879]: guacd[20724]: ERROR:#011File open refused (-2): "\Download\file.pdf"
Oct 31 12:08:21 guacd[1879]: guacd[20724]: ERROR:#011File open refused (-2): "\Download\file.pdf"
Oct 31 12:08:21 guacd[20724]: File open refused (-2): "\Download\file.pdf"
Oct 31 12:08:21 guacd[20724]: File open refused (-2): "\Download\file.pdf"
Oct 31 12:08:21 guacd[1879]: guacd[20724]: ERROR:#011File open refused (-2): "\Download\file.pdf"
Oct 31 12:08:21 guacd[20724]: File open refused (-2): "\Download\file.pdf"
Oct 31 12:08:21 guacd[1879]: guacd[20724]: ERROR:#011File open refused (-2): "\Download\file.pdf"

When it doesn't, it shows:

Oct 31 12:08:24 guacd[20724]: File open refused (-2): "/Download/file.pdf"
Oct 31 12:08:24 guacd[1879]: guacd[20724]: ERROR:#011File open refused (-2): "/Download/file.pdf"

So we have more errors when it works ;-) I guess the refused-errors are somewhat expected because of strange design decisions of FUSE-mount. But maybe we can trace the 1% bug with the 2-log-line situation?

I also did some automated tests. During 1000 test rounds of (login -> download file -> logout -> repeat) the 2-log-line situation does not happen. So it's seems not a "stability" issue but occurs only under certain circumstances.

saddy001 commented 2 years ago

Oh wait I noticed another difference: In the first log above, the folder is "\Download\file.pdf" (with backslashes). In the second log, when it does not work it's "/Download/file.pdf" (slashes).

I also found an old issue mentioning this: https://sourceforge.net/p/guacamole/discussion/1110834/thread/5c97ce09/

saddy001 commented 2 years ago

May be related to #2031

matt335672 commented 2 years ago

Hi @saddy001

Thanks for raising this, and thanks for introducing me to this Guacamole feature. I'd not come across it before.

I've tried to reproduce this and failed. Details on my side:-

I've managed to get the copy command to give me an Input/Output error message after hitting cancel, but after a few seconds the copy always succeeds. I have however managed to get a listing of the download directory which looks like this:-

total 0
-????????? ? ?        ?                 ?            ? pamauth.png

A few questions for you. Can you get the fault to happen, and then try the following:-

Also, are you ignoring any exceptions from your shutil.copy2 call which might be providing more info?

saddy001 commented 2 years ago

To make it more clear than in my first posting, I observed two different issues. Issue A: File download not working at all within a session. Heals itself when starting a new session Issue B: File download not working within 5 seconds after providing a file (copy)

The following is about Issue B For me it's easy to reproducible like the following. This is the file:

$ ls -hla file.txt
-rw-r--r-- 1 user user 12K Dez  4  2020 file.txt

$ file file.txt
file.txt: ASCII text, with very long lines, with no line terminators

Now, within 5 seconds, do all of the following:

$ date; cp file.txt ~/thinclient_drives/GUACFS/Download/
Mo 1. Nov 16:53:07 CET 2021
# it's working (download dialog appears)

$ date; cp file.txt ~/thinclient_drives/GUACFS/Download/
Mo 1. Nov 16:53:09 CET 2021
cp: reguläre Datei '/home/user/thinclient_drives/GUACFS/Download/file.txt' kann nicht angelegt werden: Eingabe-/Ausgabefehler
# it stops working (no download dialog)

$ date; cp file.txt ~/thinclient_drives/GUACFS/Download/
Mo 1. Nov 16:53:11 CET 2021
cp: reguläre Datei '/home/user/thinclient_drives/GUACFS/Download/file.txt' kann nicht angelegt werden: Eingabe-/Ausgabefehler

$ date; cp file.txt ~/thinclient_drives/GUACFS/Download/
Mo 1. Nov 16:53:12 CET 2021
cp: reguläre Datei '/home/user/thinclient_drives/GUACFS/Download/file.txt' kann nicht angelegt werden: Eingabe-/Ausgabefehler

$ date; cp file.txt ~/thinclient_drives/GUACFS/Download/
Mo 1. Nov 16:53:13 CET 2021
# here it's working again after the 5s delay

The same procedure but we look at the folder attributes:

$ date; cp file.txt ~/thinclient_drives/GUACFS/Download/
Mo 1. Nov 16:56:22 CET 2021

$ date; ls -l /home/$USER/thinclient_drives/GUACFS; ls -l /home/$USER/thinclient_drives/GUACFS/Download
Mo 1. Nov 16:56:23 CET 2021
insgesamt 0
drwx------ 1 user user 4096 Nov  1 16:55 Download
insgesamt 0
-rw------- 1 user user  12250 Nov  1 16:56 file.txt
-rw------- 1 user user 188834 Apr  3  2021  ExLBG8aUYAYBIkT.png
-rw------- 1 user user 209150 Apr  3  2021  ExLCk4XVIA4vJ9i.jpeg

$ date; ls -l /home/$USER/thinclient_drives/GUACFS; ls -l /home/$USER/thinclient_drives/GUACFS/Download
Mo 1. Nov 16:56:25 CET 2021
insgesamt 0
drwx------ 1 user user 4096 Nov  1 16:55 Download
insgesamt 0
-rw------- 1 user user  12250 Nov  1 16:56 file.txt
-rw------- 1 user user 188834 Apr  3  2021  ExLBG8aUYAYBIkT.png
-rw------- 1 user user 209150 Apr  3  2021  ExLCk4XVIA4vJ9i.jpeg

$ date; ls -l /home/$USER/thinclient_drives/GUACFS; ls -l /home/$USER/thinclient_drives/GUACFS/Download
Mo 1. Nov 16:56:27 CET 2021
insgesamt 0
drwx------ 1 user user 4096 Nov  1 16:56 Download
ls: Zugriff auf '/home/user/thinclient_drives/GUACFS/Download/file.txt' nicht möglich: Datei oder Verzeichnis nicht gefunden
insgesamt 0
-????????? ? ?         ?              ?            ? file.txt
-rw------- 1 user user 188834 Apr  3  2021  ExLBG8aUYAYBIkT.png
-rw------- 1 user user 209150 Apr  3  2021  ExLCk4XVIA4vJ9i.jpeg

Notice that, when it's working we get -????????? ? ? ? ? ? file.txt. When it doesn't (within the delay), we get "proper" permissions -rw------- 1 user user 12250 Nov 1 16:56 file.txt.

$ ps -fU $USER | grep xrdp
user 22805 22803  0 16:50 ?        00:00:00 /usr/lib/xorg/Xorg :10 -auth .Xauthority -config xrdp/xorg.conf -noreset -nolisten tcp -logfile .xorgxrdp.%s.log
user 22821 22803  0 16:50 ?        00:00:00 /usr/local/sbin/xrdp-chansrv
user 23019 22869  0 16:56 pts/0    00:00:00 grep --color=auto xrdp

As far as I understand, the "????" permissions are expected and indicate that fuse is working correctly: https://unix.stackexchange.com/q/17402 So I guess, fuse needs some time to make the file available and during that time, we cannot process another. And I have the feeling that we cannot do much about this, except the remove-file workaround from above.

Regarding Issue A I read somewhere that this can happen, when the previous session was not properly closed, so that the fuse mount cannot be properly unmounted. So as a workaround I implemented into the blue the following before starting a session:

fusermount -u ~/thinclient_drives > /dev/null 2>&1 || :
rm -rf ~/thinclient_drives
matt335672 commented 2 years ago

Thanks for the clarification @saddy001

I've done a bit more poking around on our side. FUSE is working perfectly well. The cp command results in a call into chansrv, and this is sending an open request for the file to Guacamole.

It seems the open request for the file is being bounced by Guacamole. Rather oddly (on my setup at least), Guacamole is returning STATUS_NO_SUCH_FILE which doesn't make a lot of sense to me. We're turning that into the Unix EIO as a sort of a catch-all error.

If by some chance you are building from source, you can see this by changing this line from a LOG_DEVEL to a LOG:-

https://github.com/neutrinolabs/xrdp/blob/a4c7ee077c049202d73f82f518b2de958d722890/sesman/chansrv/devredir.c#L939

Running with development logging enabled is also an option, but this is really verbose and it slows everything to a crawl.

I don't know what to suggest at this point. I don't think there's anything we can do about in within xrdp itself, as all that is happening is our call is getting bounced by the other end. I think your remove-file workaround may be the best option, if you have control over the Python source.

As regards Issue A, if chansrv doesn't exit cleanly, that's exactly what happens. Your workaround is good for that, but reporting chansrv crashes will help us fix the issue.

Is that a bit helpful?

saddy001 commented 2 years ago

Yes, the workaround is fine for Issue B. As I have a clue what might cause Issue A, I can look out and provide logs next time.