[
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
