FIFO logfile removed on configuration reload

[ema]

Log files created with mode ascii_pipe are unlinked upon logging.yaml configuration reload. This means that the named pipe will keep on working as expected only util a process is reading from it. Restarting the reader process breaks logging. The bug has been reproduced against master (1fa443c).

Setup

Traffic Server was built from master with:

autoreconf -if
./configure --enable-layout=Debian --sysconfdir=/etc/trafficserver --libdir=/usr/lib/trafficserver --libexecdir=/usr/lib/trafficserver/modules
make -j4

The following configuration was used:

# /etc/trafficserver/records.config
CONFIG proxy.config.bin_path STRING /home/ema/dev/trafficserver/src/traffic_server/
CONFIG proxy.config.diags.debug.enabled INT 1
CONFIG proxy.config.diags.debug.tags STRING log-file

# /etc/trafficserver/logging.yaml
formats:
    - name: common
      format: 'test: %<chi> - %<caun> [%<cqtn>] "%<cqtx>" %<pssc> %<pscl>'

logs:
    - filename: fifologs
      format: common
      mode: ascii_pipe

The traffic_manager process was started with:

sudo -u trafficserver ./src/traffic_manager/traffic_manager --nosyslog

Reproducing the issue

Startup with no reader

Upon startup, the fifologs.pipe named pipe is created, but opening it fails (as expected) due to lack of readers:

[Nov 21 09:38:01.876] traffic_server DEBUG: <LogFile.cc:80 (LogFile)> (log-file) exiting LogFile constructor, m_name=/var/log/trafficserver/fifologs.pipe, this=0x55ea88a8bfb0
[Nov 21 09:38:01.876] traffic_server DEBUG: <LogFile.cc:175 (open_file)> (log-file) Created named pipe /var/log/trafficserver/fifologs.pipe for logging
[Nov 21 09:38:01.876] traffic_server DEBUG: <LogFile.cc:179 (open_file)> (log-file) attempting to open pipe /var/log/trafficserver/fifologs.pipe
[Nov 21 09:38:01.876] traffic_server DEBUG: <LogFile.cc:182 (open_file)> (log-file) no readers for pipe /var/log/trafficserver/fifologs.pipe
[Nov 21 09:38:01.876] traffic_server DEBUG: <LogFile.cc:80 (LogFile)> (log-file) exiting LogFile constructor, m_name=/var/log/trafficserver/error.log, this=0x55ea88a88340
[Nov 21 09:38:01.876] traffic_server DEBUG: <LogFile.cc:80 (LogFile)> (log-file) exiting LogFile constructor, m_name=/var/log/trafficserver/scrapfile.log, this=0x55ea88a8ec30

Issuing an HTTP request to traffic_server results in another failed attempt to open the pipe in order to write a log entry for the transaction:

[Nov 21 09:39:06.998] [LOG_PREPROC 0] DEBUG: <LogFile.cc:427 (write_ascii_logbuffer3)> (log-file) entering LogFile::write_ascii_logbuffer3 for /var/log/trafficserver/fifologs.pipe (this=0x55ea88a8bfb0)
[Nov 21 09:39:06.998] [LOG_PREPROC 0] DEBUG: <LogFile.cc:427 (write_ascii_logbuffer3)> (log-file) entering LogFile::write_ascii_logbuffer3 for /var/log/trafficserver/error.log (this=0x55ea88a88340)
[Nov 21 09:39:06.998] [LOG_FLUSH] DEBUG: <LogFile.cc:179 (open_file)> (log-file) attempting to open pipe /var/log/trafficserver/fifologs.pipe
[Nov 21 09:39:06.998] [LOG_FLUSH] DEBUG: <LogFile.cc:182 (open_file)> (log-file) no readers for pipe /var/log/trafficserver/fifologs.pipe

Proper logging upon reader startup

Starting a reader (eg: cat /var/log/trafficserver/fifologs.pipe) and performing another HTTP request:

[Nov 21 09:39:56.139] [LOG_PREPROC 0] DEBUG: <LogFile.cc:427 (write_ascii_logbuffer3)> (log-file) entering LogFile::write_ascii_logbuffer3 for /var/log/trafficserver/fifologs.pipe (this=0x55ea88a8bfb0)
[Nov 21 09:39:56.139] [LOG_PREPROC 0] DEBUG: <LogFile.cc:427 (write_ascii_logbuffer3)> (log-file) entering LogFile::write_ascii_logbuffer3 for /var/log/trafficserver/error.log (this=0x55ea88a88340)
[Nov 21 09:39:56.139] [LOG_FLUSH] DEBUG: <LogFile.cc:179 (open_file)> (log-file) attempting to open pipe /var/log/trafficserver/fifologs.pipe

