Glenn Golden <g...@zplane.com> [2023-02-02 15:55:51 -0700]: > Pádraig Brady <p...@draigbrady.com> [2023-02-01 20:37:47 +0000]: > > > > That was informative thanks. > > > > What I think is happening is that to support --follow=name tail(1) operates > > in non blocking mode so that it doesn't block when reading a file, and has > > the opportunity to recheck. > > > > Now it determines when a read() shouldn't block by doing stat() and if size > > or mtime haven't changed, then it doesn't perform the read. In fact for non > > regular files it only goes on the mtime, which I guess is not changing for > > your device. > > > > Yes, that appears to be the case: The mtime is evidently updated only when > the USB host writes to the device; data arriving from the device to the host > does not update mtime. > > > > > Note if you were just doing --follow=descriptor on a single file tail(1) > > would operate in a simpler blocking manner and would work fine with your > > device I expect (not through the changing symlink of course). > > > > I think following by descriptor can't really work reliably for this case, > because the tail process, even though it operates in blocking mode as you say, > nevertheless kind of heisenbergs the situation because it holds the original > fd open, which in turn causes the USB driver to assign a new minor device > number to the device upon its reboot. And that effectively dissociates the > original fd from the device. So tail thereafter just sees EOF forever. > > Example: Suppose the original file descriptor that dev/ttyPSLOG points to > is /dev/ttyACM0, and tail has been successfully following that via > --follow=descriptor in blocking mode. Then the device reboots. Upon > detecting the reincarnated device, the driver sees that /dev/ttyACM0 is > still open (because tail hasn't explicitly close()d it, despite the fact > that there's no longer a device behind it and he keeps getting EOF on > every read()). So because /dev/ttyACM0 is still marked as "open", the > driver winds up assigning the reincarnated device a new interface name based > on the next available minor device number, e.g. /dev/ttyACM1. As a result, > the original fd is left pointing to /dev/ttyACM0, which no longer exists > in the filesystem, and read() returns EOF forever. (Why doesn't it instead > return in error upon disappearance of the original device node? I don't know. > But "EOF forever" is what is observed with strace.) > > In contrast, if tail -- or any other process for that matter -- did not have > the original fd open when the reboot occurred, only then would the driver > (probably) wind up reassigning /dev/ttyACM0 to the device. > > So, perversely, it is the tail process itself, by holding the fd open, > that prevents the behavior we'd like with --follow=descriptor. > > > > > I wonder could we try the read() anyway when operating on a > > a single non regular file that has successfully been set in non blocking > > mode? > > In that case we shouldn't block and read() would return 0 if no data. > > I haven't thought about that much, but the diff below should do it. > > At least it shows the part of the code involved, > > which compares the various stat() members to determine to read or not. > > Perhaps you could add debugging there (or strace -v -e fstat,newfstatat > > ...). > > For example to see if st_size changes for you > > (I don't think there is any other stat member we could key on). > > > > Ok, thanks. Let me fiddle around with your updated patch (the one named > "tail-F-dev.patch") and I'll let you know what I find. >
Your two patches (the one mentioned above and the earlier one avoiding the xlseek() on a non-regular file) do almost fix the problem, but not quite. I added one additional mod, and with that, it now seems to address the issue fully. (And doesn't seem to break any "make check" tests.) See what you think. Summary comments up top. Thanks, - Glenn
diff --git a/ORIGtail.c b/tail_p2g1.c index 2244509dd..c992d22fd 100644 --- a/ORIGtail.c +++ b/tail_p2g1.c @@ -1,3 +1,40 @@ +//=========================================================================== +// Modified version of tail.c, based against git version 9.1.139-b5904, +// to address the issue described in +// +// https://lists.gnu.org/archive/html/coreutils/2023-01/msg00030.html +// +// It incorporates Padraig's informal mods and patches from that thread, +// along with some additional debug code and a further patch added by me, +// as follows: +// +// 1. Padraig's inline diff from his coreutils email dated +// 30 Jan 2023 21:27:50 +0000. +// +// 2. The untested patch named tail-F-dev.patch attached to Padraig's email +// dated 1 Feb 2023 21:25:40 +0000. (This patch almost, but not quite, +// fixes the problem; with only this patch and the one above applied, +// dump_remainder() dies with EBADF.) +// +// 3. Various GDG debug printfs, noted in this file by "GDG: debug +// print only", added to understand why the above two patches did not +// quite fix the problem. These printfs can be enabled/disabled via +// static global "show_gdg_printfs", which is defined just before usage(). +// +// 4. An additional mod to Padraig's patches above, which seems to fully +// address the problem, without breaking any "make check" tests. This +// mod is noted in the code by "GDG: Functional change", and is +// commented in detail at that point. +// +// NOTE: This file does _not_ include the inline diff from Padraig's email +// dated 1 Feb 2023 20:37:47 +0000 (which he subsequently noted shortly +// thereafter would not work). +// +// - gdg, 2023.02.05 +// +//=========================================================================== + + /* tail -- output the last part of file(s) Copyright (C) 1989-2023 Free Software Foundation, Inc. @@ -256,6 +293,11 @@ static struct option const long_options[] = {NULL, 0, NULL, 0} }; +// +// GDG: If set, GDG printfs are emitted. +// +static int show_gdg_printfs = 0; + void usage (int status) { @@ -462,6 +504,13 @@ static uintmax_t dump_remainder (bool want_header, char const *pretty_filename, int fd, uintmax_t n_bytes) { + // GDG: debug print only + if (show_gdg_printfs) + { + error(0, 0, _("dump_remainder(fn=%s, fd=%d)"), + quoteaf (pretty_filename), fd); + } + uintmax_t n_written; uintmax_t n_remaining = n_bytes; @@ -1001,6 +1050,12 @@ recheck (struct File_spec *f, bool blocking) assert (valid_file_spec (f)); + // GDG: debug print only + if (show_gdg_printfs) + { + error (0, 0, _("recheck(): open(%s,%d)"), quoteaf (pretty_name (f)), fd); + } + /* If the open fails because the file doesn't exist, then mark the file as not tailable. */ f->tailable = !(reopen_inaccessible_files && fd == -1); @@ -1104,12 +1159,24 @@ recheck (struct File_spec *f, bool blocking) /* Close the old one. */ close_fd (f->fd, pretty_name (f)); + // GDG: debug print only + if (show_gdg_printfs) + { + error (0, 0, _("recheck(): close_fd(%d, %s) in Clause 1"), + f->fd, quoteaf (pretty_name (f))); + } } else { /* No changes detected, so close new fd. */ close_fd (fd, pretty_name (f)); + // GDG: debug print only + if (show_gdg_printfs) + { + error (0, 0, _("recheck(): close_fd(%d, %s) in Clause 2"), + fd, quoteaf (pretty_name (f))); + } } /* FIXME: When a log is rotated, daemons tend to log to the @@ -1122,7 +1189,8 @@ recheck (struct File_spec *f, bool blocking) { /* Start at the beginning of the file. */ record_open_fd (f, fd, 0, &new_stats, (is_stdin ? -1 : blocking)); - xlseek (fd, 0, SEEK_SET, pretty_name (f)); + if (S_ISREG (new_stats.st_mode)) + xlseek (fd, 0, SEEK_SET, pretty_name (f)); } } @@ -1221,6 +1289,9 @@ tail_forever (struct File_spec *f, size_t n_files, double sleep_interval) f[i].blocking = blocking; } + // This flag added by Padraig's tail-F-dev.patch + bool read_unchanged = false; + if (!f[i].blocking) { if (fstat (fd, &stats) != 0) @@ -1240,10 +1311,28 @@ tail_forever (struct File_spec *f, size_t n_files, double sleep_interval) <= f[i].n_unchanged_stats++) && follow_mode == Follow_name) { + // GDG: debug print only + if (show_gdg_printfs) + { + error(0, 0, + _("tail_forever(fd=%d): Call recheck()"), fd); + } recheck (&f[i], f[i].blocking); f[i].n_unchanged_stats = 0; } - continue; + if (S_ISREG (stats.st_mode) || 1 < n_files) + continue; + else + { + // GDG: debug print only + if (show_gdg_printfs) + { + error(0, 0, + _("tail_forever(fd=%d): Set read_unchanged=true"), + fd); + } + read_unchanged = true; + } } /* This file has changed. Print out what we can, and @@ -1252,8 +1341,40 @@ tail_forever (struct File_spec *f, size_t n_files, double sleep_interval) f[i].mtime = get_stat_mtime (&stats); f[i].mode = stats.st_mode; + // + // GDG: Functional change. + // + // At this point in the non-blocking clause, the assumption is + // that the recheck() call above has found that the file has + // changed, so it's necessary to re-point local variable fd to + // the new file descriptor obtained by recheck()'s call to + // record_open_fd(); that new file descriptor is f[i]->fd. + // + // If this re-point of fd is not done, them the fd corresponding + // to the old (now-closed) file winds up being used in the call + // to dump_remainder() further below, leading to EBADF. + // + // I am not 100% confident that this change is entirely correct + // as-is; only that it (a) seems to make sense superficially, + // (b) does seem to fix the particular problem being studied, + // and (c) does not cause any of the "make check" tests to fail. + // However, due to my unfamiliarity with the code and the less + // than transparent logic flow in this clause, it is certainly + // possible that this putative fix is still not quite right and + // winds up breaking something else in some subtle way. + // + // However: If this change _is_ deemed to be correct, then it + // would seem to imply that the use of 'fd' in the regular-file + // case in the 'XXX heuristic' clause below (where fd is used as + // an arg to xlseek()) may also be historically wrong. As to how + // it could ever haved worked when seeking on a closed fd... + // I have no clue. Perhaps that clause was never being invoked. + // + fd = f[i].fd; + /* reset counter */ - f[i].n_unchanged_stats = 0; + if (! read_unchanged) + f[i].n_unchanged_stats = 0; /* XXX: This is only a heuristic, as the file may have also been truncated and written to if st_size >= size @@ -1286,8 +1407,18 @@ tail_forever (struct File_spec *f, size_t n_files, double sleep_interval) else bytes_to_read = COPY_TO_EOF; + // GDG: debug print only + if (show_gdg_printfs) + { + error(0, 0, + _("tail_forever(): call dump_remainder(name=%s, fd=%d)"), + quoteaf (name), fd); + } bytes_read = dump_remainder (false, name, fd, bytes_to_read); + if (read_unchanged && bytes_read) + f[i].n_unchanged_stats = 0; + any_input |= (bytes_read != 0); f[i].size += bytes_read; }
