[7.1.4/7.1.6] Fatal: PluginVC.cc:126: failed assertion magic == PLUGIN_VC_MAGIC_ALIVE #5109
Description
Possibly duplicate of issue #4246.
When configured over 900 remap authproxy configurations, trafficserver fails with an assertion:
Fatal: PluginVC.cc:126: failed assertion
magic == PLUGIN_VC_MAGIC_ALIVE
It's perfectly easy to reproduce when proxy.config.task_threads is set to 1, while I can experience this issue in several minutes when set to 12. Tested failing with 7.1.6 as well.
Configuration looks like this, but with >900 parallel blocks:
map http://337.auth.my.org http://192.168.123.21
redirect http://site1.my.org https://site1.my.org
map https://site1.my.org http://192.168.123.124 @plugin=authproxy.so @pparam=--auth-transform=redirect @pparam=--auth-host=337.auth.my.org @pparam=--auth-port=80
map http://338.auth.my.org http://192.168.123.21
redirect http://site2.my.org https://site2.my.org
map https://site2.my.org http://192.168.123.125 @plugin=authproxy.so @pparam=--auth-transform=redirect @pparam=--auth-host=338.auth.my.org @pparam=--auth-port=80
There are also gzip.so and header_rewrite.so modules enabled globally. header_rewrite's configuration is:
cond %{STATUS} =401
set-redirect 302 /authservice/
cond %{READ_REQUEST_HDR_HOOK} [AND]
cond %{INCOMING-PORT} =443
set-header X-Forwarded-Proto https
systemd service output:
Mar 4 00:20:03 proxy-public traffic_cop[119899]: --- Cop Starting [Version: Apache Traffic Server - traffic_cop - 7.1.4 - (build # 080611 on Aug 6 2018 at 11:06:56)] ---
Mar 4 00:20:03 proxy-public traffic_cop[119899]: traffic_manager not running, making sure traffic_server is dead
Mar 4 00:20:03 proxy-public traffic_cop[119899]: spawning traffic_manager
Mar 4 00:20:03 proxy-public traffic_cop[119899]: binpath is bin
Mar 4 00:20:03 proxy-public traffic_manager[119902]: NOTE: --- Manager Starting ---
Mar 4 00:20:03 proxy-public traffic_manager[119902]: NOTE: Manager Version: Apache Traffic Server - traffic_manager - 7.1.4 - (build # 080611 on Aug 6 2018 at 11:06:56)
Mar 4 00:20:03 proxy-public traffic_manager[119902]: NOTE: RLIMIT_NOFILE(7):cur(300000),max(300000)
Mar 4 00:20:06 proxy-public traffic_server[119909]: NOTE: --- traffic_server Starting ---
Mar 4 00:20:06 proxy-public traffic_server[119909]: NOTE: traffic_server Version: Apache Traffic Server - traffic_server - 7.1.4 - (build # 080611 on Aug 6 2018 at 11:06:56)
Mar 4 00:20:06 proxy-public traffic_server[119909]: NOTE: RLIMIT_NOFILE(7):cur(300000),max(300000)
Mar 4 00:20:38 proxy-public traffic_server[119909]: Fatal: PluginVC.cc:126: failed assertionmagic == PLUGIN_VC_MAGIC_ALIVE
Mar 4 00:20:38 proxy-public traffic_crashlog[119911]: {0x2af0ed014680} NOTE: crashlog started, target=119909, debug=false syslog=true, uid=0 euid=0
Mar 4 00:20:38 proxy-public traffic_crashlog[119911]: {0x2af0ed014680} NOTE: logging to 0x556a669904f0
Mar 4 00:20:38 proxy-public traffic_crashlog[119911]: {0x2af0ed014680} ERROR: wrote crash log to /var/log/trafficserver/crash-2019-03-04-002038.log
In traffic.out:
traffic_server: received signal 6 (Aborted)
traffic_server - STACK TRACE:
/usr/bin/traffic_server(_Z19crash_logger_invokeiP9siginfo_tPv+0xa0)[0x55d1ed17d650]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110e0)[0x2ac831af90e0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x2ac8327d8fff]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x2ac8327da42a]
/usr/lib/trafficserver/libtsutil.so.7(+0x2e9d8)[0x2ac82fc0d9d8]
/usr/lib/trafficserver/libtsutil.so.7(+0x2c715)[0x2ac82fc0b715]
/usr/bin/traffic_server(_ZN8PluginVC12main_handlerEiPv+0x4e8)[0x55d1ed1d4f68]
/usr/bin/traffic_server(_ZN7EThread13process_eventEP5Eventi+0x92)[0x55d1ed474ea2]
/usr/bin/traffic_server(_ZN7EThread15execute_regularEv+0x52c)[0x55d1ed475fdc]
/usr/bin/traffic_server(+0x3cd8b9)[0x55d1ed4748b9]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x74a4)[0x2ac831aef4a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x2ac83288ed0f]
Relevant thread info in crash log:
Thread 120830, [ET_NET 23]:
0 0x000055d1ed17d632 crash_logger_invoke(int, siginfo_t*, void*) + 0x82
1 0x00002ac831af90e0 __restore_rt + (nil)
2 0x00002ac8327d8fff gsignal + 0xcf
3 0x00002ac8327da42a abort + 0x16a
4 0x00002ac82fc0d9d8 ink_abort(char const*, ...) + 0xa8
5 0x00002ac82fc0b715 _ink_assert + 0x15
6 0x000055d1ed1d4f68 PluginVC::main_handler(int, void*) + 0x4e8
7 0x000055d1ed474ea2 EThread::process_event(Event*, int) + 0x92
8 0x000055d1ed475fdc EThread::execute_regular() + 0x52c
9 0x000055d1ed4748b9 TasksProcessor::~TasksProcessor() + 0x89
10 0x00002ac831aef4a4 start_thread + 0xc4
11 0x00002ac83288ed0f clone + 0x3f
12 0x0000000000000000 0x0 + 0x3f
When enabling diag with filters "pvc*|authproxy*", it's able to observe that the crash may happens on either Active or Passive side (info from pvc_event DEBUG message), and printing the magic value (and recompile) shows that the magic is set to equal to PLUGIN_VC_MAGIC_DEAD, not an arbitrary value. Didn't find clue in authproxy DIAG outputs on whether a specific request would trigger it. Guess it is likely to be a race condition.