Project

General

Profile

Bug #3928

`tail -f ...` doesn't notice file truncation

Added by Robert Mustacchi about 6 years ago. Updated almost 6 years ago.

Status:
Resolved
Priority:
Normal
Category:
cmd - userland programs
Start date:
2013-07-28
Due date:
% Done:

100%

Estimated time:
Difficulty:
Medium
Tags:

Description

/usr/bin/tail -f FILE doesn't notice file truncation. /opt/local/bin/tail from pkgsrc is fine with it. Mac's tail is fine with it too.

Repro:

# in one shell:
[root@headnode (bh1-kvm1:0) /var/tmp]# touch follow.log
[root@headnode (bh1-kvm1:0) /var/tmp]# tail -f follow.log
one
two
ree
three

# in another shell:
[root@headnode (bh1-kvm1:0) /var/tmp]# echo one >> follow.log
[root@headnode (bh1-kvm1:0) /var/tmp]# echo two >> follow.log
[root@headnode (bh1-kvm1:0) /var/tmp]# echo -n '' > follow.log   # wipe it
[root@headnode (bh1-kvm1:0) /var/tmp]# cat follow.log
[root@headnode (bh1-kvm1:0) /var/tmp]# echo three >> follow.log
[root@headnode (bh1-kvm1:0) /var/tmp]# echo three >> follow.log
[root@headnode (bh1-kvm1:0) /var/tmp]# echo three >> follow.log

History

#1

Updated by Robert Mustacchi about 6 years ago

  • % Done changed from 0 to 90
  • Tags deleted (needs-triage)
#2

Updated by Robert Mustacchi about 6 years ago

Under some conditions, tail -f will create duplicate output after a truncation event – conditions that seem to be much more likely in a virtual environment (e.g., VMware) than directly on metal. Here is a depiction of the race between "tail -f" and a series of truncates and writes to a file.

.

                                         echo "bar" > /var/tmp/foo;
                                         echo "baz" > /var/tmp/foo;
       tail -f /var/tmp/foo              echo "bop" > /var/tmp/foo
+--------------------------------+   +--------------------------------+
|                                |   |                                |
| Associates: MODIFIED           |   |                                |
|   (Active: Modified)           |   |                                |
|                                |   |                                |
| Associates: TRUNC              |   |                                |
|   (Active: Trunc, Modified)    |   |                                |
|                              +------->                              |
|                                |   | VE_CREATE:                     |
|                                |   |   Emits TRUNC|MODIFIED         |
|                                |   |      (Active: Trunc, Modified) |
|                                |   |     Sends TRUNC                |
|                                |   |      (Active: Modified)        |
|                                |   |     Sends MODIFIED             |
|                                |   |      (Active: <none>)          |
|                                |   |                                |
|                                |   | FOP_FILE_WRITE "bar":          |
|                                |   |   Emits: MODIFIED              |
|                                |   |      (Active: <none>)          |
|                              <-------+                              |
| Gets: TRUNC                    |   |                                |
| Associates: TRUNC              |   |                                |
|   (Active: Trunc)              |   |                                |
| Seeks: 0                       |   |                                |
| Reads: "bar"                   |   |                                |
|                                |   |                                |
| Gets: MODIFIED                 |   |                                |
| Associates: MODIFIED           |   |                                |
|   (Active: Modified, Trunc)    |   |                                |
| Reads: <EOF>                   |   |                                |
|                              +------->                              |
|                                |   | VE_CREATE:                     |
|                                |   |   Emits TRUNC|MODIFIED         |
|                                |   |      (Active: Modified, Trunc) |
|                                |   |     Sends MODIFIED             |
|                                |   |      (Active: Trunc)           |
|                                |   |     Sends TRUNC                |
|                                |   |      (Active: <none>)          |
|                                |   |                                |
|                                |   | FOP_FILE_WRITE "baz":          |
|                                |   |   Emits: MODIFIED              |
|                                |   |      (Active: <none>)          |
|                              <-------+                              |
| Gets: MODIFIED                 |   |                                |
| Associates: MODIFIED           |   |                                |
|   (Active: Modified)           |   |                                |
|                                |   |                                |
| Gets: TRUNC                    |   |                                |
| Associates: TRUNC              |   |                                |
|   (Active: Trunc, Modified)    |   |                                |
| Seeks: 0                       |   |                                |
| Reads: "baz"                   |   |                                |
|                              +------->                              |
|                                |   | VE_CREATE:                     |
|                                |   |   Emits TRUNC|MODIFIED         |
|                                |   |      (Active: Trunc, Modified) |
|                                |   |     Sends TRUNC                |
|                                |   |      (Active: Modified)        |
|                                |   |     Sends MODIFIED             |
|                                |   |      (Active: <none>)          |
|                              <-------+                              |
| Gets: TRUNC                    |   |                                |
| Associates: TRUNC              |   |                                |
|   (Active: Trunc)              |   |                                |
| Seeks: 0                       |   |                                |
| Reads: "baz"                   |   |                                |
|                              +------->                              |
|                                |   | FOP_FILE_WRITE "bop":          |
|                                |   |   Emits: MODIFIED              |
|                                |   |      (Active: Trunc)           |
|                                |   |                                |
| ...                            |   | ...                            |

