]> arthur.barton.de Git - netatalk.git/blobdiff - libatalk/cnid/dbd/cnid_dbd.c
Merge branch-2-1
[netatalk.git] / libatalk / cnid / dbd / cnid_dbd.c
index 085e0cd2e0c633e471f0bbabb6dfbfea4450acd1..990248e45e439a22bc4de87377ae8fbe7e1e95f7 100644 (file)
@@ -1,7 +1,6 @@
 /*
- * $Id: cnid_dbd.c,v 1.4 2005-09-07 15:23:22 didg Exp $
- *
  * Copyright (C) Joerg Lenneis 2003
+ * Copyright (C) Frank Lahm 2010
  * All Rights Reserved.  See COPYING.
  */
 
 #include <arpa/inet.h>
 #include <errno.h>
 #include <netdb.h>
-#include <time.h>    
+#include <time.h>
+
 #include <netatalk/endian.h>
 #include <atalk/logger.h>
 #include <atalk/adouble.h>
 #include <atalk/cnid.h>
-#include "cnid_dbd.h"
 #include <atalk/cnid_dbd_private.h>
+#include <atalk/util.h>
+
+#include "cnid_dbd.h"
 
 #ifndef SOL_TCP
 #define SOL_TCP IPPROTO_TCP
 #endif /* ! SOL_TCP */
 
