Search code examples
bashio-redirectiontail

Why do I have inconsistent behaviour when I `tail -f` a file that has been redirected with the `>` operator


I am working on some script, and encountered this behaviour. This is a simplified example.

On one tty,

# touch file
# tail -f file 2> /dev/null

On another tty, in the same directory, run the following script:

#!/bin/bash
for i in {1..15}; do
    echo $i > ./file
    sleep 2
done

Why is it that the tail -f command does not correctly reflect the file changes when I use the > operator? If I use the >> append operator, it works as intended.

Eventually, the tailing of the file that has been redirected with the > operator shows the following:

1
2
6
7
9

15

Solution

  • tail -f only reliably detects changes that are appended. It tries to detect writes where the file is truncated, shortened, or otherwise modified not-at-the-end, but this detection is spotty. It can detect some of these but misses many.

    Algorithm

    1. tail uses inotify to watch for changes.
    2. When there's a change event it quickly runs fstat() to check the file's metadata, including its size.
    3. If the size is larger, it assumes data has been appended and reads the added data.
    4. If the size is smaller, it prints "file truncated" and starts over from the beginning.

    Consequences

    > truncates the file to size 0 and then writes the new contents. Whether tail detects these types of writes is hit or miss. If you write a larger or equal number of bytes it often misses those writes.

    • Step 4 ensures it will reliably detect if the file length has shortened. If you modify your loop to write successively shorter strings each iteration then tail will detect every one:

      for i in {1..5}; do
        for ((j=6-i; j>=0; --j)); do echo $i; done > file
        sleep 2
      done
      
      tail: file: file truncated
      1
      1
      1
      1
      1
      tail: file: file truncated
      2
      2
      2
      2
      tail: file: file truncated
      3
      3
      3
      tail: file: file truncated
      4
      4
      tail: file: file truncated
      5
      
    • There's a race condition between steps 1 and 2. When you run echo $i > file there are two modifications back-to-back: the file is truncated, and then $i is written. If tail is able to run fstat() in between the two modifications then it detects the truncation. If it's too slow, though, it misses it. That's what usually happens, which is why it misses most, but not all, of the writes.

      It also explains why sleeping doesn't help. To eliminate the race condition you'd need to sleep in between truncating and writing $i, not after.

      Indeed, you can do exactly that like so:

      for i in {1..15}; do (sleep 2; echo $i) > file; done
      

      > file runs immediately and truncates the file. The script then sleeps for two seconds before writing $i. There's a clear gap between the two modifications.

      As expected, tail now detects every single write:

      1
      tail: file: file truncated
      2
      tail: file: file truncated
      3
      tail: file: file truncated
      4
      tail: file: file truncated
      5
      tail: file: file truncated
      6
      tail: file: file truncated
      7
      tail: file: file truncated
      8
      tail: file: file truncated
      9
      tail: file: file truncated
      10
      tail: file: file truncated
      11
      tail: file: file truncated
      12
      tail: file: file truncated
      13
      tail: file: file truncated
      14
      tail: file: file truncated
      15