Hello,
The attached patch polishes helper debugging. These changes were
inspired by production 3.0 code where support folks apparently found
them useful. They add message length and/or message contents debugging
to several helper processing paths. I think they are worth accepting.
I ported and rewrote the changes using the Raw manipulator proposed in
the previous patch.
Thank you,
Alex.
Polished helper messages debugging slightly.
Made stateful and stateless debugging a little bit more similar/symmetric.
Debug helperStatefulSubmit message contents length.
Debug accumulated helperStatefulHandleRead buffer.
Polished helperHandleRead buffer debugging.
=== modified file 'src/helper.cc'
--- src/helper.cc 2012-12-08 01:50:46 +0000
+++ src/helper.cc 2012-12-14 00:48:11 +0000
@@ -398,41 +398,41 @@
{
if (hlp == NULL) {
debugs(84, 3, "helperSubmit: hlp == NULL");
HelperReply nilReply;
callback(data, nilReply);
return;
}
helper_request *r = new helper_request;
helper_server *srv;
r->callback = callback;
r->data = cbdataReference(data);
r->buf = xstrdup(buf);
if ((srv = GetFirstAvailable(hlp)))
helperDispatch(srv, r);
else
Enqueue(hlp, r);
- debugs(84, 9, "helperSubmit: " << buf);
+ debugs(84, DBG_DATA, Raw("buf", buf, strlen(buf)));
}
/// lastserver = "server last used as part of a reserved request sequence"
void
helperStatefulSubmit(statefulhelper * hlp, const char *buf, HLPCB * callback, void *data, helper_stateful_server * lastserver)
{
if (hlp == NULL) {
debugs(84, 3, "helperStatefulSubmit: hlp == NULL");
HelperReply nilReply;
callback(data, nilReply);
return;
}
helper_stateful_request *r = new helper_stateful_request;
r->callback = callback;
r->data = cbdataReference(data);
if (buf != NULL) {
r->buf = xstrdup(buf);
@@ -440,41 +440,42 @@
} else {
r->buf = NULL;
r->placeholder = 1;
}
if ((buf != NULL) && lastserver) {
debugs(84, 5, "StatefulSubmit with lastserver " << lastserver);
assert(lastserver->flags.reserved);
assert(!(lastserver->request));
debugs(84, 5, "StatefulSubmit dispatching");
helperStatefulDispatch(lastserver, r);
} else {
helper_stateful_server *srv;
if ((srv = StatefulGetFirstAvailable(hlp))) {
helperStatefulDispatch(srv, r);
} else
StatefulEnqueue(hlp, r);
}
- debugs(84, 9, "helperStatefulSubmit: placeholder: '" << r->placeholder << "', buf '" << buf << "'.");
+ debugs(84, DBG_DATA, "placeholder: '" << r->placeholder <<
+ "', " << Raw("buf", buf, strlen(buf)));
}
/**
* DPW 2007-05-08
*
* helperStatefulReleaseServer tells the helper that whoever was
* using it no longer needs its services.
*/
void
helperStatefulReleaseServer(helper_stateful_server * srv)
{
debugs(84, 3, HERE << "srv-" << srv->index << " flags.reserved = " << srv->flags.reserved);
if (!srv->flags.reserved)
return;
++ srv->stats.releases;
srv->flags.reserved = 0;
if (srv->parent->OnEmptyQueue != NULL && srv->data)
srv->parent->OnEmptyQueue(srv->data);
@@ -897,41 +898,41 @@
helper *hlp = srv->parent;
assert(cbdataReferenceValid(data));
/* Bail out early on COMM_ERR_CLOSING - close handlers will tidy up for us */
if (flag == COMM_ERR_CLOSING) {
return;
}
assert(conn->fd == srv->readPipe->fd);
debugs(84, 5, "helperHandleRead: " << len << " bytes from " << hlp->id_name << " #" << srv->index + 1);
if (flag != COMM_OK || len == 0) {
srv->closePipesSafely();
return;
}
srv->roffset += len;
srv->rbuf[srv->roffset] = '\0';
- debugs(84, 9, "helperHandleRead: '" << srv->rbuf << "'");
+ debugs(84, DBG_DATA, Raw("accumulated", srv->rbuf, srv->roffset));
if (!srv->stats.pending) {
/* someone spoke without being spoken to */
debugs(84, DBG_IMPORTANT, "helperHandleRead: unexpected read from " <<
hlp->id_name << " #" << srv->index + 1 << ", " << (int)len <<
" bytes '" << srv->rbuf << "'");
srv->roffset = 0;
srv->rbuf[0] = '\0';
}
while ((t = strchr(srv->rbuf, hlp->eom))) {
/* end of reply found */
char *msg = srv->rbuf;
int i = 0;
int skip = 1;
debugs(84, 3, "helperHandleRead: end of reply found");
if (t > srv->rbuf && t[-1] == '\r' && hlp->eom == '\n') {
t = '\0';
@@ -994,40 +995,41 @@
/* Bail out early on COMM_ERR_CLOSING - close handlers will tidy up for us */
if (flag == COMM_ERR_CLOSING) {
return;
}
assert(conn->fd == srv->readPipe->fd);
debugs(84, 5, "helperStatefulHandleRead: " << len << " bytes from " <<
hlp->id_name << " #" << srv->index + 1);
if (flag != COMM_OK || len == 0) {
srv->closePipesSafely();
return;
}
srv->roffset += len;
srv->rbuf[srv->roffset] = '\0';
r = srv->request;
+ debugs(84, DBG_DATA, Raw("accumulated", srv->rbuf, srv->roffset));
if (r == NULL) {
/* someone spoke without being spoken to */
debugs(84, DBG_IMPORTANT, "helperStatefulHandleRead: unexpected read from " <<
hlp->id_name << " #" << srv->index + 1 << ", " << (int)len <<
" bytes '" << srv->rbuf << "'");
srv->roffset = 0;
}
if ((t = strchr(srv->rbuf, hlp->eom))) {
/* end of reply found */
int called = 1;
int skip = 1;
debugs(84, 3, "helperStatefulHandleRead: end of reply found");
if (t > srv->rbuf && t[-1] == '\r' && hlp->eom == '\n') {
*t = '\0';
// rewind to the \r octet which is the real terminal now
// and remember that we have to skip forward 2 places now.