At this point the pipe is opened successfully, and logs are shown as expected by cat.

lsof /var/log/trafficserver/fifologs.pipe
COMMAND     PID          USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
cat        4165          root    3r  FIFO  253,1      0t0 917531 /var/log/trafficserver/fifologs.pipe
[TS_MAIN] 31309 trafficserver   43w  FIFO  253,1      0t0 917531 /var/log/trafficserver/fifologs.pipe

Trigger logging.yaml configuration reload and fifo deletion

After adding an empty line to logging.yaml and triggering a configuration reload with pkill -HUP traffic_manager:

[Nov 21 10:05:09.927] [LOG_FLUSH] DEBUG: <LogFile.cc:80 (LogFile)> (log-file) exiting LogFile constructor, m_name=/var/log/trafficserver/fifologs.pipe, this=0x1543bc008cc0
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:175 (open_file)> (log-file) Created named pipe /var/log/trafficserver/fifologs.pipe for logging
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:179 (open_file)> (log-file) attempting to open pipe /var/log/trafficserver/fifologs.pipe
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:182 (open_file)> (log-file) no readers for pipe /var/log/trafficserver/fifologs.pipe
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:80 (LogFile)> (log-file) exiting LogFile constructor, m_name=/var/log/trafficserver/error.log, this=0x1543bc007880
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:115 (~LogFile)> (log-file) entering LogFile destructor, this=0x1543bc008cc0
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:119 (~LogFile)> (log-file) exiting LogFile destructor, this=0x1543bc008cc0
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:115 (~LogFile)> (log-file) entering LogFile destructor, this=0x1543bc007880
[Nov 21 10:05:09.929] [LOG_FLUSH] DEBUG: <LogFile.cc:119 (~LogFile)> (log-file) exiting LogFile destructor, this=0x1543bc007880

Once this happens, lsof /var/log/trafficserver/fifologs.pipe reports the pipe as not being open by cat and TS_MAIN any longer. The fifo results now deleted:

