maindavfs2 - Support: sr #108649, Excessive "open files exceed...

 
 

sr #108649: Excessive "open files exceed max cache size by XXX MiBytes" messages

Submitter:  Dale Worley <worley>
Submitted:  Wed 10 Sep 2014 02:33:14 PM UTC
   
 
Category:  None Priority:  5 - Normal
Severity:  1 - Wish Status:  In Progress
Privacy:  Public Assigned to:  _71007
Open/Closed:  Closed Operating System:  GNU/Linux
* Mandatory Fields

Add a New Comment Rich Markup
   

Sun 14 Sep 2014 04:40:52 PM UTC, comment #5: 

"created backup ..."means that the file is moved to lost+found because davfs2 can't upload it to the server.
Once a file is in lost+found it will stay there until you manually remove it. A successful uplaod of a file with the same name does not change this, because davfs2 cannot know whether the files are indentical (to be precise: it would be a lot of code to check this and I think it is better you know there is a problem).

Werner

- <_71007>
Thu 11 Sep 2014 05:34:35 PM UTC, comment #4: 

It looks like it would help me if I increased max_upload_attempts.  It appears that davfs attempted to upload pack-257a6780d5be5a622caedfda0b1d282613743683.pack 15 times, which is the default max_upload_attempts.

Dale Worley <worley>
Thu 11 Sep 2014 04:04:18 PM UTC, comment #3: 

As you suggested, these cached files reflect files in lost+found.  I
though I had a cron job to report files in lost+found, but I used "ls
-l lost+found" instead of "ls -al lost+found", and of course, all the
file names in lost+found start with "."!

(To see the "http" log lines, I've selected the lines returned by
"journalctl" that contain "mount.davfs".)  I see numerous occurrences
of "tidy: neon error" followed by "Could not connect to server: No
route to host" -- which is not surprising :-(.  davfs2 seems to retry
sending files repeatedly, eventually sending the files, as far as I
can tell looking at the log by eye.

Looking at the log lines, the problem seems to be associated with the
log lines starting "created backup of ...".  The problem files all
have "created backup" lines.  For example, "created backup of
0x17cbe90" appears to be associated with
pack-257a6780d5be5a622caedfda0b1d282613743683.pack:

Sep 09 06:15:10 hobgoblin.ariadne.com mount.davfs[6164]: tidy: /dav/Backups/Custom/objects/pack/pack-257a6780d5be5a622caedfda0b1d282613743683.pack
Sep 09 06:15:10 hobgoblin.ariadne.com mount.davfs[6164]: Running pre_send hooks
Sep 09 06:15:10 hobgoblin.ariadne.com mount.davfs[6164]: [315B blob data]
Sep 09 06:15:10 hobgoblin.ariadne.com mount.davfs[6164]: Sending request-line and headers:
Sep 09 06:15:10 hobgoblin.ariadne.com mount.davfs[6164]: req: Connecting to 74.112.185.70:443
Sep 09 06:15:13 hobgoblin.ariadne.com mount.davfs[6164]: req: Connecting to 74.112.184.70:443
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: [91B blob data]
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: Running destroy hooks.
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: Request ends.
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: tidy: neon error
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: Could not connect to server: No route to host
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: new node: 0x16881d0->0x17eb6f0
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: created backup of 0x17cbe90
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: /dav/Backups/Custom/objects/pack/pack-257a6780d5be5a622caedfda0b1d282613743683.pack
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: deleting node 0x17cbe90
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: SELECT: 1
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: FUSE_WRITE 48784: n=0x17b0670
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: u=1000 g=1000 p=13161
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: fh=5, off=70254592, sz=31744
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: wf=0x2, f=0x8002
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: written 31744i
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: RET: Success
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: tidy: 7 of 3997 nodes changed
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: cache-size: 365 MiBytes.
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: resize cache: 365 of 50 MiBytes used.
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: open files exceed max cache size by 315 MiBytes
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: 365 of 50 MiBytes used.
Sep 09 06:15:16 hobgoblin.ariadne.com mount.davfs[6164]: tidy: /dav/Backups/Custom/objects/pack/pack-2ec9da82f63d087a3ef373d8d62a0f30128ba446.idx

What is the significance of "created backup ..."?

Dale Worley <worley>
Thu 11 Sep 2014 02:20:10 PM UTC, comment #2: 