In the above, we have read/emitted "baz" twice. Now, one might well suggest that this could be eliminated by not reading on a TRUNC event (that is, by only setting the seek offset on a TRUNC and waiting for a MODIFIED to actually read), but this actually gives rise to an equal and opposite race condition:

.
                                         echo "bar" > /var/tmp/foo;
                                         echo "baz" > /var/tmp/foo;
       tail -f /var/tmp/foo              echo "bop" > /var/tmp/foo
+--------------------------------+   +--------------------------------+
|                                |   |                                |
| Associates: MODIFIED           |   |                                |
|   (Active: Modified)           |   |                                |
|                                |   |                                |
| Associates: TRUNC              |   |                                |
|   (Active: Trunc, Modified)    |   |                                |
|                              +------->                              |
|                                |   | VE_CREATE:                     |
|                                |   |   Emits TRUNC|MODIFIED         |
|                                |   |      (Active: Trunc, Modified) |
|                                |   |     Sends TRUNC                |
|                                |   |      (Active: Modified)        |
|                                |   |     Sends MODIFIED             |
|                                |   |      (Active: <none>)          |
|                                |   |                                |
|                                |   | FOP_FILE_WRITE "bar":          |
|                                |   |   Emits: MODIFIED              |
|                                |   |      (Active: <none>)          |
|                              <-------+                              |
| Gets: TRUNC                    |   |                                |
| Associates: TRUNC              |   |                                |
|   (Active: Trunc)              |   |                                |
| Seeks: 0                       |   |                                |
|                                |   |                                |
| Gets: MODIFIED                 |   |                                |
| Associates: MODIFIED           |   |                                |
|   (Active: Modified, Trunc)    |   |                                |
| Reads: "bar"                   |   |                                |
|                              +------->                              |
|                                |   | VE_CREATE:                     |
|                                |   |   Emits TRUNC|MODIFIED         |
|                                |   |      (Active: Modified, Trunc) |
|                                |   |     Sends MODIFIED             |
|                                |   |      (Active: Trunc)           |
|                                |   |     Sends TRUNC                |
|                                |   |      (Active: <none>)          |
|                                |   |                                |
|                                |   | FOP_FILE_WRITE "baz":          |
|                                |   |   Emits: MODIFIED              |
|                                |   |      (Active: <none>)          |
|                              <-------+                              |
| Gets: MODIFIED                 |   |                                |
| Associates: MODIFIED           |   |                                |
|   (Active: Modified)           |   |                                |
| Reads: <EOF>                   |   |                                |
|                                |   |                                |
| Gets: TRUNC                    |   |                                |
| Associates: TRUNC              |   |                                |
|   (Active: Trunc, Modified)    |   |                                |
| Seeks: 0                       |   |                                |

Note that in this case, "baz" was never read/emitted. (We seem to not hit this race very frequently on hardware because it is avoided if the VE_CREATE/FOP_FILE_WRITE sequence completes before tail processes its events, in which case the right thing will happen regardless of the ordering of the events.)

The fundamental problem is in the ordering of the events; instead of being effectively a stack whereby the last association is delivered first, the events need to be delivered in the order in which they are associated – and with respect to tail, it must construct its associations such that any pending truncate is always be delivered before any pending modification from the same event.

#3

Updated by Robert Mustacchi almost 6 years ago

  • Status changed from New to Resolved
  • % Done changed from 90 to 100

Resolved in 72102e7461c97dc268d21d9dd8f02da45f174acd.

Also available in: Atom PDF