[ https://issues.apache.org/jira/browse/TS-1506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Conan Wang updated TS-1506: --------------------------- Attachment: TS-1506.patch Can not reproduce the crash on git master, but the output is still not correct. Attached patch make 'cquuh' and 'cquup' work if request is valid. > %<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 > Fix For: 3.3.3 > > Attachments: TS-1506.patch > > > 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