[
https://issues.apache.org/jira/browse/TS-1411?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13799249#comment-13799249
]
Sean Cosgrave commented on TS-1411:
-----------------------------------
David, go ahead and try the changes from TS-1988, but I don't think they are
going to resolve the underlying issue.
In the crash stack trace we see that in the function
marshal_client_req_url_canon() m_client_req_url_canon_str is pointing at a bad
spot in memory. I have a idea on why m_client_req_url_canon_str might be bad,
but I don't really know how it gets into this state. In the older version of TS
that we used in the past we encountered a crash in
LogAccessHttp::marshal_client_req_url() where m_client_req_url_str was pointing
to bad memory. It was pointing to the wrong place in memory because it was
equal to URL::m_ptr_printed_string, which was also was pointing to a bad spot
in memory. The heap that URL::m_ptr_printed_string pointed to probably got
coallesced, and the URL's pointer was not updated.
I think this bug is actually the same bug. I think
LogAccessHttp::m_client_req_url_canon_str is pointing at a bad spot in memory
because the heap where the string was stored was coallesced. In fact, I have
seen (with some help from Bryan) that in this crash both
LogAccessHttp::m_client_req_url_str (which points to the same memory as
URL::m_ptr_printed_string) and LogAccessHttp::m_client_req_url_canon_str point
to the same memory address:
{noformat}
(gdb) p (LogAccessHttp)*lad
$4 = {<LogAccess> = {_vptr.LogAccess = 0x6d2a10, initialized = false},
m_http_sm = 0x2ac8b337d2b0, m_arena = {m_blocks = 0x0}, m_client_request =
0x2ac8b337d9a8,
m_proxy_response = 0x2ac8b337d9e8, m_proxy_request = 0x0, m_server_response =
0x0, m_cache_response = 0x2ac8b337dae8,
m_client_req_url_str = 0x2ac7ac5af0bb <Address 0x2ac7ac5af0bb out of bounds>,
m_client_req_url_len = 1968,
m_client_req_url_canon_str = 0x2ac7ac5af0bb <Address 0x2ac7ac5af0bb out of
bounds>, m_client_req_url_canon_len = 1968,
{noformat}
Here is how I think we get into this state:
1. m_client_req_url_str gets set to URL::m_ptr_printed_string, and
m_client_req_url_canon_str gets set to m_client_req_url_str because
LogUtils::escapify_url returns m_client_req_url_str when the URL does not have
any characters that need to be escaped.
{noformat}
void
LogAccessHttp::init()
{
HttpTransact::HeaderInfo * hdr = &(m_http_sm->t_state.hdr_info);
if (hdr->client_request.valid()) {
m_client_request = &(hdr->client_request);
m_url = m_client_request->url_get();
if (m_url) {
m_client_req_url_str = m_url->string_get_ref(&m_client_req_url_len);
m_client_req_url_canon_str = LogUtils::escapify_url(&m_arena,
m_client_req_url_str,
m_client_req_url_len,
&m_client_req_url_canon_len);
{noformat}
{noformat}
char *
LogUtils::escapify_url(Arena *arena, char *url, size_t len_in, int *len_out,
char *dst, size_t dst_size, const unsigned char *map)
{
// skipping some lines.....
// Count specials in the url, assuming that there won't be any.
//
int count = 0;
char *p = url;
char *in_url_end = url + len_in;
while (p < in_url_end) {
register unsigned char c = *p;
if (map[c / 8] & (1 << (7 - c % 8))) {
++count;
}
++p;
}
if (!count) {
// The common case, no escapes, so just return the source string.
//
*len_out = len_in;
if (dst)
ink_strlcpy(dst, url, dst_size);
return url;
}
{noformat}
2. At some point after init() happens the HdrHeap::coalesce_str_heaps function
gets called, and all the strings for the URL class get moved from the heap they
were originally in into a new heap, and their pointers get updated, except for
m_ptr_printed_string, and the pointers in the LogAccessHttp class.
{noformat}
void
URLImpl::move_strings(HdrStrHeap * new_heap)
{
HDR_MOVE_STR(m_ptr_scheme, m_len_scheme);
HDR_MOVE_STR(m_ptr_user, m_len_user);
HDR_MOVE_STR(m_ptr_password, m_len_password);
HDR_MOVE_STR(m_ptr_host, m_len_host);
HDR_MOVE_STR(m_ptr_port, m_len_port);
HDR_MOVE_STR(m_ptr_path, m_len_path);
HDR_MOVE_STR(m_ptr_params, m_len_params);
HDR_MOVE_STR(m_ptr_query, m_len_query);
HDR_MOVE_STR(m_ptr_fragment, m_len_fragment);
// HDR_MOVE_STR(m_ptr_printed_string, m_len_printed_string);
}
{noformat}
3. We now have a crash when we try to access the
LogAccessHttp::m_client_req_url_canon_str variable.
{noformat}
int
LogAccessHttp::marshal_client_req_url_canon(char *buf)
{
int len = round_strlen(m_client_req_url_canon_len + 1);
if (buf) {
// STC: m_client_req_url_canon_str is no good here :(
marshal_mem(buf, m_client_req_url_canon_str, m_client_req_url_canon_len,
len);
}
return len;
}
{noformat}
I will continue to investigate how this happens and try to think of some
possible fixes. If any of you have any helpful info, please share. :) Thanks!
> Seg fault when using %<cquuc>
> -----------------------------
>
> Key: TS-1411
> URL: https://issues.apache.org/jira/browse/TS-1411
> Project: Traffic Server
> Issue Type: Bug
> Components: Logging
> Affects Versions: 3.2.0
> Environment: RHEL 6.2 x86_64
> Reporter: David Carlin
> Assignee: Yunkai Zhang
> Priority: Critical
> Fix For: 4.2.0
>
> Attachments: Log rotation segaults.txt, TS-1411 backtraces.txt
>
>
> I've been experiencing some segfaults during log rotation. The sequence of
> events is this.. log rotation occurs, then I get hundreds of dropping log
> buffer error msgs, then the segfault.
> This started occurring when I lengthened the default log format to include
> the unmapped URL and the user agent string:
> %<cqtq> %<ttms> %<chi> %<crc>/%<pssc> %<psql> %<cqhm> %<cquc> %<caun>
> %<phr>/%<pqsn> %<psct> %<xid> %<cquuc> \"%<{User-Agent}cqh>\"
> In terms of frequency, we have a number of boxes and I probably see one of
> these crashed per day since the above change. Logs are rotated every 2 hours.
> I've had other log related segfaults, reported in TS-1330 - these new ones
> seem to have a different cause.
> [Aug 14 21:07:20.002] Server {0x2ae3a8887700} STATUS: The rolled logfile,
> /home/y/logs/trafficserver/error.log_l30.ycs.a4e.yahoo.com.20120814.17h59m50s-20120814.20h00m00s.old,
> was auto-deleted; 3148252 bytes were reclaimed.
> [Aug 14 21:07:42.859] Server {0x2ae3a8887700} STATUS: The rolled logfile,
> /home/y/logs/trafficserver/squid.blog_l30.ycs.a4e.yahoo.com.20120814.18h00m00s-20120814.20h00m00s.old,
> was auto-deleted; 14735520048 bytes were reclaimed.
> [Aug 14 21:07:42.865] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [Aug 14 21:07:42.865] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [Aug 14 21:07:42.865] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [Aug 14 21:07:42.865] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [Aug 14 21:07:42.865] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [...]
> [Aug 14 21:07:42.876] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [Aug 14 21:07:42.876] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [Aug 14 21:07:42.876] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> [Aug 14 21:07:42.876] Server {0x2ae3a8887700} WARNING: Dropping log buffer,
> can't keep up.
> NOTE: Traffic Server received Sig 11: Segmentation fault
> /home/y/bin/traffic_server - STACK TRACE:
> /lib64/libpthread.so.0[0x383f00f500]
> /home/y/bin/traffic_server(_ZN9LogAccess11marshal_memEPcPKcii+0x48)[0x58a118]
> /home/y/bin/traffic_server(_ZN13LogAccessHttp28marshal_client_req_url_canonEPc+0x20)[0x58c3f0]
> /home/y/bin/traffic_server(_ZN12LogFieldList7marshalEP9LogAccessPc+0x32)[0x59d5a2]
> /home/y/bin/traffic_server(_ZN9LogObject3logEP9LogAccessPc+0x399)[0x5a7ed9]
> /home/y/bin/traffic_server(_ZN3Log6accessEP9LogAccess+0x146)[0x58f506]
> /home/y/bin/traffic_server(_ZN6HttpSM12update_statsEv+0x630)[0x526c50]
> /home/y/bin/traffic_server(_ZN6HttpSM9kill_thisEv+0x928)[0x52b548]
> /home/y/bin/traffic_server(_ZN6HttpSM12main_handlerEiPv+0x198)[0x52b868]
> /home/y/bin/traffic_server(_ZN10HttpTunnel12main_handlerEiPv+0xde)[0x56c3ee]
> /home/y/bin/traffic_server[0x673871]
> /home/y/bin/traffic_server(_Z15write_to_net_ioP10NetHandlerP18UnixNetVConnectionP7EThread+0x847)[0x6756e7]
> /home/y/bin/traffic_server(_ZN10NetHandler12mainNetEventEiP5Event+0x286)[0x66e076]
> /home/y/bin/traffic_server(_ZN7EThread13process_eventEP5Eventi+0xb4)[0x696ce4]
> /home/y/bin/traffic_server(_ZN7EThread7executeEv+0x4c3)[0x697673]
> /home/y/bin/traffic_server[0x695cb2]
> /lib64/libpthread.so.0[0x383f007851]
--
This message was sent by Atlassian JIRA
(v6.1#6144)
