From 5fd60bee90f24cd522d4cf3cd9335e4c8dce3d58 Mon Sep 17 00:00:00 2001 From: Frank Lahm Date: Fri, 25 Nov 2011 17:41:54 +0100 Subject: [PATCH] Add lots of debugging code in the DSI handling routines --- configure.ac | 2 +- etc/afpd/afp_dsi.c | 8 ++--- etc/afpd/fork.c | 14 ++++---- include/atalk/dsi.h | 5 ++- libatalk/dsi/dsi_cmdreply.c | 26 ++++++++------ libatalk/dsi/dsi_read.c | 45 +++++++++++++------------ libatalk/dsi/dsi_stream.c | 67 +++++++++++++++++++++---------------- 7 files changed, 92 insertions(+), 75 deletions(-) diff --git a/configure.ac b/configure.ac index 0c711b14..d6a36899 100644 --- a/configure.ac +++ b/configure.ac @@ -839,7 +839,7 @@ if test x"$netatalk_cv_search_sendfile" = x"yes"; then AC_SEARCH_LIBS(sendfile, sendfile) AC_CHECK_FUNC([sendfile], [netatalk_cv_HAVE_SENDFILE=yes]) dnl -- there's a bug somewhere, disable for now - netatalk_cv_HAVE_SENDFILE=no +# netatalk_cv_HAVE_SENDFILE=no ;; *freebsd*) diff --git a/etc/afpd/afp_dsi.c b/etc/afpd/afp_dsi.c index 295e03df..3105db63 100644 --- a/etc/afpd/afp_dsi.c +++ b/etc/afpd/afp_dsi.c @@ -483,7 +483,7 @@ void afp_over_dsi(AFPObj *obj) continue; /* Blocking read on the network socket */ - cmd = dsi_receive(dsi); + cmd = dsi_stream_receive(dsi); if (cmd == 0) { /* cmd == 0 is the error condition */ @@ -592,7 +592,7 @@ void afp_over_dsi(AFPObj *obj) /* AFP replay cache */ rc_idx = dsi->clientID % REPLAYCACHE_SIZE; - LOG(log_debug, logtype_afpd, "DSI request ID: %u", dsi->clientID); + LOG(log_debug, logtype_dsi, "DSI request ID: %u", dsi->clientID); if (replaycache[rc_idx].DSIreqID == dsi->clientID && replaycache[rc_idx].AFPcommand == function) { @@ -640,9 +640,7 @@ void afp_over_dsi(AFPObj *obj) if (dsi->flags & DSI_NOREPLY) { dsi->flags &= ~DSI_NOREPLY; break; - } - - if (!dsi_cmdreply(dsi, err)) { + } else if (!dsi_cmdreply(dsi, err)) { LOG(log_error, logtype_afpd, "dsi_cmdreply(%d): %s", dsi->socket, strerror(errno) ); if (dsi_disconnect(dsi) != 0) afp_dsi_die(EXITERR_CLNT); diff --git a/etc/afpd/fork.c b/etc/afpd/fork.c index 69ab4a33..41749b94 100644 --- a/etc/afpd/fork.c +++ b/etc/afpd/fork.c @@ -893,6 +893,9 @@ static int read_fork(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf, si goto afp_read_err; } + LOG(log_debug, logtype_afpd, "afp_read(name: \"%s\", offset: %jd, reqcount: %jd)", + of_name(ofork), (intmax_t)offset, (intmax_t)reqcount); + savereqcount = reqcount; saveoff = offset; if (ad_tmplock(ofork->of_ad, eid, ADLOCK_RD, saveoff, savereqcount,ofork->of_refnum) < 0) { @@ -901,9 +904,13 @@ static int read_fork(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf, si } *rbuflen = MIN(reqcount, *rbuflen); + LOG(log_debug, logtype_afpd, "afp_read(name: \"%s\", offset: %jd, reqcount: %jd): reading %jd bytes from file", + of_name(ofork), (intmax_t)offset, (intmax_t)reqcount, (intmax_t)*rbuflen); err = read_file(ofork, eid, offset, nlmask, nlchar, rbuf, rbuflen, xlate); if (err < 0) goto afp_read_done; + LOG(log_debug, logtype_afpd, "afp_read(name: \"%s\", offset: %jd, reqcount: %jd): got %jd bytes from file", + of_name(ofork), (intmax_t)offset, (intmax_t)reqcount, (intmax_t)*rbuflen); /* dsi can stream requests. we can only do this if we're not checking * for an end-of-line character. oh well. */ @@ -936,6 +943,7 @@ static int read_fork(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf, si int fd; fd = ad_readfile_init(ofork->of_ad, eid, &offset, 0); + if (dsi_stream_read_file(dsi, fd, offset, dsi->datasize) < 0) { if (errno == EINVAL || errno == ENOSYS) goto afp_read_loop; @@ -959,12 +967,6 @@ afp_read_loop: goto afp_read_exit; offset += *rbuflen; -#ifdef DEBUG1 - if (obj->options.flags & OPTION_DEBUG) { - printf( "(read) reply: %d, %d\n", *rbuflen, dsi->clientID); - bprint(rbuf, *rbuflen); - } -#endif /* dsi_read() also returns buffer size of next allocation */ cc = dsi_read(dsi, rbuf, *rbuflen); /* send it off */ if (cc < 0) diff --git a/include/atalk/dsi.h b/include/atalk/dsi.h index 7ae0bd24..eded2b8f 100644 --- a/include/atalk/dsi.h +++ b/include/atalk/dsi.h @@ -187,7 +187,7 @@ extern void dsi_close (DSI *); extern ssize_t dsi_stream_write (DSI *, void *, const size_t, const int mode); extern size_t dsi_stream_read (DSI *, void *, const size_t); extern int dsi_stream_send (DSI *, void *, size_t); -extern int dsi_stream_receive (DSI *, void *, const size_t, size_t *); +extern int dsi_stream_receive (DSI *); extern int dsi_disconnect(DSI *dsi); #ifdef WITH_SENDFILE @@ -212,6 +212,5 @@ extern void dsi_readdone (DSI *); (x)->header.dsi_len = htonl((x)->cmdlen); \ dsi_stream_send((x), (x)->commands, (x)->cmdlen); \ } while (0) -#define dsi_receive(x) (dsi_stream_receive((x), (x)->commands, \ - DSI_CMDSIZ, &(x)->cmdlen)) + #endif /* atalk/dsi.h */ diff --git a/libatalk/dsi/dsi_cmdreply.c b/libatalk/dsi/dsi_cmdreply.c index f924da5a..ae24535d 100644 --- a/libatalk/dsi/dsi_cmdreply.c +++ b/libatalk/dsi/dsi_cmdreply.c @@ -1,6 +1,4 @@ /* - * $Id: dsi_cmdreply.c,v 1.5 2009-10-25 06:13:11 didg Exp $ - * * Copyright (c) 1997 Adrian Sun (asun@zoology.washington.edu) * All rights reserved. See COPYRIGHT. */ @@ -11,6 +9,7 @@ #include #include +#include #include /* this assumes that the reply follows right after the command, saving @@ -18,12 +17,19 @@ * reserved field are assumed to already be set. */ int dsi_cmdreply(DSI *dsi, const int err) { -int ret; - dsi->header.dsi_flags = DSIFL_REPLY; - /*dsi->header.dsi_command = DSIFUNC_CMD;*/ - dsi->header.dsi_len = htonl(dsi->datalen); - dsi->header.dsi_code = htonl(err); - - ret = dsi_stream_send(dsi, dsi->data, dsi->datalen); - return ret; + int ret; + + LOG(log_debug, logtype_dsi, "dsi_cmdreply(DSI ID: %u, len: %jd): START", + dsi->clientID, (intmax_t)dsi->datalen); + + dsi->header.dsi_flags = DSIFL_REPLY; + dsi->header.dsi_len = htonl(dsi->datalen); + dsi->header.dsi_code = htonl(err); + + ret = dsi_stream_send(dsi, dsi->data, dsi->datalen); + + LOG(log_debug, logtype_dsi, "dsi_cmdreply(DSI ID: %u, len: %jd): END", + dsi->clientID, (intmax_t)dsi->datalen); + + return ret; } diff --git a/libatalk/dsi/dsi_read.c b/libatalk/dsi/dsi_read.c index 092544ad..12971511 100644 --- a/libatalk/dsi/dsi_read.c +++ b/libatalk/dsi/dsi_read.c @@ -23,6 +23,7 @@ #include #include +#include /* streaming i/o for afp_read. this is all from the perspective of the * client. it basically does the reverse of dsi_write. on first entry, @@ -30,40 +31,42 @@ * buffer. it returns the amount of stuff still to be read * (constrained by the buffer size). */ ssize_t dsi_readinit(DSI *dsi, void *buf, const size_t buflen, - const size_t size, const int err) + const size_t size, const int err) { + LOG(log_maxdebug, logtype_dsi, "dsi_readinit: sending %zd bytes from buffer, total size: %zd", + buflen, size); - dsi->flags |= DSI_NOREPLY; /* we will handle our own replies */ - dsi->header.dsi_flags = DSIFL_REPLY; - /*dsi->header.dsi_command = DSIFUNC_CMD;*/ - dsi->header.dsi_len = htonl(size); - dsi->header.dsi_code = htonl(err); + dsi->flags |= DSI_NOREPLY; /* we will handle our own replies */ + dsi->header.dsi_flags = DSIFL_REPLY; + dsi->header.dsi_len = htonl(size); + dsi->header.dsi_code = htonl(err); - dsi->in_write++; - if (dsi_stream_send(dsi, buf, buflen)) { - dsi->datasize = size - buflen; - return MIN(dsi->datasize, buflen); - } + dsi->in_write++; + if (dsi_stream_send(dsi, buf, buflen)) { + dsi->datasize = size - buflen; + LOG(log_maxdebug, logtype_dsi, "dsi_readinit: remaining data for sendfile: %zd", dsi->datasize); + return MIN(dsi->datasize, buflen); + } - return -1; /* error */ + return -1; /* error */ } void dsi_readdone(DSI *dsi) { - dsi->in_write--; + dsi->in_write--; } /* send off the data */ ssize_t dsi_read(DSI *dsi, void *buf, const size_t buflen) { - size_t len; - - len = dsi_stream_write(dsi, buf, buflen, 0); + size_t len; - if (len == buflen) { - dsi->datasize -= len; - return MIN(dsi->datasize, buflen); - } + len = dsi_stream_write(dsi, buf, buflen, 0); - return -1; + if (len == buflen) { + dsi->datasize -= len; + return MIN(dsi->datasize, buflen); + } + + return -1; } diff --git a/libatalk/dsi/dsi_stream.c b/libatalk/dsi/dsi_stream.c index b7f1bb45..6c8b51e4 100644 --- a/libatalk/dsi/dsi_stream.c +++ b/libatalk/dsi/dsi_stream.c @@ -266,7 +266,7 @@ ssize_t dsi_stream_write(DSI *dsi, void *data, const size_t length, int mode) dsi->in_write++; written = 0; - LOG(log_maxdebug, logtype_dsi, "dsi_stream_write: sending %u bytes", length); + LOG(log_maxdebug, logtype_dsi, "dsi_stream_write(send: %zd bytes): START", length); if (dsi->flags & DSI_DISCONNECTED) return -1; @@ -305,6 +305,7 @@ ssize_t dsi_stream_write(DSI *dsi, void *data, const size_t length, int mode) } dsi->write_count += written; + LOG(log_maxdebug, logtype_dsi, "dsi_stream_write(send: %zd bytes): END", length); exit: dsi->in_write--; @@ -317,10 +318,12 @@ exit: #ifdef WITH_SENDFILE ssize_t dsi_stream_read_file(DSI *dsi, int fromfd, off_t offset, const size_t length) { + int ret = 0; size_t written; ssize_t len; + off_t pos = offset; - LOG(log_maxdebug, logtype_dsi, "dsi_stream_read_file: sending %u bytes", length); + LOG(log_maxdebug, logtype_dsi, "dsi_stream_read_file(send %zd bytes): START", length); if (dsi->flags & DSI_DISCONNECTED) return -1; @@ -329,14 +332,15 @@ ssize_t dsi_stream_read_file(DSI *dsi, int fromfd, off_t offset, const size_t le written = 0; while (written < length) { - len = sys_sendfile(dsi->socket, fromfd, &offset, length - written); + len = sys_sendfile(dsi->socket, fromfd, &pos, length - written); if (len < 0) { if (errno == EINTR) continue; - if (errno == EINVAL || errno == ENOSYS) - return -1; - + if (errno == EINVAL || errno == ENOSYS) { + ret = -1; + goto exit; + } if (errno == EAGAIN || errno == EWOULDBLOCK) { if (dsi_peek(dsi)) { /* can't go back to blocking mode, exit, the next read @@ -351,15 +355,20 @@ ssize_t dsi_stream_read_file(DSI *dsi, int fromfd, off_t offset, const size_t le } else if (!len) { /* afpd is going to exit */ - errno = EIO; - return -1; /* I think we're at EOF here... */ + ret = -1; + goto exit; } else written += len; } dsi->write_count += written; + +exit: dsi->in_write--; + LOG(log_maxdebug, logtype_dsi, "dsi_stream_read_file: sent: %zd", written); + if (ret != 0) + return -1; return written; } #endif @@ -423,8 +432,7 @@ int dsi_stream_send(DSI *dsi, void *buf, size_t length) size_t towrite; ssize_t len; - LOG(log_maxdebug, logtype_dsi, "dsi_stream_send: %u bytes", - length ? length : sizeof(block)); + LOG(log_maxdebug, logtype_dsi, "dsi_stream_send(%u bytes): START", length); if (dsi->flags & DSI_DISCONNECTED) return 0; @@ -439,6 +447,7 @@ int dsi_stream_send(DSI *dsi, void *buf, size_t length) sizeof(dsi->header.dsi_reserved)); if (!length) { /* just write the header */ + LOG(log_maxdebug, logtype_dsi, "dsi_stream_send(%u bytes): DSI header, no data", sizeof(block)); length = (dsi_stream_write(dsi, block, sizeof(block), 0) == sizeof(block)); return length; /* really 0 on failure, 1 on success */ } @@ -482,22 +491,26 @@ int dsi_stream_send(DSI *dsi, void *buf, size_t length) iov[1].iov_len -= len; } } + + LOG(log_maxdebug, logtype_dsi, "dsi_stream_send(%u bytes): END", length); unblock_sig(dsi); return 1; } -/* --------------------------------------- - * read data. function on success. 0 on failure. data length gets - * stored in length variable. this should really use size_t's, but - * that would require changes elsewhere. */ -int dsi_stream_receive(DSI *dsi, void *buf, const size_t ilength, - size_t *rlength) +/*! + * Read DSI command and data + * + * @param dsi (rw) DSI handle + * + * @return DSI function on success, 0 on failure + */ +int dsi_stream_receive(DSI *dsi) { char block[DSI_BLOCKSIZ]; - LOG(log_maxdebug, logtype_dsi, "dsi_stream_receive: %u bytes", ilength); + LOG(log_maxdebug, logtype_dsi, "dsi_stream_receive: START"); if (dsi->flags & DSI_DISCONNECTED) return 0; @@ -508,26 +521,22 @@ int dsi_stream_receive(DSI *dsi, void *buf, const size_t ilength, dsi->header.dsi_flags = block[0]; dsi->header.dsi_command = block[1]; - /* FIXME, not the right place, - but we get a server disconnect without reason in the log - */ - if (!block[1]) { - LOG(log_error, logtype_dsi, "dsi_stream_receive: invalid packet, fatal"); + + if (dsi->header.dsi_command == 0) return 0; - } - memcpy(&dsi->header.dsi_requestID, block + 2, - sizeof(dsi->header.dsi_requestID)); + memcpy(&dsi->header.dsi_requestID, block + 2, sizeof(dsi->header.dsi_requestID)); memcpy(&dsi->header.dsi_code, block + 4, sizeof(dsi->header.dsi_code)); memcpy(&dsi->header.dsi_len, block + 8, sizeof(dsi->header.dsi_len)); - memcpy(&dsi->header.dsi_reserved, block + 12, - sizeof(dsi->header.dsi_reserved)); + memcpy(&dsi->header.dsi_reserved, block + 12, sizeof(dsi->header.dsi_reserved)); dsi->clientID = ntohs(dsi->header.dsi_requestID); /* make sure we don't over-write our buffers. */ - *rlength = min(ntohl(dsi->header.dsi_len), ilength); - if (dsi_stream_read(dsi, buf, *rlength) != *rlength) + dsi->cmdlen = min(ntohl(dsi->header.dsi_len), DSI_CMDSIZ); + if (dsi_stream_read(dsi, dsi->commands, dsi->cmdlen) != dsi->cmdlen) return 0; + LOG(log_debug, logtype_dsi, "dsi_stream_receive: DSI cmdlen: %zd", dsi->cmdlen); + return block[1]; } -- 2.39.2