lsof | grep /var/log/trafficserver/fifologs.pipe 
[TS_MAIN]  7855          trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
traffic_s  7855  7869    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_NET    7855  7872    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_NET    7855  7873    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_NET    7855  7874    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_NET    7855  7875    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_NET    7855  7876    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_NET    7855  7877    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[LOG_PREP  7855  7878    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[LOG_FLUS  7855  7879    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7880    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7881    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7882    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7883    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7884    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7885    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7886    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_AIO    7855  7887    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ACCEPT    7855  7888    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ACCEPT    7855  7889    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_TASK   7855  7890    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
[ET_TASK   7855  7891    trafficserver   44w     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)
cat        8018                   root    3r     FIFO              253,1       0t0     917531 /var/log/trafficserver/fifologs.pipe (deleted)

Restarting the reader

Stopping the cat process and starting a new one results in all logs being lost:

[Nov 21 10:08:44.556] [LOG_PREPROC 0] DEBUG: <LogFile.cc:427 (write_ascii_logbuffer3)> (log-file) entering LogFile::write_ascii_logbuffer3 for /var/log/trafficserver/fifologs.pipe (this=0x55f66c78ff30)
[Nov 21 10:08:44.556] [LOG_FLUSH] ERROR: Failed to write log to /var/log/trafficserver/fifologs.pipe: [tried 88, wrote 0, Broken pipe]

Avoiding unlink

diff --git a/proxy/logging/LogObject.cc b/proxy/logging/LogObject.cc
index c745bddb2..0d4ed90a9 100644
--- a/proxy/logging/LogObject.cc
+++ b/proxy/logging/LogObject.cc
@@ -1009,7 +1009,7 @@ LogObjectManager::_solve_filename_conflicts(LogObject *log_object, int maxConfli
             roll_file = false;
           } else {
             if (S_ISFIFO(s.st_mode)) {
-              unlink(filename);
+              //unlink(filename);
               roll_file = false;
             }
           }

With the patch above applied, a logging.yaml reload does not remove the pipe, and the reader (cat in our example) can be restarted at will without breaking logging. Notice how in this case there is no no readers for pipe error:

[Nov 21 10:59:19.579] [LOG_FLUSH] DEBUG: <LogFile.cc:80 (LogFile)> (log-file) exiting LogFile constructor, m_name=/var/log/trafficserver/fifologs.pipe, this=0x14dfac008c80
[Nov 21 10:59:19.579] [LOG_FLUSH] DEBUG: <LogFile.cc:179 (open_file)> (log-file) attempting to open pipe /var/log/trafficserver/fifologs.pipe
[Nov 21 10:59:19.579] [LOG_FLUSH] DEBUG: <LogFile.cc:80 (LogFile)> (log-file) exiting LogFile constructor, m_name=/var/log/trafficserver/error.log, this=0x14dfac007840
[Nov 21 10:59:19.580] [LOG_FLUSH] DEBUG: <LogFile.cc:115 (~LogFile)> (log-file) entering LogFile destructor, this=0x14dfac008c80
[Nov 21 10:59:19.580] [LOG_FLUSH] DEBUG: <LogFile.cc:119 (~LogFile)> (log-file) exiting LogFile destructor, this=0x14dfac008c80
[Nov 21 10:59:19.580] [LOG_FLUSH] DEBUG: <LogFile.cc:115 (~LogFile)> (log-file) entering LogFile destructor, this=0x14dfac007840
[Nov 21 10:59:19.580] [LOG_FLUSH] DEBUG: <LogFile.cc:119 (~LogFile)> (log-file) exiting LogFile destructor, this=0x14dfac007840

However, this causes TS_MAIN to open a new file descriptor every time logging.yaml is reloaded. For example, after 3 reloads:

lsof /var/log/trafficserver/fifologs.pipe
COMMAND     PID          USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
[TS_MAIN] 30483 trafficserver   40w  FIFO  253,1      0t0 925539 /var/log/trafficserver/fifologs.pipe
[TS_MAIN] 30483 trafficserver   44w  FIFO  253,1      0t0 925539 /var/log/trafficserver/fifologs.pipe
[TS_MAIN] 30483 trafficserver   45w  FIFO  253,1      0t0 925539 /var/log/trafficserver/fifologs.pipe
[TS_MAIN] 30483 trafficserver   47w  FIFO  253,1      0t0 925539 /var/log/trafficserver/fifologs.pipe
cat       31587          root    3r  FIFO  253,1      0t0 925539 /var/log/trafficserver/fifologs.pipe

The file descriptor leak shown above should clearly be avoided, though on a busy server it is arguably an improvement over breaking logging altogether, possibly filling up /var with Failed to write log entries.

[bryancall]

@wmfgerrit Can you please create a PR for this?

[bryancall]

I was able to reproduce the issue on my Fedora 30 server.

[bryancall]

Stack trace when reloading the configuration:

#0  LogObjectManager::_solve_filename_conflicts (this=0x7f9270008f58, log_object=0x7f9270015f70, maxConflicts=99) at LogObject.cc:914
#1  0x00000000007847b2 in LogObjectManager::_manage_object (this=0x7f9270008f58, log_object=0x7f9270015f70, is_api_object=false, maxConflicts=99) at LogObject.cc:872
#2  0x000000000076d5c9 in LogObjectManager::manage_object (this=0x7f9270008f58, logObject=0x7f9270015f70, maxConflicts=99) at LogObject.h:367
#3  0x000000000078a615 in YamlLogConfig::loadLogConfig (this=0x7f92bd0b09b8, cfgFilename=0x7f9270011120 "/usr/local/etc/trafficserver/logging.yaml") at YamlLogConfig.cc:102
#4  0x0000000000789f1a in YamlLogConfig::parse (this=0x7f92bd0b09b8, cfgFilename=0x7f9270011120 "/usr/local/etc/trafficserver/logging.yaml") at YamlLogConfig.cc:39
#5  0x000000000076bf7d in LogConfig::evaluate_config (this=0x7f9270008f30) at LogConfig.cc:816
#6  0x000000000076a445 in LogConfig::setup_log_objects (this=0x7f9270008f30) at LogConfig.cc:375
#7  0x0000000000769dfb in LogConfig::init (this=0x7f9270008f30, prev_config=0x7f9270000e50) at LogConfig.cc:278
#8  0x0000000000756cbc in Log::change_configuration () at Log.cc:117
#9  0x0000000000756f9a in Log::periodic_tasks (time_now=1563831090) at Log.cc:221
#10 0x000000000075dc9f in Log::flush_thread_main () at Log.cc:1361
#11 0x000000000075e743 in LoggingFlushContinuation::mainEvent (this=0x15daae0) at Log.cc:285
#12 0x0000000000624949 in Continuation::handleEvent (this=0x15daae0, event=1, data=0x15008e0) at /home/bcall/dev/apache/trafficserver/iocore/eventsystem/I_Continuation.h:190
#13 0x00000000008e4295 in EThread::execute (this=0x7f92bd1b2010) at UnixEThread.cc:322
#14 0x00000000008e2d91 in spawn_thread_internal (a=0x15da440) at Thread.cc:92
#15 0x00007f92c527d5a2 in start_thread () from /lib64/libpthread.so.0
#16 0x00007f92c4e49303 in clone () from /lib64/libc.so.6

[ericcarlschwartz]

re: reproducing this, I can confirm we have also been seeing this @ yahoo!

would it make more sense to reuse existing pipes than remove the unlink?

[ema]

Fixed in master by #6076