(This was written before I digested comment #1.)

Further information about my situation:

The "ls -alR" of ~/.davfs2 is at the end of this comment.  The cached
files seem to be copies of files named:

pack-257a6780d5be5a622caedfda0b1d282613743683.pack
pack-2ec9da82f63d087a3ef373d8d62a0f30128ba446.idx
pack-2ec9da82f63d087a3ef373d8d62a0f30128ba446.pack
pack-fe73ad0ec75cd71654095110e63fb64c8bc5b161.pack

There are such files that I attempted to copy to the DAV server.  The
sequence of events was:

1. Copy a few dozen files to the server using rsync.

2. The copying of three files failed.  It appears that this was due to
intermittent network connectivity problems.  The davfs mount did not
crash; rsync/davfs recovered and continued copying files.  The files
that failed were named:

pack-257a6780d5be5a622caedfda0b1d282613743683.pack
pack-2ec9da82f63d087a3ef373d8d62a0f30128ba446.idx
pack-2ec9da82f63d087a3ef373d8d62a0f30128ba446.pack

3. Later, re-running rsync, it copied these three files successfully.

4. The directory listing shown below was taken later, but davfs had
not been dismounted and remounted in the interim.

5. The file pack-fe73ad0ec75cd71654095110e63fb64c8bc5b161.pack is
related to an earlier copying operation, which preceded the latest
reboot.

$ ls -alR ~/.davfs2

.davfs2:
total 32
drwx------.   4 worley worley  4096 Jun  6 03:00 .
drwxr-x---. 109 worley worley 12288 Sep 11 09:55 ..
drwx------.   3 worley worley  4096 Jun 18 16:48 cache
drwx------.   3 worley worley  4096 Jan  9  2013 certs
-rw-------.   1 worley worley  2361 Mar  7  2014 davfs2.conf
-rw-------.   1 worley worley  2703 Apr 15 14:06 secrets

.davfs2/cache:
total 104
drwx------. 3 worley worley  4096 Jun 18 16:48 .
drwx------. 4 worley worley  4096 Jun  6 03:00 ..
drwx------. 2 worley davfs2 94208 Sep 11 09:47 dav.box.com-dav+common-home-worley-box.com+worley

.davfs2/cache/dav.box.com-dav+common-home-worley-box.com+worley:
total 178808
drwx------. 2 worley davfs2     94208 Sep 11 09:47 .
drwx------. 3 worley worley      4096 Jun 18 16:48 ..
-rw-------. 1 worley davfs2  79141791 Sep  4 22:08 .pack-257a6780d5be5a622caedfda0b1d282613743683.pack.LrUSsg-DJmGz2
-rw-------. 1 worley davfs2      1100 Sep  7 16:38 .pack-2ec9da82f63d087a3ef373d8d62a0f30128ba446.idx.f3Jkbj-lRMuo5
-rw-------. 1 worley davfs2      3434 Sep  7 16:38 .pack-2ec9da82f63d087a3ef373d8d62a0f30128ba446.pack.40A9um-zkp0J8
-rw-------. 1 worley davfs2 103797615 Aug 30 03:35 .pack-fe73ad0ec75cd71654095110e63fb64c8bc5b161.pack.kNxyP1-tLin1c
-rw-r--r--. 1 worley davfs2     40341 Sep  3 10:24 index

.davfs2/certs:
total 12
drwx------. 3 worley worley 4096 Jan  9  2013 .
drwx------. 4 worley worley 4096 Jun  6 03:00 ..
drwx------. 2 worley worley 4096 Jan  9  2013 private

.davfs2/certs/private:
total 8
drwx------. 2 worley worley 4096 Jan  9  2013 .
drwx------. 3 worley worley 4096 Jan  9  2013 ..

Dale Worley <worley>
Wed 10 Sep 2014 06:27:36 PM UTC, comment #1: 

"If the situation is problematic enough to complain about in /var/log/messages, I would expect the driver to remedy it (e.g., by deleting cached files) once the file system became idle."

This message is written by the function that tries to delete files from the cache. And it is written because it is not possible to delete more files. A file cannot be deleted if

  • it is open
  • it is not yet uploaded to the server. Frequent temporary network or server failures can delay an upload for along time.
  • it is in the lost+found directory. Files get in the lost+found directory when upload fails with an error that indicates permanent failure.


So you should

  • look at your lost+found directory
  • check the debug log for HTTP status codes of PUT requests. Anything other than 200, 201 or 204 indicates a problem with the connection to the server.


Werner

- <_71007>
Wed 10 Sep 2014 02:33:14 PM UTC, original submission:  

(I don't know the significance of this, but it is probably not the desired behavior, so I am reporting it.)

I use davfs2 to communicate with a box.com account, and it works well (modulo network connection problems).  I upload a dozen or so files of size 99 MB.  This appears to cause the davfs driver to report into /var/log/messages:

Sep 10 10:15:19 hobgoblin mount.davfs: open files exceed max cache size by 124 MiBytes

every 30 seconds or so.  It is not surprising that this happens during the file transfer, because I have "debug most" set in davfs2.conf, and a GB of files are being transferred.

However, the messages continue to be generated even after the filesystem has been idle a long time.  It is true that the cache size exceeds 124 MiB, the actual size is around 175 MB.  But this persists long after all files in the filesystem are not being accessed.  (I've confirmed this with fuser.)  If the situation is problematic enough to complain about in /var/log/messages, I would expect the driver to remedy it (e.g., by deleting cached files) once the file system became idle.

Dale Worley <worley>

 

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

Attach Files:
   
   
Comment:
   

No files currently attached

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by _71007 (Posted a comment)
  • -email is unavailable- added by worley (Submitted the item)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only logged-in users can vote.

     

    Follow 3 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2016-04-15 _71007 Open/ClosedOpen Closed
    2014-09-10 _71007 StatusNone In Progress
        Assigned toNone _71007

    Back to the top

    Powered by Savane 3.13-d3ae.
    Corresponding source code