helpdavfs2 - Support: sr #108640, Cannot write files larger than...

 
 

sr #108640: Cannot write files larger than 20416 bytes.

Submitted by:  None
Submitted on:  Wed 27 Aug 2014 12:49:12 AM UTC  
 
Category:  None Priority:  5 - Normal
Severity:  3 - Normal Status:  Done
Privacy:  Public Assigned to:  Werner Baumann <wbaumann>
Originator Email:  -email is unavailable- Open/Closed:  Closed
Operating System:  GNU/Linux

Add a New Comment(Rich Markup)
   

You are not logged in

Please log in, so followups can be emailed to you.

 

( Jump to the original submission)

Sun 07 Sep 2014 07:34:07 AM UTC, comment #11:

As long as you have 1.5.1 try calling /sbin/umount.davfs directly instead of calling fusermount -u.

Werner

Werner Baumann <wbaumann>
Project AdministratorIn charge of this item.
Sat 06 Sep 2014 07:45:31 PM UTC, comment #10:

Ok I will try umount once Arch bumps the package to 1.5.2 (I'm still on 1.5.1 with the umount bug). I have notified the maintainers, shouldn't be too long.

Thanks again for your help, and it is good news that the kernel fix will reach us in some time.

Raimar Sandner <raimar>
Sat 06 Sep 2014 04:42:52 PM UTC, comment #9:

Thanks for testing.

The reason why 128 KiB doesn't work is probably that header overhead is added. But 130 KiB shuld be enough and with 135 KiB this workaround is on the sure side.

The other problem:

I would advice to use mount and umount because davfs2 is designed to work with these standard commands. I don't know exactly what fusermount does. Especially I don't know whether fusermount -u will call the umount.davfs helper. The file system type must be davfs, don't use fuse.davfs.

Some background:

When a davfs2 file system is unmounted by the kernel then the fuse kernel module will close the fuse device. This is the way the mount.davfs daemon notices that it is unmounted. It now will start to clean up and try to save all dirty files from the cache to the server. The problem is that this may take an arbitrary long time and this may be not noticed by the user.

Because of this there is the umount.davfs helper. Umount will call this helper when mtab shows file system davfs or when utab shows option helper=davfs. The only purpose of the umount helper is to identify the daemon porcess and to not return until the daemon process has terminated (printing "Waiting until ...").

There have been problems in the past with systems where mtab is a symbolic link to /proc/mounts. But this problems should have gone now with the use of the utab file.

If you use umount you should always see the umount message "waiting ..." and it will only return when the daemon has terminated. If you don't see this message then please check:

  • output of mount: is either the file system type davfs or is the option helper=davfs set?
  • is /etc/mtab a symbolic link or a regular file?
  • if mtab is a symbolic link: is file /var/run/mount/utab present and does it contain a line for the file system and has it option helper=davfs present?

Cheers
Werner

Werner Baumann <wbaumann>
Project AdministratorIn charge of this item.
Sat 06 Sep 2014 02:32:30 PM UTC, comment #8:

With buf_size 128: Now the problem is shifted to a limit of bs=131009 byte (131008 still works), both with dd and cp. Log is attached, to me it looks the same.

With buf_size 135 it kind of works, there is no Input/Output error anymore up to very large blocksizes. However there is a different problem and I don't know if it is related.

When I try to write a large file (say 10M) over my slow connection, dd immediately returns (that's fine, probably because of caching), but also fusermount -u returns immediately. The filesystem is now unmounted, but in a traffic monitor and in the logs I can see that the transfer is still ongoing in the background. Only after a while when the transfer has completed, the file is actually present on the remote side. Because the user is not alerted and the fusermount -u succeeds, it could happen easily that the transfer is interrupted, e.g. laptop put to sleep.

I checked on a different system with kernel 13.15.7, unfortunately also an older version 1.4.7 of davfs2. Here when calling fusermount -u, a message is displayed:

/sbin/umount.davfs: waiting while mount.davfs (pid 9705) synchronizes the cache .. O

I don't know whether the different behaviour comes from davfs 1.4.7 or the buf_size.

Cheers

(file #32039)

Raimar Sandner <raimar>
Sat 06 Sep 2014 08:32:54 AM UTC, comment #7:

You probably noticed from the fuse.devel mailing list that Maxim Patlasov fixed the issue. Of course it will take time for this patch to make it into the kernel release.

To handle the case with Linux kernels that suffer from this bug I have an idea and you might help testing:
As I understand the fuse documentation the maximum size of kernel messages is 128 KiB. In davfs2 you can configure the size of the buffer with option buf_size in davfs2.conf.
If you still have Linux kernel 3.16.1 running could you set buf_size to 128 (or maybe 135) and test with dd and an huge blocksize as well as with cp?

Cheers
Werner

Werner Baumann <wbaumann>
Project AdministratorIn charge of this item.
Sun 31 Aug 2014 11:37:40 AM UTC, comment #6:

Thank you :)

Raimar Sandner <raimar>
Sun 31 Aug 2014 08:22:09 AM UTC, comment #5:

So it definitely looks like a kernel bug. I already sent a report to fuse.devel mailing list (http://news.gmane.org/gmane.comp.file-systems.fuse.devel) and will add your information about kernel versions.

Werner

Werner Baumann <wbaumann>
Project AdministratorIn charge of this item.
Sun 31 Aug 2014 02:25:45 AM UTC, comment #4:

I can confirm Preferred block size is 4096 and max_read is 16384. Using bs=4096 and count=10 works, also for example bs=20417 count=2. cp fails for a file with 20417 bytes. I double-checked, but I'm quite sure the rate limit of journald did not kick in (and we would get a warning about dropped messages if it had).

Currently I am running Arch Linux with kernel 3.16.1, when I temporarily downgrade to 3.15.7 the problem disappears.

If I find the time I will try to bisect the kernel in order to get more information about which commit causes the trouble between 3.15 and 3.16, otherwise I will turn to the FUSE mailing list.

Thanks for your support.

Raimar Sandner <raimar>
Sat 30 Aug 2014 03:50:39 PM UTC, comment #3:

Before starting to debug kernel code you may do this checks first:

  • stat -f on your davfs2 file system will report the preferred block size. It should be 4096.
  • cat /proc/mounts shows the mount options. Option max_read should be 16384.
  • What happens when you use bs=4096 and count=10 with dd?
  • What happens when you use cp to copy a file that is bigger than 20416 byte?

Here are some informations about block and buffer sizes used by davfs2:

  • For read and write operations with the fuse device davfs2 uses a buffer of 17 KiB, which is 20480 Byte (this is the default if you don't change it in davfs2.conf).
  • Because of a bug in old versions of fuse davfs2 reports much lower values to fuse. On mount it sets max_read=16384, on FUSE_INIT it reports max_write=16321 (reduced by header overhead).
  • On FUSE_STAT it reports block size 4096.

And now the funny bit: 20416 bit is exactly the size that is available in the real buffer of davfs2 for write requests from fuse (20480 Byte - 64 Byte of headers). But fuse does not write into this buffer. davfs2 will use this buffer when reading from /dev/fuse. Even if fuse would send a request with more than 20416 Byte of data, davfs2 would only read 20480 Byte and could correctly parse (and log) the headers. The trouble would only occur on the next read. But there is no FUSE_WRITE header in the log.

You might once more check for any restrictions of your log daemon (though your last log file looks fine). There might be restrictions that restrict the number of messages per time for one process. In this case some messages might be missing intermittendly (not at the end). This is just to be sure. I did not see any problems with your last log file.

If your log file is ok, then I would suggest to report this to the fuse mailing list. I have no experience in kernel debugging at all.

Cheers
Werner

Werner Baumann <wbaumann>
Project AdministratorIn charge of this item.
Fri 29 Aug 2014 12:45:47 AM UTC, comment #2:

Thanks for looking at my problem.

You were right about the length restrictions, apparently one has to call journalctl with -a to display also the long entries from the journal.

About the missing messages: probably I didn't allow for enough time to pass after the fusermount -u before I took the journal snapshot.

I uploaded a new log, hopefully everything is there now. Is there a way to make the fuse kernel module more verbose, to see why the FUSE-WRITE is missing?

Best regards

(file #31995)

Raimar Sandner <raimar>
Thu 28 Aug 2014 07:38:22 PM UTC, comment #1:

This looks like a problem with the fuse kernel module.

There is this message:
Aug 27 01:49:42.329177 flock mount.davfs[7562]: SELECT: 1
Aug 27 01:49:42.329426 flock mount.davfs[7562]: READ: Resource temporarily unavailable
When select returns davfs2 tries to read from the fuse device which fails with "temporarily unavailable". This is not a problem as such (temporarily) and the next time reading from the fuse device succeeds.

But then davfs2 gets upcall "FUSE_RELEASE:" which means closing the file. There was not any FUSE-WRITE upcall before closing.

Besides the fuse kernel module the culprit may be some other part of your system that causes fuse to close the connection to davfs2.

There seems also to be a problem with your log daemon. Some log messages are missing and the HTTP request lines are replaced by "[268B blob data]". Maybe there are some restrictions configured regarding the amount of log messages or the length of log messages. For debugging davfs2 you should remove these restriction.

Werner

Werner Baumann <wbaumann>
Project AdministratorIn charge of this item.
Wed 27 Aug 2014 12:49:12 AM UTC, original submission:

Server: Sabre 1.8.10 (owncloud)
Client: davfs2 1.5.1 on Arch Linux

I have set use_locks 0.

This test succeeds:

SIZE=20416
mount /mnt/owncloud
dd if=/dev/zero of=/mnt/owncloud/test.txt bs=$SIZE count=1
sleep 5
fusermount -u /mnt/owncloud

This same test fails for `SIZE=20417` with `dd: error writing ‘/mnt/owncloud/test.txt’: Input/output error`.

I have enabled full debug, the only significant difference I can spot is this for the successfull write:

```
Aug 27 02:22:22 flock mount.davfs[10017]: setattr /owncloud/remote.php/webdav/test.txt
Aug 27 02:22:22 flock mount.davfs[10017]: set size
Aug 27 02:22:22 flock mount.davfs[10017]: RET: Success
Aug 27 02:22:22 flock mount.davfs[10017]: SELECT: 1
Aug 27 02:22:22 flock mount.davfs[10017]: FUSE_FLUSH: ignored
Aug 27 02:22:22 flock mount.davfs[10017]: RET: Success
Aug 27 02:22:22 flock mount.davfs[10017]: SELECT: 1
Aug 27 02:22:22 flock mount.davfs[10017]: FUSE_WRITE:
Aug 27 02:22:22 flock mount.davfs[10017]: n 0xbffa90, fd 6
Aug 27 02:22:22 flock mount.davfs[10017]: pid 10018, flags 02
Aug 27 02:22:22 flock mount.davfs[10017]: size 20416, off 0
Aug 27 02:22:22 flock mount.davfs[10017]: written 20416
Aug 27 02:22:22 flock mount.davfs[10017]: RET: Success
Aug 27 02:22:22 flock mount.davfs[10017]: SELECT: 1
Aug 27 02:22:22 flock mount.davfs[10017]: FUSE_FLUSH: ignored
Aug 27 02:22:22 flock mount.davfs[10017]: RET: Success
Aug 27 02:22:22 flock mount.davfs[10017]: SELECT: 1
Aug 27 02:22:22 flock mount.davfs[10017]: FUSE_RELEASE:
```

Versus the failure:

```
Aug 27 01:49:42.327988 flock mount.davfs[7562]: setattr /owncloud/remote.php/webdav/test.txt
Aug 27 01:49:42.328188 flock mount.davfs[7562]: set size
Aug 27 01:49:42.328391 flock mount.davfs[7562]: RET: Success
Aug 27 01:49:42.328595 flock mount.davfs[7562]: SELECT: 1
Aug 27 01:49:42.328785 flock mount.davfs[7562]: FUSE_FLUSH: ignored
Aug 27 01:49:42.328970 flock mount.davfs[7562]: RET: Success
Aug 27 01:49:42.329177 flock mount.davfs[7562]: SELECT: 1
Aug 27 01:49:42.329426 flock mount.davfs[7562]: READ: Resource temporarily unavailable
Aug 27 01:49:42.329623 flock mount.davfs[7562]: SELECT: 1
Aug 27 01:49:42.329812 flock mount.davfs[7562]: FUSE_FLUSH: ignored
Aug 27 01:49:42.330000 flock mount.davfs[7562]: RET: Success
Aug 27 01:49:42.330709 flock mount.davfs[7562]: SELECT: 1
Aug 27 01:49:42.330720 flock mount.davfs[7562]: FUSE_RELEASE:
```

Please find the full log files attached. I can also provide wireshark logs if this helps.

Anonymous

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #31995:  2014-08-29_02:10:59_flock_failure.log added by raimar (41KiB - text/plain - hopefully complete this time)
file #31969:  2014-08-27_01:49:52_flock_failure.log added by None (36KiB - text/x-log - Log files of a successfull and a failed session.)
file #31970:  2014-08-27_02:22:32_flock_success.log added by None (34KiB - text/x-log - Log files of a successfull and a failed session.)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by raimar (Updated the item)
  • -email is unavailable- added by wbaumann (Posted a comment)
  • -email is unavailable- added by None (Submitted the item)
  •  

    Do you think this task is very important?
    If so, you can add your encouragement to it.
    This task has 0 encouragements so far.

    Only logged-in users can vote.

     

     

     

    Follow 8 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2016-04-15 wbaumann Open/ClosedOpen => Closed
    2014-09-07 wbaumann StatusIn Progress => Done
    2014-09-06 raimar Attached File- => Added 2014-09-06_12:14:07_failure_buf_size_128.log, #32039
    2014-08-29 raimar Attached File- => Added 2014-08-29_02:10:59_flock_failure.log, #31995
    2014-08-28 wbaumann StatusNone => In Progress
        Assigned toNone => wbaumann
    2014-08-27 None Attached File- => Added 2014-08-27_01:49:52_flock_failure.log, #31969
        Attached File- => Added 2014-08-27_02:22:32_flock_success.log, #31970

    Back to the top


    Powered by Savane 3.3