With AddressSanitizer enabled trafficserver fails to come up

[dnj12345]

When trying to start traffic-server, built with '--enable-asan' option, traffic-server fails to come up. I see the following dump in the traffic.out file...

=================================================================
==648==ERROR: AddressSanitizer: stack-buffer-overflow on address 0x7ffed5021470 at pc 0x7ff98638e904 bp 0x7ffed5021360 sp 0x7ffed5020b08
WRITE of size 4 at 0x7ffed5021470 thread T0
    #0 0x7ff98638e903 in __asan_memcpy (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x8c903)
    #1 0x55d15c in std::char_traits<char>::copy(char*, char const*, unsigned long) /usr/include/c++/5/bits/char_traits.h:290
    #2 0x55d15c in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_S_copy(char*, char const*, unsigned long) /usr/include/c++/5/bits/basic_string.h:299
    #3 0x55d15c in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_S_copy_chars(char*, char const*, char const*) /usr/include/c++/5/bits/basic_string.h:346
    #4 0x55d15c in void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char const*>(char const*, char const*, std::forward_iterator_tag) /usr/include/c++/5/bits/basic_string.tcc:229
    #5 0x55d15c in void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct_aux<char const*>(char const*, char const*, std::__false_type) /usr/include/c++/5/bits/basic_string.h:195
    #6 0x55d15c in void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char const*>(char const*, char const*) /usr/include/c++/5/bits/basic_string.h:214
    #7 0x55d15c in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(char const*, unsigned long, std::allocator<char> const&) /usr/include/c++/5/bits/basic_string.h:447
    #8 0x55d15c in metrics_index /root/ts-source/trafficserver-7.1.6/lib/bindings/metrics.cc:102
    #9 0x577795 in lj_BC_FUNCC (/opt/trafficserver/bin/traffic_manager+0x577795)
    #10 0x56718f in lua_pcall (/opt/trafficserver/bin/traffic_manager+0x56718f)
    #11 0x440524 in Evaluator::eval(lua_State*) const /root/ts-source/trafficserver-7.1.6/cmd/traffic_manager/metrics.cc:98
    #12 0x440524 in EvaluatorList::evaluate(lua_State*) const /root/ts-source/trafficserver-7.1.6/cmd/traffic_manager/metrics.cc:175
    #13 0x440524 in metrics_binding_evaluate(BindingInstance&) /root/ts-source/trafficserver-7.1.6/cmd/traffic_manager/metrics.cc:410
    #14 0x432296 in main /root/ts-source/trafficserver-7.1.6/cmd/traffic_manager/traffic_manager.cc:777
    #15 0x7ff98417082f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)
    #16 0x4352c8 in _start (/opt/trafficserver/bin/traffic_manager+0x4352c8)

OS: Ubuntu 16.04
ATS Version: 7.1.6

[randall]

@dnj12345 Is this with the default configs? Do you have changes in metrics.config?

[zwoop]

Yeh, I assume in this case, "key" is a nullptr ? Which seems odd on its own, but maybe a bug in the Lua script? Although, then the assert above should have tripped ...

[dnj12345]

Looking at the metrics.cc, there’s a check for nullptr just before the crash line. @randall, I was using default metrics config. I had my custom plugin and http_stats_plugin. Did not have anything else. Dk.

…

On Jun 4, 2019, at 12:38 PM, Leif Hedstrom ***@***.***> wrote: Yeh, I assume in this case, "key" is a nullptr ? Which seems odd on its own, but maybe a bug in the Lua script? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[randall]

I built 7.1.6 and 7.1.7 with ASAN on the Ubuntu 16.04 CI docker image and could not repro the crash.

Does the crash occur with the plugin disabled?

[dnj12345]

It happens with or without any plugins enabled.

BTW, here's how I built it:

> autoreconf -if
> configure --prefix=/opt/trafficserver --enable-cppapi --enable-asan
> make install

Here's some additional dump info that was logged in traffic.out..

Address 0x7fff752aee60 is located in stack of thread T0 at offset 176 in frame
    #0 0x55cfcf in metrics_index /root/ts-source/trafficserver-7.1.6/lib/bindings/metrics.cc:91

  This frame has 3 object(s):
    [32, 40) 'len'
    [96, 104) '__dnew'
    [160, 192) '<unknown>' <== Memory access at offset 176 is inside this variable
