Conan Wang created TS-1506:
------------------------------
Summary: %<cquuh> log symbol will crash TS when requesting a SSL
url.
Key: TS-1506
URL: https://issues.apache.org/jira/browse/TS-1506
Project: Traffic Server
Issue Type: Bug
Components: Logging, SSL
Affects Versions: 3.2.3
Environment: OS X 10.8
Reporter: Conan Wang
cquuh (or cquuc, cquup) field symbol for logs_xml.config is introduced in
https://issues.apache.org/jira/browse/TS-1002. Requesting a normal url is OK.
If request a HTTPS url, TS will crash.
If log format contains %<cquuh>, TS will crash at logging phase.
{code}
[Sep 27 18:00:46.714] Server {0x103c04000} NOTE: cache enabled
[Sep 27 18:00:54.077] Server {0x108c06000} DEBUG: (ssl)
[SSLNextProtocolAccept:mainEvent] event 202 netvc 0x102065710
[Sep 27 18:00:54.078] Server {0x108c06000} DEBUG: (ssl) ssl=0x10470c240 ad=112
lookup=0x1007af780 server=wkl.me
[Sep 27 18:00:54.078] Server {0x108c06000} DEBUG: (ssl) found SSL context
0x101318fc0 for requested name 'wkl.me'
[Sep 27 18:00:54.078] Server {0x108c06000} DEBUG: (ssl) advertised NPN
sethttp/1.http/1.0
[Sep 27 18:00:54.082] Server {0x108c06000} DEBUG: (ssl)
SSLNetVConnection::sslServerHandShakeEvent, handshake completed successfully
[Sep 27 18:00:54.082] Server {0x108c06000} DEBUG: (ssl) client selected next
protocol http/1.1
[Sep 27 18:00:54.082] Server {0x108c06000} DEBUG: (ssl)
[SSLNextProtocolAccept:mainEvent] event 102 netvc 0x102065710
[Sep 27 18:00:54.099] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] b->write_avail()=4096
[Sep 27 18:00:54.099] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] rres=-1
[Sep 27 18:00:54.099] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_WOULD_BLOCK(read)
[Sep 27 18:00:54.099] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] bytes_read == 0
[Sep 27 18:00:54.099] Server {0x108c06000} DEBUG: (ssl) read_from_net, read
finished - would block
[Sep 27 18:00:54.114] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] b->write_avail()=4096
[Sep 27 18:00:54.114] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] rres=657
SSL Read
GET / HTTP/1.1
Host: wkl.me
Connection: keep-alive
Cache-Control: no-cache
Pragma: no-cache
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.4
(KHTML, like Gecko) Chrome/22.0.1229.79 Safari/537.4
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Encoding: gzip,deflate,sdch
Accept-Language: zh-CN,zh;q=0.8,en-US;q=0.6,en;q=0.4
Accept-Charset: GBK,utf-8;q=0.7,*;q=0.3
Cookie: __utma=113004674.1646024061.1302082154.1348645626.1348738067.49;
__utmb=113004674.99.10.1348738067; __utmc=113004674;
__utmz=113004674.1319557793.26.11.utmcsr=about.me|utmccn=(referral)|utmcmd=referral|utmcct=/wkl
[Sep 27 18:00:54.115] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] rres=-1
[Sep 27 18:00:54.115] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_WOULD_BLOCK(read)
[Sep 27 18:00:54.115] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] bytes_read=657
[Sep 27 18:00:54.115] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] b->write_avail()=3439
[Sep 27 18:00:54.131] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] rres=-1
[Sep 27 18:00:54.131] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_WOULD_BLOCK(read)
[Sep 27 18:00:54.131] Server {0x108c06000} DEBUG: (ssl)
[SSL_NetVConnection::ssl_read_from_net] bytes_read == 0
[Sep 27 18:00:54.133] Server {0x108c06000} DEBUG: (ssl) read_from_net, read
finished - would block
[Sep 27 18:00:54.351] Server {0x108c06000} DEBUG: (ssl)
SSLNetVConnection::loadBufferAndCallWrite, before do_SSL_write, l=302,
towrite=1061, b=0x103095340
[Sep 27 18:00:54.351] Server {0x108c06000} DEBUG: (ssl)
SSLNetVConnection::loadBufferAndCallWrite,Number of bytes written=302 ,
total=302
[Sep 27 18:00:54.351] Server {0x108c06000} DEBUG: (ssl)
SSLNetVConnection::loadBufferAndCallWrite, before do_SSL_write, l=759,
towrite=1061, b=0x103095300
[Sep 27 18:00:54.351] Server {0x108c06000} DEBUG: (ssl)
SSLNetVConnection::loadBufferAndCallWrite,Number of bytes written=759 ,
total=1061
[Sep 27 18:00:54.352] Server {0x108c06000} DEBUG: (ssl)
SSLNetVConnection::loadBufferAndCallWrite, write successful.
FATAL: LogAccess.cc:817: failed assert `actual_len < padded_len`
/Users/conan/develop/box/ts/bin/traffic_server - STACK TRACE:
0 libtsutil.3.dylib 0x0000000100bd0dd4 ink_fatal + 356
1 libtsutil.3.dylib 0x0000000100bce72c _ink_assert + 76
2 traffic_server 0x000000010019f36e
_ZN9LogAccess11marshal_memEPcPKcii + 108
3 traffic_server 0x00000001001a32d0
_ZN13LogAccessHttp36marshal_client_req_unmapped_url_hostEPc + 122
4 traffic_server 0x00000001001c2fef
_ZN8LogField7marshalEP9LogAccessPc + 155
5 traffic_server 0x00000001001c31ac
_ZN12LogFieldList7marshalEP9LogAccessPc + 88
6 traffic_server 0x00000001001d74a6
_ZN9LogObject3logEP9LogAccessPc + 2838
7 traffic_server 0x00000001001b2a01
_ZN16LogObjectManager3logEP9LogAccess + 73
8 traffic_server 0x00000001001a9a41
_ZN3Log6accessEP9LogAccess + 893
9 traffic_server 0x000000010010249f
_ZN6HttpSM12update_statsEv + 883
10 traffic_server 0x00000001001152f7
_ZN6HttpSM9kill_thisEv + 1039
11 traffic_server 0x0000000100115928
_ZN6HttpSM12main_handlerEiPv + 1126
12 traffic_server 0x0000000100060954
_ZN12Continuation11handleEventEiPv + 148
13 traffic_server 0x0000000100170f9c
_ZN10HttpTunnel12main_handlerEiPv + 460
14 traffic_server 0x0000000100060954
_ZN12Continuation11handleEventEiPv + 148
15 traffic_server 0x0000000100325354
_ZL23write_signal_and_updateiP18UnixNetVConnection + 100
16 traffic_server 0x0000000100325462
_ZL17write_signal_doneiP10NetHandlerP18UnixNetVConnection + 50
17 traffic_server 0x0000000100325ef3
_Z15write_to_net_ioP10NetHandlerP18UnixNetVConnectionP7EThread + 2547
18 traffic_server 0x0000000100326148
_Z12write_to_netP10NetHandlerP18UnixNetVConnectionP14PollDescriptorP7EThread +
168
19 traffic_server 0x000000010031864c
_ZN10NetHandler12mainNetEventEiP5Event + 3554
20 traffic_server 0x0000000100060954
_ZN12Continuation11handleEventEiPv + 148
21 traffic_server 0x000000010034d27a
_ZN7EThread13process_eventEP5Eventi + 370
22 traffic_server 0x000000010034cb45
_ZN7EThread7executeEv + 1311
23 traffic_server 0x000000010034bbd4
_ZL21spawn_thread_internalPv + 132
24 libsystem_c.dylib 0x00007fff880a2742 _pthread_start + 327
25 libsystem_c.dylib 0x00007fff8808f181 thread_start + 13
Program received signal SIGABRT, Aborted.
[Switching to process 3732 thread 0x2803]
0x00007fff879b1212 in __pthread_kill ()
(gdb) bt
#0 0x00007fff879b1212 in __pthread_kill ()
#1 0x00007fff880a3af4 in pthread_kill ()
#2 0x00007fff880e7dce in abort ()
#3 0x0000000100bcf7f0 in ink_die_die_die ()
#4 0x0000000100bd0ad5 in ink_fatal_va ()
#5 0x0000000100bd0dd4 in ink_fatal ()
#6 0x0000000100bce72c in _ink_assert ()
#7 0x000000010019f36e in LogAccess::marshal_mem ()
#8 0x00000001001a32d0 in LogAccessHttp::marshal_client_req_unmapped_url_host ()
#9 0x00000001001c2fef in LogField::marshal ()
#10 0x00000001001c31ac in LogFieldList::marshal ()
#11 0x00000001001d74a6 in LogObject::log ()
#12 0x00000001001b2a01 in LogObjectManager::log ()
#13 0x00000001001a9a41 in Log::access ()
#14 0x000000010010249f in HttpSM::update_stats ()
#15 0x00000001001152f7 in HttpSM::kill_this ()
#16 0x0000000100115928 in HttpSM::main_handler ()
#17 0x0000000100060954 in Continuation::handleEvent ()
#18 0x0000000100170f9c in HttpTunnel::main_handler ()
#19 0x0000000100060954 in Continuation::handleEvent ()
#20 0x0000000100325354 in write_signal_and_update ()
#21 0x0000000100325462 in write_signal_done ()
#22 0x0000000100325ef3 in write_to_net_io ()
#23 0x0000000100326148 in write_to_net ()
#24 0x000000010031864c in NetHandler::mainNetEvent ()
#25 0x0000000100060954 in Continuation::handleEvent ()
#26 0x000000010034d27a in EThread::process_event ()
#27 0x000000010034cb45 in EThread::execute ()
#28 0x000000010034bbd4 in spawn_thread_internal ()
#29 0x00007fff880a2742 in _pthread_start ()
#30 0x00007fff8808f181 in thread_start ()
{code}
If log format contains %<cquup> or %<cquuc>, crash message is like below. (can
reproduce by requesting a https url several times in parallel / pressing F5
quickly)
{code}
FATAL: ../../proxy/hdrs/URL.h:419: failed assert `valid()`
/Users/conan/develop/box/ts/bin/traffic_server - STACK TRACE:
0 libtsutil.3.dylib 0x0000000100bd0dd4 ink_fatal + 356
1 libtsutil.3.dylib 0x0000000100bce72c _ink_assert + 76
2 traffic_server 0x00000001001230f1
_ZN3URL14string_get_refEPi + 65
3 traffic_server 0x00000001001a31cb
_ZN13LogAccessHttp21validate_unmapped_urlEv + 77
4 traffic_server 0x00000001001a3302
_ZN13LogAccessHttp36marshal_client_req_unmapped_url_pathEPc + 28
5 traffic_server 0x00000001001c32c7
_ZN8LogField11marshal_lenEP9LogAccess + 157
6 traffic_server 0x00000001001c34a6
_ZN12LogFieldList11marshal_lenEP9LogAccess + 94
7 traffic_server 0x00000001001d7043
_ZN9LogObject3logEP9LogAccessPc + 1715
8 traffic_server 0x00000001001b2a01
_ZN16LogObjectManager3logEP9LogAccess + 73
9 traffic_server 0x00000001001a9a41
_ZN3Log6accessEP9LogAccess + 893
10 traffic_server 0x000000010010249f
_ZN6HttpSM12update_statsEv + 883
11 traffic_server 0x00000001001152f7
_ZN6HttpSM9kill_thisEv + 1039
12 traffic_server 0x0000000100115928
_ZN6HttpSM12main_handlerEiPv + 1126
13 traffic_server 0x0000000100060954
_ZN12Continuation11handleEventEiPv + 148
14 traffic_server 0x0000000100324564
_ZL22read_signal_and_updateiP18UnixNetVConnection + 100
15 traffic_server 0x00000001003246a2
_ZL16read_signal_doneiP10NetHandlerP18UnixNetVConnection + 50
16 traffic_server 0x0000000100324717
_ZN18UnixNetVConnection14readSignalDoneEiP10NetHandler + 45
17 traffic_server 0x000000010030ae44
_ZN17SSLNetVConnection11net_read_ioEP10NetHandlerP7EThread + 2308
18 traffic_server 0x000000010031852c
_ZN10NetHandler12mainNetEventEiP5Event + 3266
19 traffic_server 0x0000000100060954
_ZN12Continuation11handleEventEiPv + 148
20 traffic_server 0x000000010034d27a
_ZN7EThread13process_eventEP5Eventi + 370
21 traffic_server 0x000000010034cb45
_ZN7EThread7executeEv + 1311
22 traffic_server 0x000000010034bbd4
_ZL21spawn_thread_internalPv + 132
23 libsystem_c.dylib 0x00007fff880a2742 _pthread_start + 327
24 libsystem_c.dylib 0x00007fff8808f181 thread_start + 13
Program received signal SIGABRT, Aborted.
[Switching to process 3610 thread 0x2a03]
0x00007fff879b1212 in __pthread_kill ()
(gdb) bt
#0 0x00007fff879b1212 in __pthread_kill ()
#1 0x00007fff880a3af4 in pthread_kill ()
#2 0x00007fff880e7dce in abort ()
#3 0x0000000100bcf7f0 in ink_die_die_die ()
#4 0x0000000100bd0ad5 in ink_fatal_va ()
#5 0x0000000100bd0dd4 in ink_fatal ()
#6 0x0000000100bce72c in _ink_assert ()
#7 0x00000001001230f1 in URL::string_get_ref ()
#8 0x00000001001a31cb in LogAccessHttp::validate_unmapped_url ()
#9 0x00000001001a3302 in LogAccessHttp::marshal_client_req_unmapped_url_path ()
#10 0x00000001001c32c7 in LogField::marshal_len ()
#11 0x00000001001c34a6 in LogFieldList::marshal_len ()
#12 0x00000001001d7043 in LogObject::log ()
#13 0x00000001001b2a01 in LogObjectManager::log ()
#14 0x00000001001a9a41 in Log::access ()
#15 0x000000010010249f in HttpSM::update_stats ()
#16 0x00000001001152f7 in HttpSM::kill_this ()
#17 0x0000000100115928 in HttpSM::main_handler ()
#18 0x0000000100060954 in Continuation::handleEvent ()
#19 0x0000000100324564 in read_signal_and_update ()
#20 0x00000001003246a2 in read_signal_done ()
#21 0x0000000100324717 in UnixNetVConnection::readSignalDone ()
#22 0x000000010030ae44 in SSLNetVConnection::net_read_io ()
#23 0x000000010031852c in NetHandler::mainNetEvent ()
#24 0x0000000100060954 in Continuation::handleEvent ()
#25 0x000000010034d27a in EThread::process_event ()
#26 0x000000010034cb45 in EThread::execute ()
#27 0x000000010034bbd4 in spawn_thread_internal ()
#28 0x00007fff880a2742 in _pthread_start ()
#29 0x00007fff8808f181 in thread_start ()
{code}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
