| Subject: | Race condition in 'checkpending' when file is truncated |
While fixing a race condition in 'checkpending'/'reset_pointers' (bug report to be created soon) I spotted another race condition.
v1.3 of File::Tail contains:
sub checkpending {
my $object=shift @_;
my $old_lastcheck = $object->{lastcheck};
$object->{"lastcheck"}=time;
unless ($object->{handle}) {
$object->reset_pointers;
unless ($object->{handle}) { # This try did not open the file either
return 0;
}
}
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
if ($object->{"endpos"}<$object->{curpos}) { # file was truncated
$object->position;
} elsif (($object->{curpos}==$object->{"endpos"})
&& (time()-$object->{lastread})>$object->{'resetafter'}) {
$object->reset_pointers;
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
}
if ($object->{"endpos"}-$object->{curpos}) {
sysseek($object->{handle},$object->{curpos},SEEK_SET);
readin($object,$object->{"endpos"}-$object->{curpos});
}
return ($object->{"endpos"}-$object->{curpos});
}
If file is truncated after:
$object->reset_pointers;
and before
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
then result will be:
$object->{"endpos"}: set to new file size
$object->{"curpos"}: set to last byte that was read before being truncated
this then causes File::Tail::read to return instantly and *not* return data.. (and when it's called in a while loop it keeps the CPU busy)
Triggering the race condition is easiest if code is slightly altered:
$object->reset_pointers;
print STDERR "# Time to trigger race condition (sleeping 5 seconds)\n";
sleep 5;
print STDERR "# Done sleeping\n";
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
Running it: first create file '/tmp/foo' with contents 'foo' (`echo foo > /tmp/foo`)
Then run:
#!/usr/bin/perl
use strict;
use warnings;
use File::Tail;
my $f = File::Tail->new(name => "/tmp/foo", maxinterval => 1, tail => 0);
print while (defined ($_ = $f->read()));
When it prints "Time to trigger race condition": truncate the file: (`echo a > /tmp/foo`)
Checking running processes shows that's using 100% CPU, new data added in the file is also not printed..
What happens:
- in 'checkpending': number of bytes to read is calculated as '$object->{"endpos"} - $object->{"curpos"}': this becomes a negative number.
- 'readin' is called with a negative length but this ignores it (ok I guess)
- 'read' is called (by the calling script): this first check if there is pending data by calculating: '$object->{"endpos"} - $object->{"curpos"}'. This too is negative..
What happens next: 'read' compares this number with 0; if it's not zero it calls readin() (which ignores the negative number) and then returns empty string
- script then calls 'read' again and same thing happens
Fixing this race condition: in 'checkpending' checking if file is truncated should be done *after* $object->{"endpos"} is updated (which is done after call to 'reset_pointers').
That is:
...
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
if (($object->{curpos}==$object->{"endpos"})
&& (time()-$object->{lastread})>$object->{'resetafter'}) {
$object->reset_pointers;
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
}
if ($object->{"endpos"}<$object->{curpos}) { # file was truncated
$object->position;
}
...
| Subject: | 003-truncated_race.patch |
diff --git a/Tail.pm b/Tail.pm
index 068ac74..dc7acc9 100644
--- a/Tail.pm
+++ b/Tail.pm
@@ -425,14 +425,16 @@ sub checkpending {
}
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
- if ($object->{"endpos"}<$object->{curpos}) { # file was truncated
- $object->position;
- } elsif (($object->{curpos}==$object->{"endpos"})
+ if (($object->{curpos}==$object->{"endpos"})
&& (time()-$object->{lastread})>$object->{'resetafter'}) {
$object->reset_pointers;
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
}
+ if ($object->{"endpos"}<$object->{curpos}) { # file was truncated
+ $object->position;
+ }
+
if ($object->{"endpos"}-$object->{curpos}) {
sysseek($object->{handle},$object->{curpos},SEEK_SET);
}
diff --git a/Tail.pm.debug b/Tail.pm.debug
index 683776b..5abdd53 100644
--- a/Tail.pm.debug
+++ b/Tail.pm.debug
@@ -440,15 +440,17 @@ sub checkpending {
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
$object->logit("endposition = ".$object->{curpos});
- if ($object->{"endpos"}<$object->{curpos}) { # file was truncated
- logit($object,"File was truncated - resetting position");
- $object->position;
- } elsif (($object->{curpos}==$object->{"endpos"})
+ if (($object->{curpos}==$object->{"endpos"})
&& (time()-$object->{lastread})>$object->{'resetafter'}) {
$object->reset_pointers;
$object->{"endpos"}=sysseek($object->{handle},0,SEEK_END);
}
+ if ($object->{"endpos"}<$object->{curpos}) { # file was truncated
+ logit($object,"File was truncated - resetting position");
+ $object->position;
+ }
+
if ($object->{"endpos"}-$object->{curpos}) {
sysseek($object->{handle},$object->{curpos},SEEK_SET);
}