HINT: this may be a false positive if your program uses some custom stack unwind mechanism or swapcontext
      (longjmp and C++ exceptions *are* supported)
SUMMARY: AddressSanitizer: stack-buffer-overflow ??:0 __asan_memcpy
Shadow bytes around the buggy address:
  0x10006ea4dd70: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x10006ea4dd80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x10006ea4dd90: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x10006ea4dda0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x10006ea4ddb0: 00 00 00 00 00 00 f1 f1 f1 f1 00 f4 f4 f4 f2 f2
=>0x10006ea4ddc0: f2 f2 00 f4 f4 f4 f2 f2 f2 f2 00 00[f2]f2 f3 f3
  0x10006ea4ddd0: f3 f3 f3 f3 f3 f3 00 00 00 00 00 00 00 00 00 00
  0x10006ea4dde0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x10006ea4ddf0: 00 00 00 00 00 00 00 00 00 00 f1 f1 f1 f1 00 f4
  0x10006ea4de00: f4 f4 f2 f2 f2 f2 00 00 f4 f4 f2 f2 f2 f2 00 00
  0x10006ea4de10: 00 f4 f3 f3 f3 f3 00 00 00 00 00 00 00 00 00 00
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07
  Heap left redzone:       fa
  Heap right redzone:      fb
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack partial redzone:   f4
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
==323==ABORTING
root@15b9de7d5dac:/opt/trafficserver/var/log/trafficserver#

[dnj12345]

ok. This is weird...

I was looking into it again... noticed that there were multiple config files in my config directory. For most configs, there were three files: x.config, x.config.default, x.config_1 and some had only two (no default).

I remembered Randall's question about default configs. Sure enough, metric.config had three files as well. So I copied metric.config.default to metric.config and trafficserver came up fine. It came up fine with and without plugins.

I am not sure how I got the original metric.config (I am doing simple 'make install'). I've pasted the diff of the original metric.config (that wasn't working) against the default metric.config. Hopefully, that'll shed some light on the issue...

--- metrics.config.default	2019-05-28 23:13:29.000000000 +0000
+++ metrics.config.old	2019-06-05 06:26:20.285484641 +0000
@@ -47,7 +47,7 @@
 --
 -- integer(NAME, FUNC), counter(NAME, FUNC), float(NAME, FUNC)
 --    These global functions register a metric of the corresponding name. Each
---    registered metric will be periodically recalculated by evaluating the
+--    registered metric will be periodically recalculated by evaluating the
 --    given function.
 --
 --    The scope of a metric is derived from the name. 'proxy.cluster.*' metrics
@@ -341,7 +341,7 @@ integer 'proxy.node.http.user_agent_xact
   )
 ]]

-integer'proxy.cluster.http.user_agent_xacts_per_second' [[
+integer 'proxy.cluster.http.user_agent_xacts_per_second' [[
   return cluster('proxy.node.http.user_agent_xacts_per_second')
 ]]

@@ -455,6 +455,14 @@ counter 'proxy.cluster.http.origin_serve
   return cluster('proxy.node.http.origin_server_total_response_bytes')
 ]]

+counter 'proxy.node.http.parent_proxy_total_request_bytes' [[
+  return cluster('proxy.process.http.parent_proxy_request_total_bytes')
+]]
+
+counter 'proxy.node.http.parent_proxy_total_response_bytes' [[
+  return cluster('proxy.process.http.parent_proxy_response_total_bytes')
+]]
+
 -- Add up the downstream (client <-> proxy) traffic volume.
 counter 'proxy.node.user_agent_total_bytes' [[
   return proxy.node.http.user_agent_total_request_bytes +
@@ -521,10 +529,6 @@ float 'proxy.cluster.bandwidth_hit_ratio
   ) / cluster('proxy.node.user_agent_total_bytes_avg_10s')
 ]]

-integer 'proxy.node.bandwidth_hit_ratio_avg_10s_int_pct' [[
-  return proxy.node.bandwidth_hit_ratio_avg_10s * 100
-]]
-
 -- StatAggregation::Ag_Throughput()
 integer 'proxy.node.http.throughput' [[
   local self = ...
@@ -696,14 +700,6 @@ float 'proxy.cluster.cache_hit_mem_ratio
     )
 ]]

