[
https://issues.apache.org/jira/browse/TS-3226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14238206#comment-14238206
]
Sudheer Vinukonda edited comment on TS-3226 at 12/8/14 6:30 PM:
----------------------------------------------------------------
I am still a little bit as to unsure how the values of {{nbytes}} and {{ndone}}
could get restored inside the mutex lock to the correct values. For example, in
the specific scenario I am debugging, the {{net_read_io}} could be called by
the socket input on one side and tunnel read on the other side. The tunnel read
sets the {{nbytes}} and {{ndone}} in the {{do_io_read}} which itself does not
lock.
Below are the logs from the little instrumentation that I made, showing that
the ndone/nbytes values before the mutex were all "0", while after the mutex
were the correct/expected values.
{code}
//ntodo_t, s_ntodo_t, nbytes_t, ndone_t are calculated before acquiring the
mutex..
if (ntodo_t != (s->vio.nbytes - s->vio.ndone)) {
TraceIn(true, get_remote_addr(), get_remote_port(),
"prelock vio %p, afterlock vio %p, before lock,
ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock, ntodo:s_ntodo:nbytes:ndone
before checking..%" PRId64 ":%" PRId64 ":%" PRId64 ":%" PRId64 ":%" PRId64 ":%"
PRId64 ":%" PRId64 ":%" PRId64, pre_lock_vio, &(s->vio), ntodo_t, s_ntodo_t,
nbytes_t, ndone_t, ntodo, s->vio.ntodo(), s->vio.nbytes, s->vio.ndone);
}
{code}
{code}
-bash-4.1$ tail -f error.log | grep -i prelock
20141208.18h21m39s prelock vio 0x2ae86c0cd760, afterlock vio 0x2ae86c0cd760,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before checking..0:0:0:0:2054:2054:2054:0
20141208.18h22m56s prelock vio 0x2ae85c002ad0, afterlock vio 0x2ae85c002ad0,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before checking..0:0:0:0:2693:2693:2693:0
20141208.18h23m10s prelock vio 0x2ae86c52b1d0, afterlock vio 0x2ae86c52b1d0,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before
checking..0:0:0:0:9223372036854775807:9223372036854775807:9223372036854775807:0
20141208.18h23m28s prelock vio 0x2ae86c619390, afterlock vio 0x2ae86c619390,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before checking..0:65:65:0:65:65:65:0
{code}
was (Author: sudheerv):
I am still a little bit as to unsure how the values of {{nbytes}} and {{ndone}}
could get restored inside a mutex to the correct values. For example, in the
specific scenario I am debugging, the {{net_read_io}} could be called by the
socket input on one side and tunnel read on the other side. The tunnel read
sets the {{nbytes}} and {{ndone}} in the {{do_io_read}} which itself does not
lock.
Below are the logs from the little instrumentation that I made, showing that
the ndone/nbytes values before the mutex were all "0", while after the mutex
were the correct/expected values.
{code}
//ntodo_t, s_ntodo_t, nbytes_t, ndone_t are calculated before acquiring the
mutex..
if (ntodo_t != (s->vio.nbytes - s->vio.ndone)) {
TraceIn(true, get_remote_addr(), get_remote_port(),
"prelock vio %p, afterlock vio %p, before lock,
ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock, ntodo:s_ntodo:nbytes:ndone
before checking..%" PRId64 ":%" PRId64 ":%" PRId64 ":%" PRId64 ":%" PRId64 ":%"
PRId64 ":%" PRId64 ":%" PRId64, pre_lock_vio, &(s->vio), ntodo_t, s_ntodo_t,
nbytes_t, ndone_t, ntodo, s->vio.ntodo(), s->vio.nbytes, s->vio.ndone);
}
{code}
{code}
-bash-4.1$ tail -f error.log | grep -i prelock
20141208.18h21m39s prelock vio 0x2ae86c0cd760, afterlock vio 0x2ae86c0cd760,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before checking..0:0:0:0:2054:2054:2054:0
20141208.18h22m56s prelock vio 0x2ae85c002ad0, afterlock vio 0x2ae85c002ad0,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before checking..0:0:0:0:2693:2693:2693:0
20141208.18h23m10s prelock vio 0x2ae86c52b1d0, afterlock vio 0x2ae86c52b1d0,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before
checking..0:0:0:0:9223372036854775807:9223372036854775807:9223372036854775807:0
20141208.18h23m28s prelock vio 0x2ae86c619390, afterlock vio 0x2ae86c619390,
before lock, ntodo_t:s_ntodo_t:nbytes_t:ndone_t after lock,
ntodo:s_ntodo:nbytes:ndone before checking..0:65:65:0:65:65:65:0
{code}
> SSL data not read from the socket sometimes causing transactions to timeout
> ---------------------------------------------------------------------------
>
> Key: TS-3226
> URL: https://issues.apache.org/jira/browse/TS-3226
> Project: Traffic Server
> Issue Type: Bug
> Components: SSL
> Affects Versions: 5.1.1
> Reporter: Sudheer Vinukonda
> Assignee: Sudheer Vinukonda
> Fix For: 5.2.0
>
>
> We have had a really long standing problem where some of our origins were
> complaining of receiving POST requests with non-zero content-length header,
> but, no body (or sometimes, partial body). Due to the way our network was
> setup, this problem was not easy to be isolated due to the multiple hops
> along the way. The post body could be lost anywhere along the path (e.g.
> client, dns, routers/vips, edge, data center etc). After a lot of debugging
> and with the help of some custom-built wire traces for SSL, we managed to
> isolate the problem to our ATS hosts running on our edge layer. From the wire
> traces, we could see that, the post body is coming in alright, but is just
> sitting in the socket and not being read by the post ua tunnel producer.
> After further investigation, it seems that the producer is issuing the
> correct do_io_read for the required number of bytes, but, there seems to be a
> bug in the {{SSLNetVConnection::net_read_io}}, where the ntodo is being
> calculated before acquiring the mutex on the read vio.
> https://github.com/apache/trafficserver/blob/master/iocore/net/SSLNetVConnection.cc#L391
> Instrumenting the code with further debug traces showed that, in the failed
> transactions, I am noticing the ntodo being "0" when determined before the
> mutex, whereas the (s->vio.nbytes - s->vio.ndone) is non-zero after the
> mutex. I am not sure to understand how the nbytes on the read vio object can
> be different before acquiring mutex, but, moving the ntodo calculation after
> mutex seems to have resolved the problem. Note that this is how it is done in
> the corresponding function {{read_from_net}} in {{UnixNetVConnection}}.
> Talking to [~amc] on the IRC, it seems that the mutex is needed coz, the
> {{SSLNetVConnection::net_read_io}} could also be triggered by an incoming
> socket data before the {{UnixNetVConnection::do_io_read}} could trigger it
> and that could mess up the nbytes/ndone in the read vio.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
