Do not log twice an aborted transaction with request body #263
Conversation
This extra logging happened because the current inBuf cleanup in ConnStateData::terminateAll() does not account for the case when the pipeline is empty (the stream object already deleted in ConnStateData::afterClientWrite()).
on which bareError is updated.
These cases include various invalid requests, detected by Server::processParsedRequest(), such as requests with invalid 'Expect' header, Content-Length exceeding request_body_max_size and others.
eduard-bagdasaryan
changed the title
* Reset mayUseConnection flag for body-less requests * Use connLeftovers_ only once (i.e., do not reuse it in successive terminateAll() calls)
and require that mayUseConnection flag may be true only in a single pipeline Stream object.
| @@ -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); | |||
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
| @@ -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); | |||
| poppedBusy = true; | |||
There was a problem hiding this comment.
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)?
There was a problem hiding this comment.
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.
This extra logging happened because the current inBuf cleanup
in ConnStateData::terminateAll() did not occur when the pipeline
is already empty (for example, the stream object
was deleted after replying with an error to the client).
So, if inBuf still has unconsumed bytes, checkLogging()
assumes that there are some outstanding transaction bytes and
logs the extra error:transaction-end-before-headers entry.