-integer 'proxy.node.cache_hit_ratio_avg_10s_int_pct' [[
-  return proxy.node.cache_hit_ratio_avg_10s * 100
-]]
-
-integer 'proxy.node.cache_hit_mem_ratio_avg_10s_int_pct' [[
-  return proxy.node.cache_hit_mem_ratio_avg_10s * 100
-]]
-
 counter 'proxy.node.cache_total_hits' [[
   return proxy.process.http.cache_hit_fresh +
     proxy.process.http.cache_hit_revalidated +
@@ -1085,50 +1081,6 @@ float 'proxy.node.http.transaction_frac_
     end)
 ]]

-integer 'proxy.node.http.transaction_frac_avg_10s.hit_fresh_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.hit_fresh * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.miss_cold_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.miss_cold * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.hit_revalidated_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.hit_revalidated * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.miss_changed_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.miss_changed * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.miss_client_no_cache_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.miss_client_no_cache * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.miss_not_cacheable_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.miss_not_cacheable * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.errors.connect_failed_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.errors.connect_failed * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.errors.aborts_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.errors.aborts * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.errors.possible_aborts_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.errors.possible_aborts * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.errors.pre_accept_hangups_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.errors.pre_accept_hangups * 100
-]]
-
-integer 'proxy.node.http.transaction_frac_avg_10s.errors.other_int_pct' [[
-  return proxy.node.http.transaction_frac_avg_10s.errors.other * 100
-]]
-
 integer 'proxy.node.http.transaction_msec_avg_10s.hit_fresh' [[
   local self = ...
   return interval_of_10s(self, function()
@@ -1431,46 +1383,8 @@ integer 'proxy.cluster.client_throughput
   return cluster('proxy.node.client_throughput_out_kbit')
 ]]

--- If proxy.node.cache_hit_ratio represents 100% as 1.0, this
--- represents it as 100.
-integer 'proxy.node.cache_hit_ratio_int_pct' [[
-    return proxy.node.cache_hit_ratio * 100
-]]
-
-integer 'proxy.cluster.cache_hit_ratio_int_pct' [[
-  return proxy.cluster.cache_hit_ratio * 100
-]]
-
-integer 'proxy.node.cache_hit_mem_ratio_int_pct' [[
-  return proxy.node.cache_hit_mem_ratio * 100
-]]
-
-integer 'proxy.cluster.cache_hit_mem_ratio_int_pct' [[
-  return proxy.node.cache_hit_mem_ratio * 100
-]]
-
-integer 'proxy.node.bandwidth_hit_ratio_int_pct' [[
-  return proxy.node.bandwidth_hit_ratio * 100
-]]
-
-integer 'proxy.cluster.bandwidth_hit_ratio_int_pct' [[
-  return proxy.cluster.bandwidth_hit_ratio * 100
-]]
-
-integer 'proxy.node.cache.percent_free_int_pct' [[
-  return proxy.node.cache.percent_free * 100
-]]
-
-integer 'proxy.cluster.cache.percent_free_int_pct' [[
-  return proxy.cluster.cache.percent_free * 100
-]]
-
-integer 'proxy.node.hostdb.hit_ratio_int_pct' [[
-  return proxy.node.hostdb.hit_ratio * 100
-]]
-
-integer 'proxy.cluster.hostdb.hit_ratio_int_pct' [[
-  return proxy.cluster.hostdb.hit_ratio * 100
+float 'proxy.cluster.hostdb.hit_ratio' [[
+  return cluster('proxy.node.hostdb.hit_ratio')
 ]]

 integer 'proxy.node.cache.bytes_total_mb' [[
@@ -1481,10 +1395,18 @@ integer 'proxy.node.cache.bytes_free_mb'
   return mbytes(proxy.node.cache.bytes_free)
 ]]

+integer 'proxy.cluster.cache.bytes_free' [[
+  return cluster('proxy.cluster.cache.bytes_free')
+]]
+
 integer 'proxy.cluster.cache.bytes_free_mb' [[
   return mbytes(proxy.cluster.cache.bytes_free)
 ]]

+integer 'proxy.node.http.current_parent_proxy_connections' [[
+  return proxy.process.http.current_parent_proxy_connections
+]]
+
 integer 'proxy.cluster.http.current_parent_proxy_connections' [[
   return cluster('proxy.node.http.current_parent_proxy_connections')
 ]]
@@ -1625,7 +1547,7 @@ integer 'proxy.node.log.bytes_sent_to_ne
 ]]

 integer 'proxy.cluster.log.bytes_sent_to_network_avg_10s' [[
-  return cluster(' proxy.node.log.bytes_sent_to_network_avg_10s')
+  return cluster('proxy.node.log.bytes_sent_to_network_avg_10s')
 ]]

 integer 'proxy.node.log.bytes_received_from_network_avg_10s' [[

[randall]

Tried with the patched version of metrics.config, but I still cannot repro the ASAN issue.

What's the output from "ldd traffic_server" ?

[dnj12345]

@randall, Here's the ldd output...

# ldd /opt/trafficserver/bin/traffic_server
	linux-vdso.so.1 =>  (0x00007fff9af54000)
	libasan.so.2 => /usr/lib/x86_64-linux-gnu/libasan.so.2 (0x00007f965a2ae000)
	libtsutil.so.7 => /opt/trafficserver/lib/libtsutil.so.7 (0x00007f965a00e000)
	libhwloc.so.5 => /usr/lib/x86_64-linux-gnu/libhwloc.so.5 (0x00007f9659dd4000)
	libpcre.so.3 => /lib/x86_64-linux-gnu/libpcre.so.3 (0x00007f9659b64000)
	libtcl8.6.so => /usr/lib/x86_64-linux-gnu/libtcl8.6.so (0x00007f96597b5000)
	libresolv.so.2 => /lib/x86_64-linux-gnu/libresolv.so.2 (0x00007f965959a000)
	libssl.so.1.0.0 => /lib/x86_64-linux-gnu/libssl.so.1.0.0 (0x00007f9659331000)
	libcrypto.so.1.0.0 => /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007f9658eec000)
	libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f9658ccf000)
	libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f9658acb000)
	libstdc++.so.6 => /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (0x00007f9658749000)
	libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f9658440000)
	libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007f965822a000)
	libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f9657e60000)
	libcap.so.2 => /lib/x86_64-linux-gnu/libcap.so.2 (0x00007f9657c5a000)
	libnuma.so.1 => /usr/lib/x86_64-linux-gnu/libnuma.so.1 (0x00007f9657a4f000)
	libltdl.so.7 => /usr/lib/x86_64-linux-gnu/libltdl.so.7 (0x00007f9657845000)
	libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007f965762b000)
	/lib64/ld-linux-x86-64.so.2 (0x00007f965b21b000)

