Traffic Server
  1. Traffic Server
  2. TS-1002

log unmapped HOST when pristine_host_hdr disabled

    Details

    • Type: New Feature New Feature
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 3.1.3
    • Component/s: Logging
    • Labels:
      None

      Description

      I want to log user request's "Host" in http header before remap. I write logs_xml.config, like: %<

      {Host}

      cqh>

      When proxy.config.url_remap.pristine_host_hdr is enabled, I will get the right "Host" which is not rewritten.

      When disable the config, I always get the rewritten/mapped "Host" which is not what I need.

      logs_xml reference: http://trafficserver.apache.org/docs/v2/admin/logfmts.htm#66912

      1. TS-1002.patch
        7 kB
        Zhao Yongming

        Activity

        Hide
        Leif Hedstrom added a comment -

        This is unfortunately how it works (currently). I'm thinkign, we might want to make a copy of the "pristine" request header object before remapping, clean out all the code around logging the pristine data, and add another directive to logging to get components out of this (new) pristine host header object.

        Moving this out to 3.1.4 for now.

        Show
        Leif Hedstrom added a comment - This is unfortunately how it works (currently). I'm thinkign, we might want to make a copy of the "pristine" request header object before remapping, clean out all the code around logging the pristine data, and add another directive to logging to get components out of this (new) pristine host header object. Moving this out to 3.1.4 for now.
        Hide
        Zhao Yongming added a comment -

        I think this is fixed in the git master?

        zymtest1 trafficserver # tail -n 100 taobaomiss.log
        00:40:39 127.0.0.1 fe80::746d:74ff:febf:ebaa 428 200 TCP_MISS "http://cdn.zymlinux.net/trafficserver/0" 411 402 0 text/plain http://zymlinux.net/trafficserver/0 "-"
        00:40:39 127.0.0.1 fe80::746d:74ff:febf:ebaa 475 200 TCP_MISS "http://cdn.zymlinux.net/trafficserver/ts75.png" 418 404 9520 image/png http://zymlinux.net/trafficserver/ts75.png "-"
        00:42:42 127.0.0.1 fe80::746d:74ff:febf:ebaa 54 200 TCP_REFRESH_HIT "http://cdn.zymlinux.net/trafficserver/ts75.png" 418 404 9520 image/png http://zymlinux.net/trafficserver/ts75.png "-"
        00:42:42 127.0.0.1 fe80::746d:74ff:febf:ebaa 53 200 TCP_MISS "http://cdn.zymlinux.net/trafficserver/0" 411 402 0 text/plain http://zymlinux.net/trafficserver/0 "-"
        zymtest1 trafficserver # traffic_line -r proxy.config.url_remap.pristine_host_hdr
        0
        zymtest1 trafficserver # grep cdn.zymlinux.net /etc/trafficserver/remap.config
        map http://cdn.zymlinux.net/    http://zymlinux.net
        zymtest1 trafficserver # 
        
        Show
        Zhao Yongming added a comment - I think this is fixed in the git master? zymtest1 trafficserver # tail -n 100 taobaomiss.log 00:40:39 127.0.0.1 fe80::746d:74ff:febf:ebaa 428 200 TCP_MISS "http: //cdn.zymlinux.net/trafficserver/0" 411 402 0 text/plain http://zymlinux.net/trafficserver/0 "-" 00:40:39 127.0.0.1 fe80::746d:74ff:febf:ebaa 475 200 TCP_MISS "http: //cdn.zymlinux.net/trafficserver/ts75.png" 418 404 9520 image/png http://zymlinux.net/trafficserver/ts75.png "-" 00:42:42 127.0.0.1 fe80::746d:74ff:febf:ebaa 54 200 TCP_REFRESH_HIT "http: //cdn.zymlinux.net/trafficserver/ts75.png" 418 404 9520 image/png http://zymlinux.net/trafficserver/ts75.png "-" 00:42:42 127.0.0.1 fe80::746d:74ff:febf:ebaa 53 200 TCP_MISS "http: //cdn.zymlinux.net/trafficserver/0" 411 402 0 text/plain http://zymlinux.net/trafficserver/0 "-" zymtest1 trafficserver # traffic_line -r proxy.config.url_remap.pristine_host_hdr 0 zymtest1 trafficserver # grep cdn.zymlinux.net /etc/trafficserver/remap.config map http: //cdn.zymlinux.net/ http://zymlinux.net zymtest1 trafficserver #
        Hide
        Conan Wang added a comment -

        not fix in my test.

        CONFIG proxy.config.url_remap.pristine_host_hdr INT 0
        map http://cdn.zymlinux.net http://zymlinux.net

        squid.log
        1330668375.573 119 127.0.0.1 TCP_MISS/200 9821 GET http://zymlinux.net/trafficserver/ts75.png - DIRECT/zymlinux.net image/png -

        custom.log ( first field is %<

        {Host}

        cqh> )
        zymlinux.net - 0 TCP_MISS [02/Mar/2012:14:06:15 +0800] "GET /trafficserver/ts75.png HTTP/1.1" 200 9520 "" "" "curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8r zlib/1.2.5"

        Show
        Conan Wang added a comment - not fix in my test. CONFIG proxy.config.url_remap.pristine_host_hdr INT 0 map http://cdn.zymlinux.net http://zymlinux.net squid.log 1330668375.573 119 127.0.0.1 TCP_MISS/200 9821 GET http://zymlinux.net/trafficserver/ts75.png - DIRECT/zymlinux.net image/png - custom.log ( first field is %< {Host} cqh> ) zymlinux.net - 0 TCP_MISS [02/Mar/2012:14:06:15 +0800] "GET /trafficserver/ts75.png HTTP/1.1" 200 9520 " " " " "curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8r zlib/1.2.5"
        Hide
        Zhao Yongming added a comment -

        I have create a new cquuh ( client_req_unmapped_url_host ), which is what your needs, this patch will apply to git master

        config:
        <Format = "%<cquuc> %<cquup> %<cquuh>" />
        result:
        http://cdn.zymlinux.net/trafficserver/ts75.png /trafficserver/ts75.png cdn.zymlinux.net

        please test & review

        Show
        Zhao Yongming added a comment - I have create a new cquuh ( client_req_unmapped_url_host ), which is what your needs, this patch will apply to git master config: <Format = "%<cquuc> %<cquup> %<cquuh>" /> result: http://cdn.zymlinux.net/trafficserver/ts75.png /trafficserver/ts75.png cdn.zymlinux.net please test & review
        Hide
        Conan Wang added a comment -

        %<cquuh> works, thanks!

        cdn.zymlinux.net - 0 TCP_MISS [03/Mar/2012:15:38:47 +0800] "GET /trafficserver/ts75.png HTTP/1.1" 200 9520 "" "" "curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8r zlib/1.2.5"

        Show
        Conan Wang added a comment - %<cquuh> works, thanks! cdn.zymlinux.net - 0 TCP_MISS [03/Mar/2012:15:38:47 +0800] "GET /trafficserver/ts75.png HTTP/1.1" 200 9520 " " " " "curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8r zlib/1.2.5"
        Hide
        Conan Wang added a comment -

        btw, I didn't find a symbol which log url path with querystring before. like /trafficserver/ts75.png?version=1

        And your "cquup" can do this now. Is this new symbol on trunk?

        Show
        Conan Wang added a comment - btw, I didn't find a symbol which log url path with querystring before. like /trafficserver/ts75.png?version=1 And your "cquup" can do this now. Is this new symbol on trunk?
        Hide
        Leif Hedstrom added a comment -

        Can this bug be closed ?

        Show
        Leif Hedstrom added a comment - Can this bug be closed ?
        Hide
        Leif Hedstrom added a comment -

        Also, I'm not seeing a note in CHANGES, is this code not committed ?

        Show
        Leif Hedstrom added a comment - Also, I'm not seeing a note in CHANGES, is this code not committed ?
        Hide
        Zhao Yongming added a comment -

        git hash: 8a06dc143aa66e2da15993c9fe90e9c0f97846c4

        reopen if we need to backport

        Show
        Zhao Yongming added a comment - git hash: 8a06dc143aa66e2da15993c9fe90e9c0f97846c4 reopen if we need to backport
        Hide
        Conan Wang added a comment -

        docs need mention that 'cquup' also logs querystring.

        Show
        Conan Wang added a comment - docs need mention that 'cquup' also logs querystring.
        Hide
        Conan Wang added a comment -

        I'm trying to backport to 3.0.4. got assert error when request.

        FATAL: LogAccess.cc:794: failed assert `actual_len < padded_len`
        /box/ts-3.0.4/bin/traffic_server - STACK TRACE: 
        0   libtsutil.3.dylib                   0x0000000100d2924b ink_fatal_va + 283
        1   libtsutil.3.dylib                   0x0000000100d29554 ink_fatal + 356
        2   libtsutil.3.dylib                   0x0000000100d268cf _ink_assert + 271
        3   traffic_server                      0x00000001001b9c90 _ZN9LogAccess11marshal_memEPcPKcii + 108
        4   traffic_server                      0x00000001001bd848 _ZN13LogAccessHttp36marshal_client_req_unmapped_url_hostEPc + 122
        5   traffic_server                      0x00000001001e2d7b _ZN8LogField7marshalEP9LogAccessPc + 155
        6   traffic_server                      0x00000001001e2f30 _ZN12LogFieldList7marshalEP9LogAccessPc + 88
        7   traffic_server                      0x00000001001fb45b _ZN9LogObject3logEP9LogAccessPc + 3783
        8   traffic_server                      0x00000001001cff91 _ZN16LogObjectManager3logEP9LogAccess + 73
        9   traffic_server                      0x00000001001c5f48 _ZN3Log6accessEP9LogAccess + 1316
        10  traffic_server                      0x0000000100116bc4 _ZN6HttpSM12update_statsEv + 834
        11  traffic_server                      0x000000010012944a _ZN6HttpSM9kill_thisEv + 1042
        12  traffic_server                      0x0000000100129aa7 _ZN6HttpSM12main_handlerEiPv + 1205
        13  traffic_server                      0x000000010005cc84 _ZN12Continuation11handleEventEiPv + 148
        14  traffic_server                      0x0000000100184044 _ZN10HttpTunnel12main_handlerEiPv + 460
        15  traffic_server                      0x000000010005cc84 _ZN12Continuation11handleEventEiPv + 148
        16  traffic_server                      0x000000010036a2c4 _ZL23write_signal_and_updateiP18UnixNetVConnection + 100
        17  traffic_server                      0x000000010036a3d2 _ZL17write_signal_doneiP10NetHandlerP18UnixNetVConnection + 50
        18  traffic_server                      0x000000010036ae91 _Z15write_to_net_ioP10NetHandlerP18UnixNetVConnectionP7EThread + 2593
        19  traffic_server                      0x000000010036b0e8 _Z12write_to_netP10NetHandlerP18UnixNetVConnectionP14PollDescriptorP7EThread + 168
        20  traffic_server                      0x000000010035cd34 _ZN10NetHandler12mainNetEventEiP5Event + 4346
        21  traffic_server                      0x000000010005cc84 _ZN12Continuation11handleEventEiPv + 148
        22  traffic_server                      0x000000010039145a _ZN7EThread13process_eventEP5Eventi + 418
        23  traffic_server                      0x0000000100390cab _ZN7EThread7executeEv + 1311
        24  traffic_server                      0x000000010038fc74 _ZL21spawn_thread_internalPv + 132
        25  libsystem_c.dylib                   0x00007fff89dfe8bf _pthread_start + 335
        26  libsystem_c.dylib                   0x00007fff89e01b75 thread_start + 13
        
        Program received signal SIGABRT, Aborted.
        [Switching to process 14628 thread 0x2803]
        0x00007fff90895ce2 in __pthread_kill ()
        (gdb) bt
        #0  0x00007fff90895ce2 in __pthread_kill ()
        #1  0x00007fff89e007d2 in pthread_kill ()
        #2  0x00007fff89df1a7a in abort ()
        #3  0x0000000100d27f70 in ink_die_die_die (retval=1) at ink_error.cc:43
        #4  0x0000000100d29255 in ink_fatal_va (return_code=1, message_format=0x103d0950c "LogAccess.cc:794: failed assert `actual_len < padded_len`", ap=0x103d09498) at ink_error.cc:65
        #5  0x0000000100d29554 in ink_fatal (return_code=1, message_format=0x103d0950c "LogAccess.cc:794: failed assert `actual_len < padded_len`") at ink_error.cc:73
        #6  0x0000000100d268cf in _ink_assert (a=0x1003e2532 "actual_len < padded_len", f=0x1003e23b8 "LogAccess.cc", l=794) at ink_assert.cc:44
        #7  0x00000001001b9c90 in LogAccess::marshal_mem (dest=0x108c4f910 "", source=0x1003e2530 "-", actual_len=1, padded_len=0) at LogAccess.cc:794
        #8  0x00000001001bd848 in LogAccessHttp::marshal_client_req_unmapped_url_host (this=0x103d0a328, buf=0x108c4f910 "") at LogAccessHttp.cc:369
        #9  0x00000001001e2d7b in LogField::marshal (this=0x10128c8e0, lad=0x103d0a328, buf=0x108c4f910 "") at LogField.cc:216
        #10 0x00000001001e2f30 in LogFieldList::marshal (this=0x10128be80, lad=0x103d0a328, buf=0x108c4f910 "") at LogField.cc:493
        #11 0x00000001001fb45b in LogObject::log (this=0x108c51e00, lad=0x103d0a328, text_entry=0x0) at LogObject.cc:568
        #12 0x00000001001cff91 in LogObjectManager::log (this=0x101247040, lad=0x103d0a328) at LogObject.h:485
        #13 0x00000001001c5f48 in Log::access (lad=0x103d0a328) at Log.cc:1063
        #14 0x0000000100116bc4 in HttpSM::update_stats (this=0x109d41190) at HttpSM.cc:6044
        #15 0x000000010012944a in HttpSM::kill_this (this=0x109d41190) at HttpSM.cc:6005
        #16 0x0000000100129aa7 in HttpSM::main_handler (this=0x109d41190, event=2301, data=0x109d42e80) at HttpSM.cc:2452
        #17 0x000000010005cc84 in Continuation::handleEvent (this=0x109d41190, event=2301, data=0x109d42e80) at I_Continuation.h:146
        #18 0x0000000100184044 in HttpTunnel::main_handler (this=0x109d42e80, event=103, data=0x102094058) at HttpTunnel.cc:1468
        #19 0x000000010005cc84 in Continuation::handleEvent (this=0x109d42e80, event=103, data=0x102094058) at I_Continuation.h:146
        #20 0x000000010036a2c4 in write_signal_and_update (event=103, vc=0x102093e20) at UnixNetVConnection.cc:153
        #21 0x000000010036a3d2 in write_signal_done (event=103, nh=0x102e06618, vc=0x102093e20) at UnixNetVConnection.cc:180
        #22 0x000000010036ae91 in write_to_net_io (nh=0x102e06618, vc=0x102093e20, thread=0x102e05000) at UnixNetVConnection.cc:479
        #23 0x000000010036b0e8 in write_to_net (nh=0x102e06618, vc=0x102093e20, pd=0x104820000, thread=0x102e05000) at UnixNetVConnection.cc:352
        #24 0x000000010035cd34 in NetHandler::mainNetEvent (this=0x102e06618, event=5, e=0x102020d20) at UnixNet.cc:405
        #25 0x000000010005cc84 in Continuation::handleEvent (this=0x102e06618, event=5, data=0x102020d20) at I_Continuation.h:146
        #26 0x000000010039145a in EThread::process_event (this=0x102e05000, e=0x102020d20, calling_code=5) at UnixEThread.cc:140
        #27 0x0000000100390cab in EThread::execute (this=0x102e05000) at UnixEThread.cc:262
        #28 0x000000010038fc74 in spawn_thread_internal (a=0x10150c5e0) at Thread.cc:88
        #29 0x00007fff89dfe8bf in _pthread_start ()
        #30 0x00007fff89e01b75 in thread_start ()
        
        Show
        Conan Wang added a comment - I'm trying to backport to 3.0.4. got assert error when request. FATAL: LogAccess.cc:794: failed assert `actual_len < padded_len` /box/ts-3.0.4/bin/traffic_server - STACK TRACE: 0 libtsutil.3.dylib 0x0000000100d2924b ink_fatal_va + 283 1 libtsutil.3.dylib 0x0000000100d29554 ink_fatal + 356 2 libtsutil.3.dylib 0x0000000100d268cf _ink_assert + 271 3 traffic_server 0x00000001001b9c90 _ZN9LogAccess11marshal_memEPcPKcii + 108 4 traffic_server 0x00000001001bd848 _ZN13LogAccessHttp36marshal_client_req_unmapped_url_hostEPc + 122 5 traffic_server 0x00000001001e2d7b _ZN8LogField7marshalEP9LogAccessPc + 155 6 traffic_server 0x00000001001e2f30 _ZN12LogFieldList7marshalEP9LogAccessPc + 88 7 traffic_server 0x00000001001fb45b _ZN9LogObject3logEP9LogAccessPc + 3783 8 traffic_server 0x00000001001cff91 _ZN16LogObjectManager3logEP9LogAccess + 73 9 traffic_server 0x00000001001c5f48 _ZN3Log6accessEP9LogAccess + 1316 10 traffic_server 0x0000000100116bc4 _ZN6HttpSM12update_statsEv + 834 11 traffic_server 0x000000010012944a _ZN6HttpSM9kill_thisEv + 1042 12 traffic_server 0x0000000100129aa7 _ZN6HttpSM12main_handlerEiPv + 1205 13 traffic_server 0x000000010005cc84 _ZN12Continuation11handleEventEiPv + 148 14 traffic_server 0x0000000100184044 _ZN10HttpTunnel12main_handlerEiPv + 460 15 traffic_server 0x000000010005cc84 _ZN12Continuation11handleEventEiPv + 148 16 traffic_server 0x000000010036a2c4 _ZL23write_signal_and_updateiP18UnixNetVConnection + 100 17 traffic_server 0x000000010036a3d2 _ZL17write_signal_doneiP10NetHandlerP18UnixNetVConnection + 50 18 traffic_server 0x000000010036ae91 _Z15write_to_net_ioP10NetHandlerP18UnixNetVConnectionP7EThread + 2593 19 traffic_server 0x000000010036b0e8 _Z12write_to_netP10NetHandlerP18UnixNetVConnectionP14PollDescriptorP7EThread + 168 20 traffic_server 0x000000010035cd34 _ZN10NetHandler12mainNetEventEiP5Event + 4346 21 traffic_server 0x000000010005cc84 _ZN12Continuation11handleEventEiPv + 148 22 traffic_server 0x000000010039145a _ZN7EThread13process_eventEP5Eventi + 418 23 traffic_server 0x0000000100390cab _ZN7EThread7executeEv + 1311 24 traffic_server 0x000000010038fc74 _ZL21spawn_thread_internalPv + 132 25 libsystem_c.dylib 0x00007fff89dfe8bf _pthread_start + 335 26 libsystem_c.dylib 0x00007fff89e01b75 thread_start + 13 Program received signal SIGABRT, Aborted. [Switching to process 14628 thread 0x2803] 0x00007fff90895ce2 in __pthread_kill () (gdb) bt #0 0x00007fff90895ce2 in __pthread_kill () #1 0x00007fff89e007d2 in pthread_kill () #2 0x00007fff89df1a7a in abort () #3 0x0000000100d27f70 in ink_die_die_die (retval=1) at ink_error.cc:43 #4 0x0000000100d29255 in ink_fatal_va (return_code=1, message_format=0x103d0950c "LogAccess.cc:794: failed assert `actual_len < padded_len`" , ap=0x103d09498) at ink_error.cc:65 #5 0x0000000100d29554 in ink_fatal (return_code=1, message_format=0x103d0950c "LogAccess.cc:794: failed assert `actual_len < padded_len`" ) at ink_error.cc:73 #6 0x0000000100d268cf in _ink_assert (a=0x1003e2532 "actual_len < padded_len" , f=0x1003e23b8 "LogAccess.cc" , l=794) at ink_assert.cc:44 #7 0x00000001001b9c90 in LogAccess::marshal_mem (dest=0x108c4f910 "", source=0x1003e2530 " -", actual_len=1, padded_len=0) at LogAccess.cc:794 #8 0x00000001001bd848 in LogAccessHttp::marshal_client_req_unmapped_url_host ( this =0x103d0a328, buf=0x108c4f910 "") at LogAccessHttp.cc:369 #9 0x00000001001e2d7b in LogField::marshal ( this =0x10128c8e0, lad=0x103d0a328, buf=0x108c4f910 "") at LogField.cc:216 #10 0x00000001001e2f30 in LogFieldList::marshal ( this =0x10128be80, lad=0x103d0a328, buf=0x108c4f910 "") at LogField.cc:493 #11 0x00000001001fb45b in LogObject::log ( this =0x108c51e00, lad=0x103d0a328, text_entry=0x0) at LogObject.cc:568 #12 0x00000001001cff91 in LogObjectManager::log ( this =0x101247040, lad=0x103d0a328) at LogObject.h:485 #13 0x00000001001c5f48 in Log::access (lad=0x103d0a328) at Log.cc:1063 #14 0x0000000100116bc4 in HttpSM::update_stats ( this =0x109d41190) at HttpSM.cc:6044 #15 0x000000010012944a in HttpSM::kill_this ( this =0x109d41190) at HttpSM.cc:6005 #16 0x0000000100129aa7 in HttpSM::main_handler ( this =0x109d41190, event=2301, data=0x109d42e80) at HttpSM.cc:2452 #17 0x000000010005cc84 in Continuation::handleEvent ( this =0x109d41190, event=2301, data=0x109d42e80) at I_Continuation.h:146 #18 0x0000000100184044 in HttpTunnel::main_handler ( this =0x109d42e80, event=103, data=0x102094058) at HttpTunnel.cc:1468 #19 0x000000010005cc84 in Continuation::handleEvent ( this =0x109d42e80, event=103, data=0x102094058) at I_Continuation.h:146 #20 0x000000010036a2c4 in write_signal_and_update (event=103, vc=0x102093e20) at UnixNetVConnection.cc:153 #21 0x000000010036a3d2 in write_signal_done (event=103, nh=0x102e06618, vc=0x102093e20) at UnixNetVConnection.cc:180 #22 0x000000010036ae91 in write_to_net_io (nh=0x102e06618, vc=0x102093e20, thread=0x102e05000) at UnixNetVConnection.cc:479 #23 0x000000010036b0e8 in write_to_net (nh=0x102e06618, vc=0x102093e20, pd=0x104820000, thread=0x102e05000) at UnixNetVConnection.cc:352 #24 0x000000010035cd34 in NetHandler::mainNetEvent ( this =0x102e06618, event=5, e=0x102020d20) at UnixNet.cc:405 #25 0x000000010005cc84 in Continuation::handleEvent ( this =0x102e06618, event=5, data=0x102020d20) at I_Continuation.h:146 #26 0x000000010039145a in EThread::process_event ( this =0x102e05000, e=0x102020d20, calling_code=5) at UnixEThread.cc:140 #27 0x0000000100390cab in EThread::execute ( this =0x102e05000) at UnixEThread.cc:262 #28 0x000000010038fc74 in spawn_thread_internal (a=0x10150c5e0) at Thread .cc:88 #29 0x00007fff89dfe8bf in _pthread_start () #30 0x00007fff89e01b75 in thread_start ()

          People

          • Assignee:
            Zhao Yongming
            Reporter:
            Conan Wang
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development