You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "Leif Hedstrom (JIRA)" <ji...@apache.org> on 2012/10/10 04:44:09 UTC
[jira] [Updated] (TS-1506) % log symbol will crash TS when
requesting a SSL url.
[ https://issues.apache.org/jira/browse/TS-1506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Leif Hedstrom updated TS-1506:
------------------------------
Fix Version/s: 3.3.2
> %<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.2
>
>
> 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