Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Do not log twice an aborted transaction with request body #263

Open
wants to merge 9 commits into
base: master
Choose a base branch
from
13 changes: 13 additions & 0 deletions src/Pipeline.cc
Original file line number Diff line number Diff line change
@@ -19,6 +19,9 @@
void
Pipeline::add(const Http::StreamPointer &c)
{
Assure(!mayUseConnection());
Assure(!poppedBusy);
c->mayUseConnection(true);
requests.push_back(c);
++nrequests;
debugs(33, 3, "Pipeline " << (void*)this << " add request " << nrequests << ' ' << c);
@@ -48,6 +51,12 @@ Pipeline::back() const
return requests.back();
}

bool
Pipeline::mayUseConnection() const
{
return requests.empty() ? false : requests.front()->mayUseConnection();
}

void
Pipeline::popMe(const Http::StreamPointer &which)
{
@@ -58,6 +67,10 @@ Pipeline::popMe(const Http::StreamPointer &which)
// in reality there may be multiple contexts doing processing in parallel.
// XXX: pipeline still assumes HTTP/1 FIFO semantics are obeyed.
assert(which == requests.front());
if (which->mayUseConnection()) {
Assure(requests.size() == 1);

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This assertion might be (essentially accidentally) true in current PR code but it is not based on any HTTP logic AFAICT: The last transaction may remove itself from the pipeline regardless of how many other transactions are currently in the pipeline. That applies to all last transactions, including transactions that mayUseConnection(). Why do we need to assert this condition here?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The last transaction may remove itself from the pipeline

How can this happen, i.e., the last transaction (or any other arbitrary one) remove itself from the pipeline? We do not have API for this. What we have is popMe(), removing the front element (transaction) from the queue. Since we do not add() until front() is still using connection, only back() element may use connection. That is what this assertion checks.

poppedBusy = true;

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this code assume that after we pop a mayUseConnection() transaction, we will never push a regular GET transaction? I do not see poppedBusy becoming false after popMe(). Why is that assumption safe?! It feels like we could pop a POST transaction and then push a GET transaction.

Perhaps this code secretly relies on the being-popped completed POST transaction setting its mayUseConnection() to false before calling popMe()? In other words, perhaps this code relies on true mayUseConnection() during popMe() indicating some kind of "fatal" connection problem (i.e. a problem that is guaranteed to be handled by killing all transactions and closing the client-Squid connection so that we should not care about any future transactions on the same connection)?

Copy link
Author

@eduard-bagdasaryan eduard-bagdasaryan Oct 22, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This PR should add explicit 'mayUseConnection(false)' in all required places (i.e., where we processed all request bytes). So calling popMe() on transaction which is still using connection means that there are (or may) be still bytes belonging to that (being removed) transaction. We cannot start another transaction with these bytes left behind (i.e., face message framing problems).

this code relies on true mayUseConnection() during popMe() indicating some kind of "fatal" connection problem

I think it is true, this poppedBusy flag indicates this. The second assertion in Pipeline::add() should uphold this invariant, i.e., we cannot add a transaction if there has been a 'fatal' error on the connection.

}
requests.pop_front();
}

6 changes: 6 additions & 0 deletions src/Pipeline.h
Original file line number Diff line number Diff line change
@@ -58,10 +58,16 @@ class Pipeline
/// deregister the front request from the pipeline
void popMe(const Http::StreamPointer &);

/// whether some of the queued transactions use the connection
bool mayUseConnection() const;

/// Number of requests seen in this pipeline (so far).
/// Includes incomplete transactions.
uint32_t nrequests;

/// whether popMe() was called on a transaction with mayUseConnection()
bool poppedBusy = false;