[dnj12345]

@randall
I think the problem is in traffic_manager and not traffic_server. When I load traffic_server in gdb it showed no errors. Since traffic_server wasn't coming up, I thought it was related to that. I went back and looked at the stack trace and noticed that the stacks trace is for trafffic_manager and not traffic_server. When I load traffic_manager in gdb, the issue pops up. I haven't been able to break, before the sanitizer kicks in.

[dnj12345]

I put a breakpoint in 'lua_metrics_install'. That function somehow seems to call metric_index which is where the crash happens. In the lua_metrics_install function it's iterating over metric prefixes. It alwas seems to crash when processing the metrics prefix "proxy.node.version.manager". Hope this helps...

Thread 1 "traffic_manager" hit Breakpoint 5, lua_metrics_install (L=L@entry=0x40000378)
    at metrics.cc:244
244	      if (binding->bind_value(p->c_str(), -1)) {
2: p = "proxy.node.restarts.manager"
(gdb) c
Continuing.

Thread 1 "traffic_manager" hit Breakpoint 5, lua_metrics_install (L=L@entry=0x40000378)
    at metrics.cc:244
244	      if (binding->bind_value(p->c_str(), -1)) {
2: p = "proxy.node.restarts.proxy"
(gdb) c
Continuing.

Thread 1 "traffic_manager" hit Breakpoint 5, lua_metrics_install (L=L@entry=0x40000378)
    at metrics.cc:244
244	      if (binding->bind_value(p->c_str(), -1)) {
2: p = "proxy.node.version.manager"
(gdb) c
Continuing.

Thread 1 "traffic_manager" hit Breakpoint 5, metrics_create_record (data_type=RECD_COUNTER,
    L=0x40000378) at metrics.cc:244
244	      if (binding->bind_value(p->c_str(), -1)) {
(gdb)

[randall]

Ok, I can now repro this! But, I still don't under why it does.

[randall]

Can you try with metrics.config* removed from the etc/trafficserver directory? I'm more curious if your crash(#5596) can be replicated under ASAN than the ASAN failures with metrics.config (which has been removed in 8.0 and beyond)

[zwoop]

Giving to Randall for now (thanks for taking on this one!!)