-static void RQST_RESET(struct cnid_dbd_rqst  *r) 
-{ 
-   memset(r, 0, sizeof(struct cnid_dbd_rqst ));
+/* Wait MAX_DELAY seconds before a request to the CNID server times out */
+#define MAX_DELAY 20
+#define ONE_DELAY 5
+
+static void RQST_RESET(struct cnid_dbd_rqst  *r)
+{
+    memset(r, 0, sizeof(struct cnid_dbd_rqst ));
 }
 
-/* ----------- */
-extern char             Cnid_srv[MAXHOSTNAMELEN + 1];
-extern int              Cnid_port;
+static void delay(int sec)
+{
+    struct timeval tv;
+
+    tv.tv_usec = 0;
+    tv.tv_sec  = sec;
+    select(0, NULL, NULL, NULL, &tv);
+}
 
-static int tsock_getfd(char *host, int port)
+static int tsock_getfd(const char *host, const char *port)
 {
-int sock;
-struct sockaddr_in server;
-struct hostent* hp;
-int attr;
-int err;
-
-    server.sin_family=AF_INET;
-    server.sin_port=htons((unsigned short)port);
-    if (!host) {
-        LOG(log_error, logtype_cnid, "getfd: -cnidserver not defined");
+    int sock = -1;
+    int attr;
+    int err;
+    struct addrinfo hints, *servinfo, *p;
+    int optval;
+    socklen_t optlen = sizeof(optval);
+
+    /* Prepare hint for getaddrinfo */
+    memset(&hints, 0, sizeof hints);
+    hints.ai_family = AF_UNSPEC;
+    hints.ai_socktype = SOCK_STREAM;
+    hints.ai_flags = AI_NUMERICSERV;
+
+    if ((err = getaddrinfo(host, port, &hints, &servinfo)) != 0) {
+        LOG(log_error, logtype_default, "tsock_getfd: getaddrinfo: CNID server %s:%s : %s\n",
+            host, port, gai_strerror(err));
         return -1;
     }
-    
-    hp=gethostbyname(host);
-    if (!hp) {
-       unsigned long int addr=inet_addr(host);
-       LOG(log_warning, logtype_cnid, "getfd: Could not resolve host %s, trying numeric address instead", host);
-        if (addr!= (unsigned)-1)
-            hp=gethostbyaddr((char*)addr,sizeof(addr),AF_INET);
-       if (!hp) {
-           LOG(log_error, logtype_cnid, "getfd: Could not resolve host %s", host);
-           return(-1);
-       }
-    }
-    memcpy((char*)&server.sin_addr,(char*)hp->h_addr,sizeof(server.sin_addr));
-    sock=socket(PF_INET,SOCK_STREAM,0);
-    if (sock==-1) {
-       LOG(log_error, logtype_cnid, "getfd: socket %s: %s", host, strerror(errno));
-       return(-1);
-    }
-    attr = 1;
-    if (setsockopt(sock, SOL_TCP, TCP_NODELAY, &attr, sizeof(attr)) == -1) {
-       LOG(log_error, logtype_cnid, "getfd: set TCP_NODELAY %s: %s", host, strerror(errno));
-       close(sock);
-       return(-1);
-    }
-    if(connect(sock ,(struct sockaddr*)&server,sizeof(server))==-1) {
-        struct timeval tv;
-        err = errno;
-       close(sock);
-       sock=-1;
-       LOG(log_error, logtype_cnid, "getfd: connect %s: %s", host, strerror(err));
-        switch (err) {
-        case ENETUNREACH:
-        case ECONNREFUSED: 
-            
-            tv.tv_usec = 0;
-            tv.tv_sec  = 5;
-            select(0, NULL, NULL, NULL, &tv);
-            break;
+
+    /* loop through all the results and bind to the first we can */
+    for (p = servinfo; p != NULL; p = p->ai_next) {
+        if ((sock = socket(p->ai_family, p->ai_socktype, p->ai_protocol)) == -1) {
+            LOG(log_info, logtype_default, "tsock_getfd: socket CNID server %s:: %s",
+                host, strerror(errno));
+            continue;
         }
+
+        attr = 1;
+        if (setsockopt(sock, SOL_TCP, TCP_NODELAY, &attr, sizeof(attr)) == -1) {
+            LOG(log_error, logtype_cnid, "getfd: set TCP_NODELAY CNID server %s: %s",
+                host, strerror(errno));
+            close(sock);
+            sock = -1;
+            return -1;
+        }
+
+        if (setnonblock(sock, 1) != 0) {
+            LOG(log_error, logtype_cnid, "getfd: setnonblock: %s", strerror(err));
+            close(sock);
+            sock = -1;
+            return -1;
+        }
+
+        if (connect(sock, p->ai_addr, p->ai_addrlen) == -1) {
+            if (errno == EINPROGRESS) {
+                struct timeval tv;
+                tv.tv_usec = 0;
+                tv.tv_sec  = 5; /* give it five seconds ... */
+                fd_set wfds;
+                FD_ZERO(&wfds);
+                FD_SET(sock, &wfds);
+
+                if ((err = select(sock + 1, NULL, &wfds, NULL, &tv)) == 0) {
+                    /* timeout */
+                    LOG(log_error, logtype_cnid, "getfd: select timed out for CNID server %s",
+                        host);
+                    close(sock);
+                    sock = -1;
+                    continue;
+                }
+                if (err == -1) {
+                    /* select failed */
+                    LOG(log_error, logtype_cnid, "getfd: select failed for CNID server %s",
+                        host);
+                    close(sock);
+                    sock = -1;
+                    continue;
+                }
+
+                if ( ! FD_ISSET(sock, &wfds)) {
+                    /* give up */
+                    LOG(log_error, logtype_cnid, "getfd: socket not ready connecting to %s",
+                        host);
+                    close(sock);
+                    sock = -1;
+                    continue;
+                }
+
+                if ((err = getsockopt(sock, SOL_SOCKET, SO_ERROR, &optval, &optlen)) != 0 || optval != 0) {
+                    if (err != 0) {
+                        /* somethings very wrong */
+                        LOG(log_error, logtype_cnid, "getfd: getsockopt error with CNID server %s: %s",
+                            host, strerror(errno));
+                    } else {
+                        errno = optval;
+                        LOG(log_error, logtype_cnid, "getfd: getsockopt says: %s",
+                            strerror(errno));
+                    }
+                    close(sock);
+                    sock = -1;
+                    continue;
+                }
+            } else {
+                LOG(log_error, logtype_cnid, "getfd: connect CNID server %s: %s",
+                    host, strerror(errno));
+                close(sock);
+                sock = -1;
+                continue;
+            }
+        }
+
+        /* We've got a socket */
+        break;
     }
+
+    freeaddrinfo(servinfo);
+
+    if (p == NULL) {
+        errno = optval;
+        LOG(log_error, logtype_cnid, "tsock_getfd: no suitable network config from CNID server (%s:%s): %s",
+            host, port, strerror(errno));
+        return -1;
+    }
+
     return(sock);
 }
 
-/* --------------------- */
-static int write_vec(int fd, struct iovec *iov, size_t towrite)
+/*!
+ * Write "towrite" bytes using writev on non-blocking fd
+ *
+ * Every short write is considered an error, transmit can handle that.
+ *
+ * @param fd      (r) socket fd which must be non-blocking
+ * @param iov     (r) iovec for writev
+ * @param towrite (r) number of bytes in all iovec elements
+ * @param vecs    (r) number of iovecs in array
+ *
+ * @returns "towrite" bytes written or -1 on error
+ */
+static int write_vec(int fd, struct iovec *iov, ssize_t towrite, int vecs)
 {
     ssize_t len;
-    size_t len1;
-    
-    len1 =  iov[1].iov_len;
-    while (towrite > 0) {
-        if (((len = writev(fd, iov, 2)) == -1 && errno == EINTR) || !len)
+    int slept = 0;
+    int sleepsecs;
+
+    while (1) {
+        if (((len = writev(fd, iov, vecs)) == -1 && errno == EINTR))
+            continue;
+
+        if ((! slept) && len == -1 && errno == EAGAIN) {
+            sleepsecs = 2;
+            while ((sleepsecs = sleep(sleepsecs)));
+            slept = 1;
             continue;
-        if ((size_t)len == towrite) /* wrote everything out */
-            break;
-        else if (len < 0) { /* error */
-            return -1;
-        }
-        towrite -= len;
-        if (towrite > len1) { /* skip part of header */
-            iov[0].iov_base = (char *) iov[0].iov_base + len;
-            iov[0].iov_len -= len;
-        } else { /* skip to data */
-            if (iov[0].iov_len) {
-                len -= iov[0].iov_len;
-                iov[0].iov_len = 0;
-            }
-            iov[1].iov_base = (char *) iov[1].iov_base + len;
-            iov[1].iov_len -= len;
         }
+
+        if (len == towrite) /* wrote everything out */
+            break;
+
+        if (len == -1)
+            LOG(log_error, logtype_cnid, "write_vec: %s", strerror(errno));
+        else
+            LOG(log_error, logtype_cnid, "write_vec: short write: %d", len);
+        return len;
     }
-    return 0;
+
+    LOG(log_maxdebug, logtype_cnid, "write_vec: wrote %d bytes", len);
+
+    return len;
 }
 
 /* --------------------- */
@@ -152,8 +234,11 @@ static int init_tsock(CNID_private *db)
     int fd;
     int len;
     struct iovec iov[2];
-    
-    if ((fd = tsock_getfd(Cnid_srv, Cnid_port)) < 0) 
+
+    LOG(log_debug, logtype_cnid, "init_tsock: BEGIN. Opening volume '%s', CNID Server: %s/%s",
+        db->db_dir, db->cnidserver, db->cnidport);
+
+    if ((fd = tsock_getfd(db->cnidserver, db->cnidport)) < 0)
         return -1;
 
     len = strlen(db->db_dir);
@@ -164,46 +249,43 @@ static int init_tsock(CNID_private *db)
     iov[1].iov_base = db->db_dir;
     iov[1].iov_len  = len;
 
-    if (write_vec(fd, iov, len + sizeof(int)) < 0) {
+    if (write_vec(fd, iov, len + sizeof(int), 2) != len + sizeof(int)) {
         LOG(log_error, logtype_cnid, "init_tsock: Error/short write: %s", strerror(errno));
         close(fd);
         return -1;
     }
+
+    LOG(log_debug, logtype_cnid, "init_tsock: ok");
+
     return fd;
 }
 
 /* --------------------- */
-static int send_packet(CNID_private *db, struct cnid_dbd_rqst *rqst, int silent)
+static int send_packet(CNID_private *db, struct cnid_dbd_rqst *rqst)
 {
     struct iovec iov[2];
     size_t towrite;
-  
-    
-    if (!rqst->namelen) {
-        if (write(db->fd, rqst, sizeof(struct cnid_dbd_rqst)) != sizeof(struct cnid_dbd_rqst)) {
-           if (!silent)
-               LOG(log_warning, logtype_cnid, "send_packet: Error/short write rqst (db_dir %s): %s", 
-                   db->db_dir, strerror(errno));
-            return -1;
-        }
-        return 0;
-    }
+    int vecs;
 
     iov[0].iov_base = rqst;
     iov[0].iov_len  = sizeof(struct cnid_dbd_rqst);
+    towrite = sizeof(struct cnid_dbd_rqst);
+    vecs = 1;
 
-    iov[1].iov_base = rqst->name;
-    iov[1].iov_len  = rqst->namelen;
-
-    towrite = sizeof(struct cnid_dbd_rqst) +rqst->namelen;
+    if (rqst->namelen) {
+        iov[1].iov_base = rqst->name;
+        iov[1].iov_len  = rqst->namelen;
+        towrite += rqst->namelen;
+        vecs++;
+    }
 
-    if (write_vec(db->fd, iov, towrite) < 0) {
-       if (!silent)
-           LOG(log_warning, logtype_cnid, "send_packet: Error writev rqst (db_dir %s): %s", 
-                     db->db_dir, strerror(errno));
-       return -1;            
+    if (write_vec(db->fd, iov, towrite, vecs) != towrite) {
+        LOG(log_warning, logtype_cnid, "send_packet: Error writev rqst (db_dir %s): %s",
+            db->db_dir, strerror(errno));
+        return -1;
     }
 
+    LOG(log_maxdebug, logtype_cnid, "send_packet: {done}");
     return 0;
 }
 
@@ -230,145 +312,125 @@ static int dbd_reply_stamp(struct cnid_dbd_rply *rply)
     return 0;
 }
 
-/* --------------------- 
+/* ---------------------
  * send a request and get reply
  * assume send is non blocking
  * if no answer after sometime (at least MAX_DELAY secondes) return an error
-*/
-#define MAX_DELAY 40
-static int dbd_rpc(CNID_private *db, struct cnid_dbd_rqst *rqst, struct cnid_dbd_rply *rply, int silent)
+ */
+static int dbd_rpc(CNID_private *db, struct cnid_dbd_rqst *rqst, struct cnid_dbd_rply *rply)
 {
     ssize_t ret;
     char *nametmp;
-    struct timeval tv;
-    fd_set readfds;
-    int    maxfd;
     size_t len;
 
-    if (send_packet(db, rqst, silent) < 0) {
+    if (send_packet(db, rqst) < 0) {
         return -1;
     }
-    FD_ZERO(&readfds);
-    FD_SET(db->fd, &readfds);
-    maxfd = db->fd +1;
-        
-    tv.tv_usec = 0;
-    tv.tv_sec  = MAX_DELAY;
-    while ((ret = select(maxfd + 1, &readfds, NULL, NULL, &tv)) < 0 && errno == EINTR);
-
-    if (ret < 0) {
-       if (!silent)
-           LOG(log_error, logtype_cnid, "dbd_rpc: Error in select (db_dir %s): %s",
-               db->db_dir, strerror(errno));
-        return ret;
-    }
-    /* signal ? */
-    if (!ret) {
-        /* no answer */
-       if (!silent)
-           LOG(log_error, logtype_cnid, "dbd_rpc: select timed out (db_dir %s)",
-               db->db_dir);
-        return -1;
-    }
-
     len = rply->namelen;
     nametmp = rply->name;
-    /* assume that if we have something then everything is there (doesn't sleep) */ 
-    if ((ret = read(db->fd, rply, sizeof(struct cnid_dbd_rply))) != sizeof(struct cnid_dbd_rply)) {
-       if (!silent)
-           LOG(log_error, logtype_cnid, "dbd_rpc: Error reading header from fd (db_dir %s): %s",
-                db->db_dir, ret == -1?strerror(errno):"closed");
+
+    ret = readt(db->fd, rply, sizeof(struct cnid_dbd_rply), 0, ONE_DELAY);
+
+    if (ret != sizeof(struct cnid_dbd_rply)) {
+        LOG(log_error, logtype_cnid, "dbd_rpc: Error reading header from fd (db_dir %s): %s",
+            db->db_dir, ret == -1 ? strerror(errno) : "closed");
         rply->name = nametmp;
         return -1;
     }
     rply->name = nametmp;
     if (rply->namelen && rply->namelen > len) {
-       if (!silent)
-            LOG(log_error, logtype_cnid, 
-                 "dbd_rpc: Error reading name (db_dir %s): %s name too long wanted %d only %d, garbage?",
-                 db->db_dir, rply->namelen, len);
+        LOG(log_error, logtype_cnid,
+            "dbd_rpc: Error reading name (db_dir %s): %s name too long: %d. only wanted %d, garbage?",
+            db->db_dir, rply->name, rply->namelen, len);
         return -1;
     }
-    if (rply->namelen && (ret = read(db->fd, rply->name, rply->namelen)) != (ssize_t)rply->namelen) {
-       if (!silent)
-            LOG(log_error, logtype_cnid, "dbd_rpc: Error reading name from fd (db_dir %s): %s",
-                db->db_dir, ret == -1?strerror(errno):"closed");
+    if (rply->namelen && (ret = readt(db->fd, rply->name, rply->namelen, 0, ONE_DELAY)) != (ssize_t)rply->namelen) {
+        LOG(log_error, logtype_cnid, "dbd_rpc: Error reading name from fd (db_dir %s): %s",
+            db->db_dir, ret == -1?strerror(errno):"closed");
         return -1;
     }
+
+    LOG(log_maxdebug, logtype_cnid, "dbd_rpc: {done}");
+
     return 0;
 }
 
 /* -------------------- */
 static int transmit(CNID_private *db, struct cnid_dbd_rqst *rqst, struct cnid_dbd_rply *rply)
 {
-    struct timeval tv;
     time_t orig, t;
-    int silent = 1;
-    
+    int clean = 1; /* no errors so far - to prevent sleep on first try */
+
     if (db->changed) {
         /* volume and db don't have the same timestamp
-        */
+         */
         return -1;
     }
-    time(&orig);
     while (1) {
-
         if (db->fd == -1) {
             struct cnid_dbd_rqst rqst_stamp;
             struct cnid_dbd_rply rply_stamp;
             char  stamp[ADEDLEN_PRIVSYN];
-                
+
+            LOG(log_maxdebug, logtype_cnid, "transmit: connecting to cnid_dbd ...");
             if ((db->fd = init_tsock(db)) < 0) {
-                time(&t);
-                if (t - orig > MAX_DELAY)
-                    return -1;
-               continue;
+                goto transmit_fail;
             }
             dbd_initstamp(&rqst_stamp);
             memset(stamp, 0, ADEDLEN_PRIVSYN);
             rply_stamp.name = stamp;
             rply_stamp.namelen = ADEDLEN_PRIVSYN;
 
-            if (dbd_rpc(db, &rqst_stamp, &rply_stamp, silent) < 0)
+            if (dbd_rpc(db, &rqst_stamp, &rply_stamp) < 0)
                 goto transmit_fail;
             if (dbd_reply_stamp(&rply_stamp ) < 0)
                 goto transmit_fail;
-            
+
             if (db->notfirst) {
-               if (memcmp(stamp, db->stamp, ADEDLEN_PRIVSYN)) {
-                    LOG(log_error, logtype_cnid, "transmit: not the same db!");
-                   db->changed = 1;
-                   return -1;
-               }
-            }
-            else {
+                LOG(log_debug7, logtype_cnid, "transmit: reconnected to cnid_dbd, comparing database stamps...");
+                if (memcmp(stamp, db->stamp, ADEDLEN_PRIVSYN)) {
+                    LOG(log_error, logtype_cnid, "transmit: ... not the same db!");
+                    db->changed = 1;
+                    return -1;
+                }
+                LOG(log_debug7, logtype_cnid, "transmit: ... OK.");
+            } else { /* db->notfirst == 0 */
                 db->notfirst = 1;
-                if (db->client_stamp) {
-                   memcpy(db->client_stamp, stamp, ADEDLEN_PRIVSYN);
-               }
-               memcpy(db->stamp, stamp, ADEDLEN_PRIVSYN);
+                if (db->client_stamp)
+                    memcpy(db->client_stamp, stamp, ADEDLEN_PRIVSYN);
+                memcpy(db->stamp, stamp, ADEDLEN_PRIVSYN);
             }
+            LOG(log_debug, logtype_cnid, "transmit: attached to '%s', stamp: '%08lx'.",
+                db->db_dir, *(uint64_t *)stamp);
         }
-        if (!dbd_rpc(db, rqst, rply, silent)) {
+        if (!dbd_rpc(db, rqst, rply)) {
+            LOG(log_maxdebug, logtype_cnid, "transmit: {done}");
             return 0;
-       }
-transmit_fail:
-       silent = 0; /* From now on dbd_rpc and subroutines called from there
-                       will log messages if something goes wrong again */
+        }
+    transmit_fail:
         if (db->fd != -1) {
             close(db->fd);
+            db->fd = -1; /* FD not valid... will need to reconnect */
         }
-        time(&t);
-        if (t - orig > MAX_DELAY) {
-           LOG(log_error, logtype_cnid, "transmit: Request to dbd daemon (db_dir %s) timed out.", db->db_dir);
+
+        if (errno == ECONNREFUSED) { /* errno carefully injected in tsock_getfd */
+            /* give up */
+            LOG(log_error, logtype_cnid, "transmit: connection refused (db_dir %s)", db->db_dir);
             return -1;
-       }
+        }
 
-        /* sleep a little before retry */
-        db->fd = -1;
-        tv.tv_usec = 0;
-        tv.tv_sec  = 5;
-        select(0, NULL, NULL, NULL, &tv);
+        if (!clean) { /* don't sleep if just got disconnected by cnid server */
+            time(&t);
+            if (t - orig > MAX_DELAY) {
+                LOG(log_error, logtype_cnid, "transmit: Request to dbd daemon (db_dir %s) timed out.", db->db_dir);
+                return -1;
+            }
+            /* sleep a little before retry */
+            delay(1);
+        } else {
+            clean = 0; /* false... next time sleep */
+            time(&orig);
+        }
     }
     return -1;
 }
@@ -377,73 +439,76 @@ transmit_fail:
 static struct _cnid_db *cnid_dbd_new(const char *volpath)
 {
     struct _cnid_db *cdb;
-    
+
     if ((cdb = (struct _cnid_db *)calloc(1, sizeof(struct _cnid_db))) == NULL)
-       return NULL;
-       
+        return NULL;
+
     if ((cdb->volpath = strdup(volpath)) == NULL) {
         free(cdb);
-       return NULL;
+        return NULL;
     }
-    
+
     cdb->flags = CNID_FLAG_PERSISTENT | CNID_FLAG_LAZY_INIT;
-    
+
     cdb->cnid_add = cnid_dbd_add;
     cdb->cnid_delete = cnid_dbd_delete;
     cdb->cnid_get = cnid_dbd_get;
     cdb->cnid_lookup = cnid_dbd_lookup;
+    cdb->cnid_find = cnid_dbd_find;
     cdb->cnid_nextid = NULL;
     cdb->cnid_resolve = cnid_dbd_resolve;
     cdb->cnid_getstamp = cnid_dbd_getstamp;
     cdb->cnid_update = cnid_dbd_update;
     cdb->cnid_rebuild_add = cnid_dbd_rebuild_add;
     cdb->cnid_close = cnid_dbd_close;
-    
+
     return cdb;
 }
 
 /* ---------------------- */
-struct _cnid_db *cnid_dbd_open(const char *dir, mode_t mask _U_)
+struct _cnid_db *cnid_dbd_open(struct cnid_open_args *args)
 {
     CNID_private *db = NULL;
     struct _cnid_db *cdb = NULL;
 
-    if (!dir) {
-         return NULL;
+    if (!args->dir) {
+        return NULL;
     }
-    
-    if ((cdb = cnid_dbd_new(dir)) == NULL) {
-        LOG(log_error, logtype_default, "cnid_open: Unable to allocate memory for database");
-       return NULL;
+
+    if ((cdb = cnid_dbd_new(args->dir)) == NULL) {
+        LOG(log_error, logtype_cnid, "cnid_open: Unable to allocate memory for database");
+        return NULL;
     }
-        
+
     if ((db = (CNID_private *)calloc(1, sizeof(CNID_private))) == NULL) {
         LOG(log_error, logtype_cnid, "cnid_open: Unable to allocate memory for database");
         goto cnid_dbd_open_fail;
     }
-    
+
     cdb->_private = db;
 
     /* We keep a copy of the directory in the db structure so that we can
        transparently reconnect later. */
-    strcpy(db->db_dir, dir);
+    strcpy(db->db_dir, args->dir);
     db->magic = CNID_DB_MAGIC;
     db->fd = -1;
-#ifdef DEBUG
-    LOG(log_info, logtype_cnid, "opening database connection to %s", db->db_dir); 
-#endif
+    db->cnidserver = strdup(args->cnidserver);
+    db->cnidport = strdup(args->cnidport);
+
+    LOG(log_debug, logtype_cnid, "cnid_dbd_open: Finished initializing cnid dbd module for volume '%s'", db->db_dir);
+
     return cdb;
 
 cnid_dbd_open_fail:
     if (cdb != NULL) {
-       if (cdb->volpath != NULL) {
-           free(cdb->volpath);
-       }
-       free(cdb);
+        if (cdb->volpath != NULL) {
+            free(cdb->volpath);
+        }
+        free(cdb);
     }
     if (db != NULL)
-       free(db);
-       
+        free(db);
+
     return NULL;
 }
 
@@ -453,29 +518,28 @@ void cnid_dbd_close(struct _cnid_db *cdb)
     CNID_private *db;
 
     if (!cdb) {
-        LOG(log_error, logtype_afpd, "cnid_close called with NULL argument !");
-       return;
+        LOG(log_error, logtype_cnid, "cnid_close called with NULL argument !");
+        return;
     }
 
     if ((db = cdb->_private) != NULL) {
-#ifdef DEBUG 
-        LOG(log_info, logtype_cnid, "closing database connection to %s", db->db_dir);
-#endif  
-       if (db->fd >= 0)
-           close(db->fd);
+        LOG(log_debug, logtype_cnid, "closing database connection for volume '%s'", db->db_dir);
+
+        if (db->fd >= 0)
+            close(db->fd);
         free(db);
     }
-    
+
     free(cdb->volpath);
     free(cdb);
-    
+
     return;
 }
 
 /* ---------------------- */
 cnid_t cnid_dbd_add(struct _cnid_db *cdb, const struct stat *st,
-                const cnid_t did, char *name, const size_t len,
-                cnid_t hint _U_)
+                    const cnid_t did, char *name, const size_t len,
+                    cnid_t hint)
 {
     CNID_private *db;
     struct cnid_dbd_rqst rqst;
@@ -503,19 +567,24 @@ cnid_t cnid_dbd_add(struct _cnid_db *cdb, const struct stat *st,
 
     rqst.ino = st->st_ino;
     rqst.type = S_ISDIR(st->st_mode)?1:0;
+    rqst.cnid = hint;
     rqst.did = did;
     rqst.name = name;
     rqst.namelen = len;
 
+    LOG(log_debug, logtype_cnid, "cnid_dbd_add: CNID: %u, name: '%s', inode: 0x%llx, type: %d (0=file, 1=dir)",
+        ntohl(did), name, (long long)st->st_ino, rqst.type);
+
     rply.namelen = 0;
     if (transmit(db, &rqst, &rply) < 0) {
         errno = CNID_ERR_DB;
         return CNID_INVALID;
     }
-    
+
     switch(rply.result) {
     case CNID_DBD_RES_OK:
         id = rply.cnid;
+        LOG(log_debug, logtype_cnid, "cnid_dbd_add: got CNID: %u", ntohl(id));
         break;
     case CNID_DBD_RES_ERR_MAX:
         errno = CNID_ERR_MAX;
@@ -529,6 +598,7 @@ cnid_t cnid_dbd_add(struct _cnid_db *cdb, const struct stat *st,
     default:
         abort();
     }
+
     return id;
 }
 
@@ -540,19 +610,20 @@ cnid_t cnid_dbd_get(struct _cnid_db *cdb, const cnid_t did, char *name, const si
     struct cnid_dbd_rply rply;
     cnid_t id;
 
-
     if (!cdb || !(db = cdb->_private) || !name) {
-        LOG(log_error, logtype_cnid, "cnid_get: Parameter error");
-        errno = CNID_ERR_PARAM;        
+        LOG(log_error, logtype_cnid, "cnid_dbd_get: Parameter error");
+        errno = CNID_ERR_PARAM;
         return CNID_INVALID;
     }
 
     if (len > MAXPATHLEN) {
-        LOG(log_error, logtype_cnid, "cnid_add: Path name is too long");
+        LOG(log_error, logtype_cnid, "cnid_dbd_get: Path name is too long");
         errno = CNID_ERR_PATH;
         return CNID_INVALID;
     }
 
+    LOG(log_debug, logtype_cnid, "cnid_dbd_get: DID: %u, name: '%s'", ntohl(did), name);
+
     RQST_RESET(&rqst);
     rqst.op = CNID_DBD_OP_GET;
     rqst.did = did;
@@ -564,10 +635,11 @@ cnid_t cnid_dbd_get(struct _cnid_db *cdb, const cnid_t did, char *name, const si
         errno = CNID_ERR_DB;
         return CNID_INVALID;
     }
-    
+
     switch(rply.result) {
     case CNID_DBD_RES_OK:
         id = rply.cnid;
+        LOG(log_debug, logtype_cnid, "cnid_dbd_get: got CNID: %u", ntohl(id));
         break;
     case CNID_DBD_RES_NOTFOUND:
         id = CNID_INVALID;
@@ -576,7 +648,7 @@ cnid_t cnid_dbd_get(struct _cnid_db *cdb, const cnid_t did, char *name, const si
         id = CNID_INVALID;
         errno = CNID_ERR_DB;
         break;
-    default: 
+    default:
         abort();
     }
 
@@ -593,10 +665,12 @@ char *cnid_dbd_resolve(struct _cnid_db *cdb, cnid_t *id, void *buffer, size_t le
 
     if (!cdb || !(db = cdb->_private) || !id || !(*id)) {
         LOG(log_error, logtype_cnid, "cnid_resolve: Parameter error");
-        errno = CNID_ERR_PARAM;                
+        errno = CNID_ERR_PARAM;
         return NULL;
     }
 
+    LOG(log_debug, logtype_cnid, "cnid_dbd_resolve: resolving CNID: %u", ntohl(*id));
+
     /* TODO: We should maybe also check len. At the moment we rely on the caller
        to provide a buffer that is large enough for MAXPATHLEN plus
        CNID_HEADER_LEN plus 1 byte, which is large enough for the maximum that
@@ -606,11 +680,9 @@ char *cnid_dbd_resolve(struct _cnid_db *cdb, cnid_t *id, void *buffer, size_t le
     rqst.op = CNID_DBD_OP_RESOLVE;
     rqst.cnid = *id;
 
-    /* This mimicks the behaviour of the "regular" cnid_resolve. So far,
-       nobody uses the content of buffer. It only provides space for the
-       name in the caller. */
-    rply.name = (char *)buffer + CNID_HEADER_LEN;
-    rply.namelen = len - CNID_HEADER_LEN;
+    /* Pass buffer to transmit so it can stuff the reply data there */
+    rply.name = (char *)buffer;
+    rply.namelen = len;
 
     if (transmit(db, &rqst, &rply) < 0) {
         errno = CNID_ERR_DB;
@@ -621,7 +693,8 @@ char *cnid_dbd_resolve(struct _cnid_db *cdb, cnid_t *id, void *buffer, size_t le
     switch (rply.result) {
     case CNID_DBD_RES_OK:
         *id = rply.did;
-        name = rply.name;
+        name = rply.name + CNID_NAME_OFS;
+        LOG(log_debug, logtype_cnid, "cnid_dbd_resolve: resolved did: %u, name: '%s'", ntohl(*id), name);
         break;
     case CNID_DBD_RES_NOTFOUND:
         *id = CNID_INVALID;
@@ -646,7 +719,7 @@ int cnid_dbd_getstamp(struct _cnid_db *cdb, void *buffer, const size_t len)
 
     if (!cdb || !(db = cdb->_private) || len != ADEDLEN_PRIVSYN) {
         LOG(log_error, logtype_cnid, "cnid_getstamp: Parameter error");
-        errno = CNID_ERR_PARAM;                
+        errno = CNID_ERR_PARAM;
         return -1;
     }
     db->client_stamp = buffer;
@@ -657,7 +730,7 @@ int cnid_dbd_getstamp(struct _cnid_db *cdb, void *buffer, const size_t len)
 
 /* ---------------------- */
 cnid_t cnid_dbd_lookup(struct _cnid_db *cdb, const struct stat *st, const cnid_t did,
-                   char *name, const size_t len)
+                       char *name, const size_t len)
 {
     CNID_private *db;
     struct cnid_dbd_rqst rqst;
@@ -666,7 +739,7 @@ cnid_t cnid_dbd_lookup(struct _cnid_db *cdb, const struct stat *st, const cnid_t
 
     if (!cdb || !(db = cdb->_private) || !st || !name) {
         LOG(log_error, logtype_cnid, "cnid_lookup: Parameter error");
-        errno = CNID_ERR_PARAM;        
+        errno = CNID_ERR_PARAM;
         return CNID_INVALID;
     }
 
@@ -689,6 +762,9 @@ cnid_t cnid_dbd_lookup(struct _cnid_db *cdb, const struct stat *st, const cnid_t
     rqst.name = name;
     rqst.namelen = len;
 
+    LOG(log_debug, logtype_cnid, "cnid_dbd_lookup: CNID: %u, name: '%s', inode: 0x%llx, type: %d (0=file, 1=dir)",
+        ntohl(did), name, (long long)st->st_ino, rqst.type);
+
     rply.namelen = 0;
     if (transmit(db, &rqst, &rply) < 0) {
         errno = CNID_ERR_DB;
@@ -698,6 +774,7 @@ cnid_t cnid_dbd_lookup(struct _cnid_db *cdb, const struct stat *st, const cnid_t
     switch (rply.result) {
     case CNID_DBD_RES_OK:
         id = rply.cnid;
+        LOG(log_debug, logtype_cnid, "cnid_dbd_lookup: got CNID: %u", ntohl(id));
         break;
     case CNID_DBD_RES_NOTFOUND:
         id = CNID_INVALID;
@@ -713,18 +790,72 @@ cnid_t cnid_dbd_lookup(struct _cnid_db *cdb, const struct stat *st, const cnid_t
     return id;
 }
 
+/* ---------------------- */
+int cnid_dbd_find(struct _cnid_db *cdb, char *name, size_t namelen, void *buffer, size_t buflen)
+{
+    CNID_private *db;
+    struct cnid_dbd_rqst rqst;
+    struct cnid_dbd_rply rply;
+    int count;
+
+    if (!cdb || !(db = cdb->_private) || !name) {
+        LOG(log_error, logtype_cnid, "cnid_find: Parameter error");
+        errno = CNID_ERR_PARAM;
+        return CNID_INVALID;
+    }
+
+    if (namelen > MAXPATHLEN) {
+        LOG(log_error, logtype_cnid, "cnid_find: Path name is too long");
+        errno = CNID_ERR_PATH;
+        return CNID_INVALID;
+    }
+
+    LOG(log_debug, logtype_cnid, "cnid_find(\"%s\")", name);
+
+    RQST_RESET(&rqst);
+    rqst.op = CNID_DBD_OP_SEARCH;
+
+    rqst.name = name;
+    rqst.namelen = namelen;
+
+    rply.name = buffer;
+    rply.namelen = buflen;
+
+    if (transmit(db, &rqst, &rply) < 0) {
+        errno = CNID_ERR_DB;
+        return CNID_INVALID;
+    }
+
+    switch (rply.result) {
+    case CNID_DBD_RES_OK:
+        count = rply.namelen / sizeof(cnid_t);
+        LOG(log_debug, logtype_cnid, "cnid_find: got %d matches", count);
+        break;
+    case CNID_DBD_RES_NOTFOUND:
+        count = 0;
+        break;
+    case CNID_DBD_RES_ERR_DB:
+        errno = CNID_ERR_DB;
+        count = -1;
+        break;
+    default:
+        abort();
+    }
+
+    return count;
+}
+
 /* ---------------------- */
 int cnid_dbd_update(struct _cnid_db *cdb, const cnid_t id, const struct stat *st,
-                const cnid_t did, char *name, const size_t len)
+                    const cnid_t did, char *name, const size_t len)
 {
     CNID_private *db;
     struct cnid_dbd_rqst rqst;
     struct cnid_dbd_rply rply;
 
-    
     if (!cdb || !(db = cdb->_private) || !id || !st || !name) {
         LOG(log_error, logtype_cnid, "cnid_update: Parameter error");
-        errno = CNID_ERR_PARAM;        
+        errno = CNID_ERR_PARAM;
         return -1;
     }
 
@@ -746,6 +877,9 @@ int cnid_dbd_update(struct _cnid_db *cdb, const cnid_t id, const struct stat *st
     rqst.name = name;
     rqst.namelen = len;
 
+    LOG(log_debug, logtype_cnid, "cnid_dbd_update: CNID: %u, name: '%s', inode: 0x%llx, type: %d (0=file, 1=dir)",
+        ntohl(id), name, (long long)st->st_ino, rqst.type);
+
     rply.namelen = 0;
     if (transmit(db, &rqst, &rply) < 0) {
         errno = CNID_ERR_DB;
@@ -754,6 +888,7 @@ int cnid_dbd_update(struct _cnid_db *cdb, const cnid_t id, const struct stat *st
 
     switch (rply.result) {
     case CNID_DBD_RES_OK:
+        LOG(log_debug, logtype_cnid, "cnid_dbd_update: updated");
     case CNID_DBD_RES_NOTFOUND:
         return 0;
     case CNID_DBD_RES_ERR_DB:
@@ -765,15 +900,15 @@ int cnid_dbd_update(struct _cnid_db *cdb, const cnid_t id, const struct stat *st
 }
 
 /* ---------------------- */
-cnid_t cnid_dbd_rebuild_add(struct _cnid_db *cdb, const struct stat *st, 
-                           const cnid_t did, char *name, const size_t len, 
-                           cnid_t hint)
+cnid_t cnid_dbd_rebuild_add(struct _cnid_db *cdb, const struct stat *st,
+                            const cnid_t did, char *name, const size_t len,
+                            cnid_t hint)
 {
     CNID_private *db;
     struct cnid_dbd_rqst rqst;
     struct cnid_dbd_rply rply;
     cnid_t id;
-    
+
     if (!cdb || !(db = cdb->_private) || !st || !name || hint == CNID_INVALID) {
         LOG(log_error, logtype_cnid, "cnid_rebuild_add: Parameter error");
         errno = CNID_ERR_PARAM;
@@ -800,6 +935,9 @@ cnid_t cnid_dbd_rebuild_add(struct _cnid_db *cdb, const struct stat *st,
     rqst.namelen = len;
     rqst.cnid = hint;
 
+    LOG(log_debug, logtype_cnid, "cnid_dbd_rebuild_add: CNID: %u, name: '%s', inode: 0x%llx, type: %d (0=file, 1=dir), hint: %u",
+        ntohl(did), name, (long long)st->st_ino, rqst.type, hint);
+
     if (transmit(db, &rqst, &rply) < 0) {
         errno = CNID_ERR_DB;
         return CNID_INVALID;
@@ -808,6 +946,7 @@ cnid_t cnid_dbd_rebuild_add(struct _cnid_db *cdb, const struct stat *st,
     switch(rply.result) {
     case CNID_DBD_RES_OK:
         id = rply.cnid;
+        LOG(log_debug, logtype_cnid, "cnid_dbd_rebuild_add: got CNID: %u", ntohl(id));
         break;
     case CNID_DBD_RES_ERR_MAX:
         errno = CNID_ERR_MAX;
@@ -825,19 +964,20 @@ cnid_t cnid_dbd_rebuild_add(struct _cnid_db *cdb, const struct stat *st,
 }
 
 /* ---------------------- */
-int cnid_dbd_delete(struct _cnid_db *cdb, const cnid_t id) 
+int cnid_dbd_delete(struct _cnid_db *cdb, const cnid_t id)
 {
     CNID_private *db;
     struct cnid_dbd_rqst rqst;
     struct cnid_dbd_rply rply;
 
-
     if (!cdb || !(db = cdb->_private) || !id) {
         LOG(log_error, logtype_cnid, "cnid_delete: Parameter error");
-        errno = CNID_ERR_PARAM;        
+        errno = CNID_ERR_PARAM;
         return -1;
     }
 
+    LOG(log_debug, logtype_cnid, "cnid_dbd_delete: delete CNID: %u", ntohl(id));
+
     RQST_RESET(&rqst);
     rqst.op = CNID_DBD_OP_DELETE;
     rqst.cnid = id;
@@ -850,6 +990,7 @@ int cnid_dbd_delete(struct _cnid_db *cdb, const cnid_t id)
 
     switch (rply.result) {
     case CNID_DBD_RES_OK:
+        LOG(log_debug, logtype_cnid, "cnid_dbd_delete: deleted CNID: %u", ntohl(id));
     case CNID_DBD_RES_NOTFOUND:
         return 0;
     case CNID_DBD_RES_ERR_DB: