various improvements, fixing a bug with volumestatus names

* reducing log messages
* reducing traffic on joblist stat

10 files changed, 84 insertions, 30 deletions

diff --git a/bareos/bsock/lowlevel.py b/bareos/bsock/lowlevel.py
index 31a78d4..4838715 100644
--- a/bareos/bsock/lowlevel.py
+++ b/bareos/bsock/lowlevel.py
@@ -114,13 +114,17 @@ class LowLevel(object):
             raise RuntimeError("should connect to director first before recv data")
         msg = ""
         try:
+            timeouts = 0
             while True:
                 # get the message header
                 self.socket.settimeout(0.1)
                 try:
                     header = self.__get_header()
                 except socket.timeout:
-                    self.logger.debug("timeout on receiving header")
+                    # only log every 100 timeouts
+                    if timeouts % 100 == 0:
+                        self.logger.debug("timeout (%i) on receiving header" % (timeouts))
+                    timeouts+=1
                 else:
                     if header <= 0:
                         # header is a signal
diff --git a/bareos/fuse/bareosfuse.py b/bareos/fuse/bareosfuse.py
index c5ae289..b04a253 100644
--- a/bareos/fuse/bareosfuse.py
+++ b/bareos/fuse/bareosfuse.py
@@ -32,7 +32,8 @@ class BareosFuse(fuse.Fuse):
         self.logger.setLevel(logging.DEBUG)
         if hasattr(self, "logfile"):
             hdlr = logging.FileHandler(self.logfile)
-            formatter = logging.Formatter('%(asctime)s  %(levelname)-7s %(module)s %(funcName)s( %(message)s )')
+            # limit message size
+            formatter = logging.Formatter('%(asctime)s  %(levelname)-7s %(module)s %(funcName)s( %(message).800s )')
             hdlr.setFormatter(formatter)
             self.logger.addHandler(hdlr)
 
@@ -77,15 +78,14 @@ class BareosFuse(fuse.Fuse):
         if self.bareos:
             stat = self.bareos.getattr(Path(path))
             if isinstance(stat, fuse.Stat):
-                self.logger.debug("%s: nlink=%i" % (path, stat.st_nlink))
+                self.logger.debug("{path}: dev={stat.st_dev}, ino={stat.st_ino}, mode={stat.st_mode}, nlink={stat.st_nlink}, uid={stat.st_uid}, gid={stat.st_gid}, size={stat.st_size}, atime={stat.st_atime}, ctime={stat.st_ctime}, mtime={stat.st_mtime}".format(path=path, stat=stat))
             else:
                 self.logger.debug("%s: (int) %i" % (path, stat))
             return stat
 
     def read(self, path, size, offset):
         result = self.bareos.read(Path(path), size, offset)
-        #self.logger.debug("%s: %s" % (path, result))
-        self.logger.debug("%s" % (path))
+        self.logger.debug("%s: %s" % (path, result))
         return result
 
     def readdir(self, path, offset):
diff --git a/bareos/fuse/node/base.py b/bareos/fuse/node/base.py
index 3cd8a89..012da3f 100644
--- a/bareos/fuse/node/base.py
+++ b/bareos/fuse/node/base.py
@@ -25,10 +25,13 @@ class Base(object):
         self.content = None
         self.subnodes = {}
         self.subnodes_old = self.subnodes.copy()
+        self.subnode_count = len(self.subnodes)
         self.static = False
         self.lastupdate = None
+        self.lastupdate_stat = None
         # timeout for caching
         self.cache_timeout = timedelta(seconds=60)
+        self.cache_stat_timeout = timedelta(seconds=60)
 
     @classmethod
     def get_id(cls, *args, **kwargs):
