Fifos and persistent readers

I recently worked on a daemon (call it slurper) that persistently read data from syslog via a FIFO (also known as a named pipe). On startup, slurper would work fine for a couple of hours then stop processing input from the FIFO.  The relevant code in slurper is:

	while True:
	self.logger.info("[Re]starting to read %s" % self.input_file)
	with open(self.input_file, "rb") as f:
	for line in f:
	...do_stuff_with_line...(line)

view raw broken_pipe_persistent_reader.py hosted with ❤ by GitHub

Digging into this mystery revealed that syslogd server was getting EAGAIN errors on the fifo descriptor.  According to man 7 pipe:

      O_NONBLOCK enabled, n <= PIPE_BUF
              If there is room to write n bytes to the pipe, then write(2) succeeds immediately, writing all n bytes; otherwise write(2) fails, with errno set to EAGAIN.

The syslogd daemon was opening the pipe in O_NONBLOCK mode and getting EAGAIN errors which implied that the pipe was full. (man 7 pipe states that the pipe buffer is 64K).
Additionally, a `cat` on the FIFO drains the pipe and allows syslogd to write more content.

All these clues imply that the FIFO has no reader. But how can that be? A check on lsof shows that slurper has an open fd for the named pipe. Digging deeper, an attempt to `cat` slurpers' open fd didn't return any data

cat /proc/$(pgrep slurper)/fd/ # Be careful with this. It will steal data from your pipe/file/socket on a production system

So I decided to whip up a reader that emulates slurper's behaviour

	# Pre-create the fifo
	# mkfifo /tmp/example_fifo
	# Save this to a file and strace it
	# strace -fttt -o open_close python test.py
	import time
	fname = "/tmp/example_fifo"
	with open(fname, "r") as f:
	for line in f:
	print line
	time.sleep(1)

view raw reader.py hosted with ❤ by GitHub

Strace this script to see which syscalls are being invoked

	# This will block until I run the following in ipython:
	# f = open("/tmp/example_fifo", "w", 0); f.write("Hello"); f.close()
	# $ strace -fttt -o open_close python test.py
	Hello
	# $ cat open_close
	14872 1390947892.561375 open("/tmp/example_fifo", O_RDONLY) = 3 # As expected, the reader is blocked on reading until a writer comes along (look at the second column == no. of elapsed wall time)
	...
	... # In ipython run: f = open("/tmp/example_fifo", "w", 0); f.write("Hello"); f.close()
	...
	14872 1390947902.566207 fstat(3, {st_mode=S_IFIFO|0644, st_size=0, ...}) = 0
	...
	....
	14872 1390947902.566460 read(3, "Hello", 8192) = 5
	14872 1390947902.567981 read(3, "", 4096) = 0
	14872 1390947902.568104 read(3, "", 8192) = 0 # Aha... We are reading an EOF!
	14872 1390947902.568226 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 8), ...}) = 0
	14872 1390947902.568345 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f99c6de3000
	14872 1390947902.568528 write(1, "Hello\n", 6) = 6
	14872 1390947902.568693 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
	14872 1390947903.570856 close(3) = 0 # and we exit.
	14872 1390947903.571690 munmap(0x7f99c6de4000, 4096) = 0
	14872 1390947903.572290 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f99c69bb030}, {0x425842, [], SA_RESTORER, 0x7f99c69bb030}, 8) = 0
	14872 1390947903.574587 exit_group(0) = ?

view raw open_close.py hosted with ❤ by GitHub

This reveals that a writer closing it's fd will cause readers to read an EOF (and probably exit in the case of the block under the context manager).
So we have two options:
1) Ugly and kludgy:  Wrap the context manager read block within an infinite loop the reopens the file:
2) Super cool trick. Open another dummy writer to the FIFO. The kernel sends an EOF when the last writer closes it's fd. Since our dummy writer never closes the fd, readers will never get an EOF if the real writer closes it's fd.

	while True:
	self.logger.info("[Re]starting to read %s" % self.input_file)
	with open(self.input_file, "rb") as f:
	f1 = open (fname, "w") # The dummy writer has to be opened after a reader, otherwise it would block
	for line in f:
	...do_stuff_with_line...(line)

view raw open_dummy_pipe.py hosted with ❤ by GitHub

The actual root cause: The syslog daemon was being restarted and this would cause it to close and reopen it's fds.