private:
/// requests parsed from the connection but not yet completed.
std::list<Http::StreamPointer> requests;
50 changes: 25 additions & 25 deletions src/client_side.cc
Original file line number Diff line number Diff line change
@@ -1635,10 +1635,8 @@ clientProcessRequest(ConnStateData *conn, const Http1::RequestParserPointer &hp,

clientSetKeepaliveFlag(http);
// Let tunneling code be fully responsible for CONNECT requests
if (http->request->method == Http::METHOD_CONNECT) {
context->mayUseConnection(true);
if (http->request->method == Http::METHOD_CONNECT)
conn->flags.readMore = false;
}

#if USE_OPENSSL
if (conn->switchedToHttps() && conn->serveDelayedError(context)) {
@@ -1650,7 +1648,9 @@ clientProcessRequest(ConnStateData *conn, const Http1::RequestParserPointer &hp,
/* Do we expect a request-body? */
const auto chunked = request->header.chunked();
expectBody = chunked || request->content_length > 0;
if (!context->mayUseConnection() && expectBody) {
if (http->request->method != Http::METHOD_CONNECT && !expectBody) // TODO: diff reducer
context->mayUseConnection(false);
if (http->request->method != Http::METHOD_CONNECT && expectBody) {
request->body_pipe = conn->expectRequestBody(
chunked ? -1 : request->content_length);

@@ -1680,7 +1680,6 @@ clientProcessRequest(ConnStateData *conn, const Http1::RequestParserPointer &hp,

if (!request->body_pipe->productionEnded()) {
debugs(33, 5, "need more request body");
context->mayUseConnection(true);
assert(conn->flags.readMore);
}
}
@@ -1962,6 +1961,8 @@ ConnStateData::handleRequestBodyData()
consumeInput(putSize);

if (!bodyPipe->mayNeedMoreData()) {
if (auto context = pipeline.front())
context->mayUseConnection(false);
// BodyPipe will clear us automagically when we produced everything
bodyPipe = nullptr;
}
@@ -3173,7 +3174,6 @@ ConnStateData::buildFakeRequest(SBuf &useHost, const AnyP::KnownPort usePort, co
clientSocketDetach, newClient, tempBuffer);

stream->flags.parsed_ok = 1; // Do we need it?
stream->mayUseConnection(true);
extendLifetime();
stream->registerWithConn();

@@ -3594,9 +3594,11 @@ ConnStateData::finishDechunkingRequest(bool withSuccess)
Must(!bodyPipe); // we rely on it being nil after we are done with body
if (withSuccess) {
Must(myPipe->bodySizeKnown());
Http::StreamPointer context = pipeline.front();
if (context != nullptr && context->http && context->http->request)
context->http->request->setContentLength(myPipe->bodySize());
if (auto context = pipeline.front()) {
context->mayUseConnection(false);
if (context->http && context->http->request)
context->http->request->setContentLength(myPipe->bodySize());
}
}
}

@@ -3914,30 +3916,28 @@ ConnStateData::terminateAll(const Error &rawError, const LogTagsErrors &lte)

debugs(33, 3, pipeline.count() << '/' << pipeline.nrequests << " after " << error);

if (pipeline.empty()) {
if (pipeline.empty())
bareError.update(error); // XXX: bareLogTagsErrors
} else {
// We terminate the current CONNECT/PUT/etc. context below, logging any
// error details, but that context may leave unparsed bytes behind.
// Consume them to stop checkLogging() from logging them again later.
const auto intputToConsume =
#if USE_OPENSSL
parsingTlsHandshake ? "TLS handshake" : // more specific than CONNECT
#endif
bodyPipe ? "HTTP request body" :
pipeline.back()->mayUseConnection() ? "HTTP CONNECT" :
nullptr;

// We terminate the current CONNECT/PUT/etc. context below, logging any
// error details, but that context may leave unparsed bytes behind.
// Consume them to stop checkLogging() from logging them again later.
const auto intputToConsume =
(pipeline.poppedBusy && !inBuf.isEmpty()) ? "extra connection bytes" :
(!pipeline.empty() && pipeline.mayUseConnection()) ? "still using connection" :
nullptr;

if (!pipeline.empty()) {
while (const auto context = pipeline.front()) {
context->noteIoError(error, lte);
context->finished(); // cleanup and self-deregister
assert(context != pipeline.front());
}
}

if (intputToConsume && !inBuf.isEmpty()) {
debugs(83, 5, "forgetting client " << intputToConsume << " bytes: " << inBuf.length());
inBuf.clear();
}
if (intputToConsume && !inBuf.isEmpty()) {
debugs(83, 5, "forgetting client " << intputToConsume << " bytes: " << inBuf.length());
inBuf.clear();
}

clientConnection->close();