Davfs cache behavior

monstruooo
2009-03-13
2013-04-16
<< < 1 2 3 (Page 3 of 3)
  • monstruooo
    monstruooo
    2009-04-04

    Could this be a logging problem?

    open("/var/run/mount.davfs/var-openweb-davfs-0.pid", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 5
    open("/usr/share/locale/en_US.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/share/locale/en_US/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/proc/mounts", O_RDONLY)          = 5

     
  • monstruooo
    monstruooo
    2009-04-04

    I missed these lines too:

    [pid  5552] open("/var/cache/davfs2/webdavserver-openweb+var-openweb-davfs-0+root/index", O_RDONLY|O_LARGEFILE) = 4
    [pid  5552] open("/usr/share/locale/locale.alias", O_RDONLY) = 5
    [pid  5552] open("/usr/share/locale/en_GB/LC_MESSAGES/neon.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
    [pid  5552] open("/usr/share/locale/en/LC_MESSAGES/neon.mo", O_RDONLY) = -1 ENOENT (No such file or directory)

     
  • Werner Baumann
    Werner Baumann
    2009-04-04

    The open calls are all about searching translated messages. The english messages are hard coded and allways available. Logging works even without any translated messages.

    "orphaned files" and "can't create cache" ar log level ERROR.
    "new index files": the exact wording would be helpful. There are ERROR and DEBUG messages about index.

    It seems that your system sends messages of level DEBUG either to /dev/null or somewhere else where you can't find them. You will have to examine the configuration of your syslog daemon and possibly reconfigure it. But I am not familiar with this as I use Debian and don't need to reconfigure syslog.

    Cheers
    Werner

     
  • monstruooo
    monstruooo
    2009-04-04

    I managed to get it logging with debug most. However I saw nothing in particular. There is no messages in between cat and resource unavailable:

    Apr  4 23:31:41 CA1-H mount.davfs: Sending request-line and headers:
    Apr  4 23:31:41 CA1-H mount.davfs: Connecting to 6.6.6.6
    Apr  4 23:31:42 CA1-H mount.davfs: Request ends, status 0 class 0xx, error line: Could not connect to server: Connection refused
    Apr  4 23:31:42 CA1-H mount.davfs: Running destroy hooks.
    Apr  4 23:31:42 CA1-H mount.davfs: Request ends.
    Apr  4 23:31:42 CA1-H mount.davfs: RET: Resource temporarily unavailable
    Apr  4 23:31:49 CA1-H mount.davfs: SELECT: 0
    Apr  4 23:31:49 CA1-H mount.davfs: tidy: 0 of 815 nodes changed
    Apr  4 23:31:49 CA1-H mount.davfs: cache-size: 50 MiBytes.
    Apr  4 23:31:59 CA1-H mount.davfs: SELECT: 0
    Apr  4 23:31:59 CA1-H mount.davfs: tidy: 0 of 815 nodes changed
    Apr  4 23:31:59 CA1-H mount.davfs: cache-size: 50 MiBytes.
    Apr  4 23:31:59 CA1-H mount.davfs: SELECT: 1
    Apr  4 23:31:59 CA1-H mount.davfs: FUSE_LOOKUP:
    Apr  4 23:31:59 CA1-H mount.davfs:   p 0x8f396a8, yes.txt
    Apr  4 23:31:59 CA1-H mount.davfs: lookup /openweb/yes.txt
    Apr  4 23:31:59 CA1-H mount.davfs: RET: Success
    Apr  4 23:31:59 CA1-H mount.davfs: SELECT: 1
    Apr  4 23:31:59 CA1-H mount.davfs: FUSE_OPEN:
    Apr  4 23:31:59 CA1-H mount.davfs:   n 0x8f3ed18, f 0100000
    Apr  4 23:31:59 CA1-H mount.davfs:   pid 11255, mode 00
    Apr  4 23:31:59 CA1-H mount.davfs: open /openweb/yes.txt
    Apr  4 23:31:59 CA1-H mount.davfs: Running pre_send hooks
    Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
    xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
    pr  4 23:31:59 CA1-H mount.davfs:
    Apr  4 23:31:59 CA1-H mount.davfs: Sending request-line and headers:
    Apr  4 23:31:59 CA1-H mount.davfs: Connecting to 6.6.6.6
    Apr  4 23:35:08 CA1-H mount.davfs: Request ends, status 0 class 0xx, error line: Could not connect to server: Connection timed out
    Apr  4 23:35:08 CA1-H mount.davfs: Running destroy hooks.
    Apr  4 23:35:08 CA1-H mount.davfs: Request ends.
    Apr  4 23:35:08 CA1-H mount.davfs: RET: Resource temporarily unavailable
    Apr  4 23:35:08 CA1-H mount.davfs: tidy: 0 of 815 nodes changed
    Apr  4 23:35:08 CA1-H mount.davfs: cache-size: 50 MiBytes.
    Apr  4 23:35:19 CA1-H mount.davfs: SELECT: 0
    Apr  4 23:35:19 CA1-H mount.davfs: tidy: 0 of 815 nodes changed
    Apr  4 23:35:19 CA1-H mount.davfs: cache-size: 50 MiBytes.

     
  • monstruooo
    monstruooo
    2009-04-04

    And this is the beginning of the log:

    Apr  4 23:24:01 CA1-H syslog: syslogd shutdown succeeded
    Apr  4 23:24:58 CA1-H mount.davfs: davfs2 1.3.3
    Apr  4 23:30:49 CA1-H mount.davfs: davfs2 1.3.3
    Apr  4 23:30:49 CA1-H mount.davfs: /sbin/mount.davfs -o rw http://webdavserver/openweb/ /var/openweb/davfs/0
    Apr  4 23:30:49 CA1-H mount.davfs: Configuration:
    Apr  4 23:30:49 CA1-H mount.davfs:   url: http://webdavserver/openweb/
    Apr  4 23:30:49 CA1-H mount.davfs:   mount point: /var/openweb/davfs/0
    Apr  4 23:30:49 CA1-H mount.davfs:   dav_user: root
    Apr  4 23:30:49 CA1-H mount.davfs:   dav_group: root
    Apr  4 23:30:49 CA1-H mount.davfs:   ignore_home: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   conf: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   user: 1
    Apr  4 23:30:49 CA1-H mount.davfs:   netdev: 1
    Apr  4 23:30:49 CA1-H mount.davfs:   mopts: 0xc0ed000e
    Apr  4 23:30:49 CA1-H mount.davfs:   add_mopts: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   kernel_fs: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   buf_size: 0 KiB
    Apr  4 23:30:49 CA1-H mount.davfs:   uid: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   gid: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   dir_umask: 06000
    Apr  4 23:30:49 CA1-H mount.davfs:   file_umask: 06111
    Apr  4 23:30:49 CA1-H mount.davfs:   dir_mode: 040755
    Apr  4 23:30:49 CA1-H mount.davfs:   file_mode: 0100644
    Apr  4 23:30:49 CA1-H mount.davfs:   scheme: http
    Apr  4 23:30:49 CA1-H mount.davfs:   host: webdavserver
    Apr  4 23:30:49 CA1-H mount.davfs:   port: 80
    Apr  4 23:30:49 CA1-H mount.davfs:   path: /openweb/
    Apr  4 23:30:49 CA1-H mount.davfs:   servercert: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   secrets: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   clicert: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   p_host: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   p_port: 8080
    Apr  4 23:30:49 CA1-H mount.davfs:   useproxy: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   askauth: 1
    Apr  4 23:30:49 CA1-H mount.davfs:   displayname: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   locks: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   lock_owner: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   lock_timeout: 1800 s
    Apr  4 23:30:49 CA1-H mount.davfs:   lock_refresh: 60 s
    Apr  4 23:30:49 CA1-H mount.davfs:   expect100: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   if_match_bug: 1
    Apr  4 23:30:49 CA1-H mount.davfs:   drop_weak_etags: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   allow_cookie: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   precheck: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   ignore_dav_header: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   connect_timeout: 10 s
    Apr  4 23:30:49 CA1-H mount.davfs:   read_timeout: 30 s
    Apr  4 23:30:49 CA1-H mount.davfs:   retry: 30 s
    Apr  4 23:30:49 CA1-H mount.davfs:   max_retry: 300 s
    Apr  4 23:30:49 CA1-H mount.davfs:   s_charset: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   header: (null)
    Apr  4 23:30:49 CA1-H mount.davfs:   sys_cache: /var/cache/davfs2
    Apr  4 23:30:49 CA1-H mount.davfs:   cache_dir: /var/cache/davfs2
    Apr  4 23:30:49 CA1-H mount.davfs:   backup_dir: lost+found
    Apr  4 23:30:49 CA1-H mount.davfs:   cache_size: 50 MiB
    Apr  4 23:30:49 CA1-H mount.davfs:   table_size: 1024
    Apr  4 23:30:49 CA1-H mount.davfs:   dir_refresh: 9999 s
    Apr  4 23:30:49 CA1-H mount.davfs:   file_refresh: 1 s
    Apr  4 23:30:49 CA1-H mount.davfs:   delay_upload: 10
    Apr  4 23:30:49 CA1-H mount.davfs:   gui_optimize: 0
    Apr  4 23:30:49 CA1-H mount.davfs:   debug: 0x7
    Apr  4 23:30:49 CA1-H mount.davfs:   neon_debug: 0x3
    Apr  4 23:30:49 CA1-H mount.davfs: mountpoint: /var/openweb/davfs/0
    Apr  4 23:30:49 CA1-H mount.davfs: mounts in: /proc/mounts
    Apr  4 23:30:49 CA1-H mount.davfs: PID file: /var/run/mount.davfs/var-openweb-davfs-0.pid
    Apr  4 23:30:49 CA1-H mount.davfs: changing persona: euid 0, gid 0
    Apr  4 23:30:49 CA1-H mount.davfs: Initializing webdav
    Apr  4 23:30:49 CA1-H mount.davfs: HTTP session to http://webdavserver:80 begins.
    Apr  4 23:30:49 CA1-H mount.davfs: Initializing cache
    Apr  4 23:30:49 CA1-H mount.davfs: Alignment of dav_node: 8
    Apr  4 23:30:49 CA1-H mount.davfs: Checking cache directory
    Apr  4 23:30:49 CA1-H mount.davfs:   /var/cache/davfs2/webdavserver-openweb+var-openweb-davfs-0+root
    Apr  4 23:30:49 CA1-H mount.davfs: new node: (nil)->0x8f396a8
    Apr  4 23:30:49 CA1-H mount.davfs: Reading stored cache data
    Apr  4 23:30:49 CA1-H mount.davfs: new node: 0x8f396a8->0x8f3ed18
    Apr  4 23:30:49 CA1-H mount.davfs: new node: 0x8f396a8->0x8f42f48

     
  • monstruooo
    monstruooo
    2009-04-04

    Oh. This is our redirector. When I tried to configure davfs to go directly for the webdav server, it was ok.

    This is directly from the webdav:
    Capturing on bond0
    23:51:13.530148 192.168.90.12 -> 192.168.200.223 TCP 32850 > http [SYN] Seq=0 Len=0 MSS=1460 WS=2
    23:51:13.597695 192.168.200.223 -> 192.168.90.12 TCP http > 32850 [RST, ACK] Seq=0 Ack=1 Win=0 Len=0
    23:51:14.714209 192.168.90.12 -> 192.168.200.223 TCP 32851 > http [SYN] Seq=0 Len=0 MSS=1460 WS=2
    23:51:14.781536 192.168.200.223 -> 192.168.90.12 TCP http > 32851 [RST, ACK] Seq=0 Ack=1 Win=0 Len=0

    And this is our redirector:

    23:32:08.945590 192.168.90.12 -> 6.6.6.6      TCP 32839 > http [SYN] Seq=0 Len=0 MSS=1460 WS=2
    23:32:08.946164      6.6.6.6 -> 192.168.90.12 TCP http > 32839 [RST, ACK] Seq=0 Ack=0 Win=0 Len=0
    23:32:20.943570 192.168.90.12 -> 6.6.6.6      TCP 32839 > http [SYN] Seq=0 Len=0 MSS=1460 WS=2
    23:32:20.944103      6.6.6.6 -> 192.168.90.12 TCP http > 32839 [RST, ACK] Seq=0 Ack=0 Win=0 Len=0

    Can it be that Ack makes the difference?

     
  • monstruooo
    monstruooo
    2009-04-04

    Sorry man. This is not your fault. This time it's our bug

    Cheers and sorry

     
  • Werner Baumann
    Werner Baumann
    2009-04-05

    I did not notice this wrong ACK=0. Strange enough, in your message of 2009-04-01 12:28 there are some SYN - RST sequences at 15:09:33 with ACK=1.
    I looked up the standard RFC 793, TRANSMISSION CONTROL PROTOCOL. I says in 3.4  Establishing a connection:
    "Reset Processing

      In all states except SYN-SENT, all reset (RST) segments are validated
      by checking their SEQ-fields.  A reset is valid if its sequence number
      is in the window.  In the SYN-SENT state (a RST received in response
      to an initial SYN), the RST is acceptable if the ACK field
      acknowledges the SYN."

    Neon is surely correct to not honour these RST-messages with wrong ACK-number. But I am not clear why it waits 4 minutes before it times out. But I am not familiar with these low level connection handling of neon.

    Cheers
    Werner

     
  • monstruooo
    monstruooo
    2009-04-05

    "I did not notice this wrong ACK=0. Strange enough, in your message of 2009-04-01 12:28 there are some SYN - RST sequences at 15:09:33 with ACK=1. "

    Correct. This is because the redirector does not detect immediately that the webdav is down and so it keeps forwarding packets to the server which replies with normal RSTs.  15-20 seconds later the redirector discovers that the web server is gone, downs the pool and takes on itself the job of resetting incoming connections and it makes a mess of it.

    Cheers

     
  • monstruooo
    monstruooo
    2009-04-05

    As you understand, I am now off to the F5 site to bother them with this bug. Finally you will have some rest from me

    :D  :D

     
  • monstruooo
    monstruooo
    2009-04-05

    However, I am wondering what will happen if there is nobody on the other side to rest connections. davfs will get stuck for five minutes for every request?

     
  • Werner Baumann
    Werner Baumann
    2009-04-05

    "However, I am wondering what will happen if there is nobody on the other side to rest connections. davfs will get stuck for five minutes for every request?"
    No. There are two cases:
    - an ICMP-message "destination unreachable" is received; neon is informed and will return with an error.
    - there is no reply at all; neon will return after the connect_timeout (default 10 seconds).
    There seems to be a special problem with this invalid RST-reply. Seems like the timeout-counter is reset with every such reply.
    But I don't know whether this is an issue of the TCP/IP-stack or of neon.

    Cheers
    Werner

     
  • monstruooo
    monstruooo
    2009-04-05

    "There seems to be a special problem with this invalid RST-reply. Seems like the timeout-counter is reset with every such reply. But I don't know whether this is an issue of the TCP/IP-stack or of neon. "

    Well. Then I think it's all. I still suspect this problem with the cache, but I don't think it's going to affect as in our new configuration davfs is going to be a four threaded application. Both the cache and the load will be divided between four different instances each running on a separate CPU.

    Thanks for your time

     
<< < 1 2 3 (Page 3 of 3)