@@ -42,13 +45,23 @@ class Base(object):
         """
         return None
 
+    def do_get_name(self, *args, **kwargs):
+        """
+        Get name from init parameter.
+        Normally name is statically set,
+        but for some objects is it based on status data
+        and dependend on where the instance is locationed 
+        in the directory tree (e.g. volumestatus).
+        """
+        return self.name
+
     # Interface
     # =========
 
-    def get_name(self):
-        result = self.name
-        if isinstance(self.name, unicode):
-            result = name.encode('utf-8', 'replace')
+    def get_name(self, *args, **kwargs):
+        result = self.do_get_name(*args, **kwargs)
+        if isinstance(result, unicode):
+            result = result.encode('utf-8', 'replace')
         return result
 
     def set_name(self, name):
@@ -103,13 +116,35 @@ class Base(object):
 
     def add_subnode(self, classtype, *args, **kwargs):
         instance = self.root.factory.get_instance(classtype, *args, **kwargs)
-        name = instance.get_name()
+        name = instance.get_name(*args, **kwargs)
         if not self.subnodes.has_key(name):
             self.subnodes[name] = instance
         else:
             if self.subnodes_old.has_key(name):
                 del(self.subnodes_old[name])
 
+    def update_stat(self):
+        # update status, content, ...
+        now = datetime.now()
+        if self.lastupdate_stat == None:
+            self.logger.debug("reason: first time")
+            self.do_update_stat()
+            self.lastupdate_stat = now
+        elif not self.static and (self.lastupdate_stat + self.cache_stat_timeout) < now:
+            diff = now - self.lastupdate_stat
+            self.logger.debug("reason: non-static and timeout (%d seconds)" % (diff.seconds))
+            self.do_update_stat()
+            self.lastupdate_stat = datetime.now()
+        else:
+            self.logger.debug("skipped (lastupdate: %s, static: %s)" % ( str(self.lastupdate_stat), str(self.static)))
+
+    def do_update_stat(self):
+        """
+        if not overwritten, a full update is performed.
+        Only updating the stat can be more efficient.
+        """
+        self.update()
+
     def update(self):
         # update status, content, ...
         now = datetime.now()
@@ -125,8 +160,9 @@ class Base(object):
             self.subnodes_old = self.subnodes.copy()
             self.do_update()
             for i in self.subnodes_old.keys():
-                self.logger.debug("%s: removing outdated node %s" % (self.get_name(), i))
+                self.logger.debug("removing outdated node %s" % (i))
                 del(self.subnodes[i])
+            self.subnode_count = len(self.subnodes)
             self.lastupdate = datetime.now()
         else:
             self.logger.debug("skipped (lastupdate: %s, static: %s)" % ( str(self.lastupdate), str(self.static)))
@@ -139,6 +175,7 @@ class Base(object):
         # remove marker for nodes to be deleted after update
         self.subnodes_old = {}
 
+
     # Filesystem methods
     # ==================
 
@@ -146,7 +183,7 @@ class Base(object):
         #self.logger.debug("%s(\"%s\")" % (str(self), str(path)))
         result = -errno.ENOENT
         if path.len() == 0:
-            self.update()
+            self.update_stat()
             result = self.get_stat()
         else:
             if path.get(0) in self.subnodes:
@@ -248,7 +285,10 @@ class Base(object):
         unixtimestamp = 0
         try:
             unixtimestamp = int(DateParser.parse(bareosdate).strftime("%s"))
-            self.logger.debug( "unix timestamp: %d" % (unixtimestamp))
+            #self.logger.debug( "unix timestamp: %d" % (unixtimestamp))
         except ValueError:
             pass
+        # could happen because of timezones
+        if unixtimestamp < 0:
+            unixtimestamp = 0
         return unixtimestamp
diff --git a/bareos/fuse/node/bvfscommon.py b/bareos/fuse/node/bvfscommon.py
index adba721..91a5bee 100644
--- a/bareos/fuse/node/bvfscommon.py
+++ b/bareos/fuse/node/bvfscommon.py
@@ -42,7 +42,7 @@ class BvfsCommon(Base):
     # =======
 
     def restore(self, path, pathIds, fileIds):
-        self.logger.debug( "%s: start", self.get_name() )
+        self.logger.debug( "start" )
         bvfs_restore_id = "b20042"
         dirId=''
         if pathIds:
@@ -68,4 +68,4 @@ class BvfsCommon(Base):
         except KeyError:
             self.logger.debug("failed to get resulting jobid of run command (maybe old version of Bareos Director)")
         cleanup = self.bsock.call('.bvfs_cleanup path={bvfs_restore_id}'.format(bvfs_restore_id = bvfs_restore_id))
-        self.logger.debug( "%s: end", self.get_name() )
+        self.logger.debug( "end" )
diff --git a/bareos/fuse/node/bvfsdir.py b/bareos/fuse/node/bvfsdir.py
index ebe61bd..0ead431 100644
--- a/bareos/fuse/node/bvfsdir.py
+++ b/bareos/fuse/node/bvfsdir.py
@@ -52,6 +52,7 @@ class BvfsDir(Directory, BvfsCommon):
                 name = i['name'].rstrip('/')
                 pathid = i['pathid']
                 self.add_subnode(BvfsDir, name, self.job, pathid, i)
+        self.subnode_count = len(self.subnodes)
         if self.directory:
             for i in files:
                 self.add_subnode(BvfsFile, i, self.job, self.directory['fullpath'])
diff --git a/bareos/fuse/node/client.py b/bareos/fuse/node/client.py
index 9da7d03..b4fead1 100644
--- a/bareos/fuse/node/client.py
+++ b/bareos/fuse/node/client.py
@@ -15,5 +15,5 @@ class Client(Directory):
         return name
 
     def do_update(self):
-        self.add_subnode(Backups, "backups", client=self.get_name())
-        self.add_subnode(JobsList, "jobs", "client=%s" % (self.get_name()))
+        self.add_subnode(Backups, "backups", client=self.name)
+        self.add_subnode(JobsList, "jobs", "client=%s" % (self.name))
diff --git a/bareos/fuse/node/directory.py b/bareos/fuse/node/directory.py
index ffa68ee..611933e 100644
--- a/bareos/fuse/node/directory.py
+++ b/bareos/fuse/node/directory.py
@@ -20,7 +20,7 @@ class Directory(Base):
         self.stat.st_size = 4096
 
     def readdir(self, path, offset):
-        self.logger.debug("%s(\"%s\")" % (str(self.get_name()), str(path)))
+        self.logger.debug("%s(\"%s\")" % (str(self.name), str(path)))
         # copy default dirs
         if path.len() == 0:
             self.update()
@@ -32,5 +32,5 @@ class Directory(Base):
         return result
 
     def get_stat(self):
-        self.stat.st_nlink = len(self.defaultdirs) + len(self.subnodes)
+        self.stat.st_nlink = len(self.defaultdirs) + self.subnode_count
         return super(Directory, self).get_stat()
diff --git a/bareos/fuse/node/job.py b/bareos/fuse/node/job.py
index 407afae..c6c3213 100644
--- a/bareos/fuse/node/job.py
+++ b/bareos/fuse/node/job.py
@@ -14,7 +14,7 @@ import stat
 class Job(Directory):
     def __init__(self, root, job):
         self.job = job
-        super(Job, self).__init__(root, self.get_name())
+        super(Job, self).__init__(root, self.get_name(job))
         try:
             if not job.has_key('client'):
                 job['client'] = job['clientname']
@@ -28,24 +28,25 @@ class Job(Directory):
             self.stat.st_mtime = self._convert_date_bareos_unix(self.job['realendtime'])
         except KeyError:
             pass
-        if job['jobstatus'] == 'T' or job['jobstatus'] == 'E' or job['jobstatus'] == 'W':           
+        if job['jobstatus'] == 'T' or job['jobstatus'] == 'E' or job['jobstatus'] == 'W' or job['jobstatus'] == 'f':           
             self.set_static()
 
     @classmethod
     def get_id(cls, job):
         return job['jobid']
 
-    def get_name(self):
+    def do_get_name(self, job):
         try:
-            name = "jobid={jobid}_name={name}_client={client}_level={level}_status={jobstatus}".format(**self.job)
+            name = "jobid={jobid}_name={name}_client={client}_level={level}_status={jobstatus}".format(**job)
         except KeyError:
             try:
-                name = "jobid={jobid}_name={name}_client={clientname}_level={level}_status={jobstatus}".format(**self.job)
+                name = "jobid={jobid}_name={name}_client={clientname}_level={level}_status={jobstatus}".format(**job)
             except KeyError:
-                name = "jobid={jobid}_level={level}_status={jobstatus}".format(**self.job)
+                name = "jobid={jobid}_level={level}_status={jobstatus}".format(**job)
         return name
 
     def do_update(self):
         self.add_subnode(File, name="info.txt", content = pformat(self.job) + "\n")
         self.add_subnode(JobLog, name="job.log", job=self.job)
-        self.add_subnode(BvfsDir, "data", self, None)
+        if self.job['jobstatus'] != 'f':
+            self.add_subnode(BvfsDir, "data", self, None)
diff --git a/bareos/fuse/node/jobslist.py b/bareos/fuse/node/jobslist.py
index 7a4ccf7..38b9188 100644
--- a/bareos/fuse/node/jobslist.py
+++ b/bareos/fuse/node/jobslist.py
@@ -14,6 +14,10 @@ class JobsList(Directory):
     def get_id(cls, name, selector = ''):
         return selector
 
+    def do_update_stat(self):
+        data = self.bsock.call("llist jobs %s count" % (self.selector))
+        self.subnode_count = int(data['jobs'][0]['count'])
+
     def do_update(self):
         data = self.bsock.call("llist jobs %s" % (self.selector))
         jobs = data['jobs']
diff --git a/bareos/fuse/node/volumestatus.py b/bareos/fuse/node/volumestatus.py
index fefc128..bc33dbf 100644
--- a/bareos/fuse/node/volumestatus.py
+++ b/bareos/fuse/node/volumestatus.py
@@ -8,6 +8,7 @@ import stat
 class VolumeStatus(File):
 
     __volstatus2filemode = {
+        "Archive": 0440,
         # rw
         "Append": 0660,
         # ro
@@ -25,20 +26,23 @@ class VolumeStatus(File):
         super(VolumeStatus, self).__init__(root, None, None)
         self.basename = basename
         self.volume = volume
-        self.update_stat()
+        self.do_update_stat()
         self.set_name( "%s%s" % (self.basename, self.volume['volstatus']) )
 
     @classmethod
     def get_id(cls, basename, volume):
         return "%s%s" % (basename, volume['mediaid'])
 
+    def do_get_name(self, basename, volume):
+        return "%s%s" % (basename, volume['volstatus'])
+
     def do_update(self):
         volumename = self.volume['volumename']
         data = self.bsock.call( "llist volume=%s" % (volumename) )
         self.volume = data['volume']
-        self.update_stat()
+        self.do_update_stat()
 
-    def update_stat(self):
+    def do_update_stat(self):
         try:
             self.set_name( "status=%s" % (self.volume['volstatus']) )
             self.stat.st_size = int(self.volume['volbytes'])            
@@ -54,5 +58,5 @@ class VolumeStatus(File):
         if self.__volstatus2filemode.has_key(volstatus):
             self.stat.st_mode = stat.S_IFREG | self.__volstatus2filemode[volstatus]
         else:
-            self.logger.warning( "volume status %s unknown" )
+            self.logger.warning( "volume status %s unknown" % (self.volume['volstatus']) )
             self.stat.st_mode = stat.S_IFREG | 0000