Timestamp out of range; substituting 2514-05-30 01:53:03.999999999

OpenSubmitted by Roel Janssen.
Details
4 participants
  • Ludovic Courtès
  • Mathieu Othacehe
  • Mark H Weaver
  • Roel Janssen
Owner
unassigned
Severity
important
Merged with
R
R
Roel Janssen wrote on 5 Jan 2020 21:45
(address . bug-guix@gnu.org)
d2d7f1ef9036caa9134d29b0227c895511866ec3.camel@gnu.org
Dear Guix,
When inside a container produced with:$ guix environment -CN --ad-hoc ...
I encounter a problem when running "make" for some code base:make[3]: /gnu/store/5hkc9q38w6afhrf7xyz5ybxidr87d1mq-profile/include/syslog.h:Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
This causes subsequent invocations of "make" to (re)compile more than needed.
What can I do about it?
Kind regards,Roel Janssen
L
L
Ludovic Courtès wrote on 8 Jan 2020 22:58
(name . Roel Janssen)(address . roel@gnu.org)(address . 38958@debbugs.gnu.org)
87o8vdd2zq.fsf@gnu.org
Hi Roel,
Roel Janssen <roel@gnu.org> skribis:
Toggle quote (7 lines)> When inside a container produced with:> $ guix environment -CN --ad-hoc ...>> I encounter a problem when running "make" for some code base:> make[3]: /gnu/store/5hkc9q38w6afhrf7xyz5ybxidr87d1mq-profile/include/syslog.h:> Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
Fun. :-) What does “uname -rm” return?
What the value of the ‘TZ’ environment variable?
Can it be easily reproduced?
Thanks,Ludo’.
L
L
Ludovic Courtès wrote on 27 Jan 2020 22:50
control message for bug #38958
(address . control@debbugs.gnu.org)
87blqofu0t.fsf@gnu.org
tags 38958 + moreinfoquit
R
R
Roel Janssen wrote on 27 Mar 2020 10:26
Re: bug#38958: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 38958@debbugs.gnu.org)
8aab63ee4ca678aab40be28edbc6f3178d1c8acb.camel@gnu.org
On Wed, 2020-01-08 at 22:58 +0100, Ludovic Courtès wrote:
Toggle quote (22 lines)> Hi Roel,> > Roel Janssen <roel@gnu.org> skribis:> > > When inside a container produced with:> > $ guix environment -CN --ad-hoc ...> > > > I encounter a problem when running "make" for some code base:> > make[3]: /gnu/store/5hkc9q38w6afhrf7xyz5ybxidr87d1mq-> > profile/include/syslog.h:> > Timestamp out of range; substituting 2514-05-30 01:53:03.999999999> > Fun. :-) What does “uname -rm” return?> > What the value of the ‘TZ’ environment variable?> > Can it be easily reproduced?> > Thanks,> Ludo’.>
Sorry for the long delay. This issue had somehow resolved itself.
But now the issue resurfaced for me when building an older version of QtSvg(5.9.4). The 'TZ' environment variable is empty, and the output of "uname -rm"is:5.5.10-200.fc31.x86_64 x86_64
The package recipe is somewhat involved (it's part of a build for RStudio), butif you'd like I can attach it here.
Kind regards,Roel Janssen
L
L
Ludovic Courtès wrote on 27 Mar 2020 12:54
(name . Roel Janssen)(address . roel@gnu.org)(address . 38958@debbugs.gnu.org)
87v9mq57z5.fsf@gnu.org
Roel Janssen <roel@gnu.org> skribis:
Toggle quote (30 lines)> On Wed, 2020-01-08 at 22:58 +0100, Ludovic Courtès wrote:>> Hi Roel,>> >> Roel Janssen <roel@gnu.org> skribis:>> >> > When inside a container produced with:>> > $ guix environment -CN --ad-hoc ...>> > >> > I encounter a problem when running "make" for some code base:>> > make[3]: /gnu/store/5hkc9q38w6afhrf7xyz5ybxidr87d1mq->> > profile/include/syslog.h:>> > Timestamp out of range; substituting 2514-05-30 01:53:03.999999999>> >> Fun. :-) What does “uname -rm” return?>> >> What the value of the ‘TZ’ environment variable?>> >> Can it be easily reproduced?>> >> Thanks,>> Ludo’.>> >> Sorry for the long delay. This issue had somehow resolved itself.>> But now the issue resurfaced for me when building an older version of QtSvg> (5.9.4). The 'TZ' environment variable is empty, and the output of "uname -rm"> is:> 5.5.10-200.fc31.x86_64 x86_64
Previously you mentioned the problem was in ‘guix environment -C’, butnow you say it happens while running ‘guix build qtsvg’, right?
Is there a simple way to reproduce it?
Ludo’.
L
L
Ludovic Courtès wrote on 3 Sep 2020 10:54
(address . 38958@debbugs.gnu.org)
87lfhr1bra.fsf@gnu.org
Hi,
Roel Janssen <roel@gnu.org> skribis:
Toggle quote (4 lines)> I encounter a problem when running "make" for some code base:> make[3]: /gnu/store/5hkc9q38w6afhrf7xyz5ybxidr87d1mq-profile/include/syslog.h:> Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
This issue manifests itself in build environments as well; I’ve seen iton berlin while running “guix build guix --no-offload”:
Toggle snippet (40 lines)mv "doc/contributing.fr.texi.tmp" "doc/contributing.fr.texi" PO4A doc/contributing.zh_CN.teximv "doc/contributing.ru.texi.tmp" "doc/contributing.ru.texi"make: guix/store/schema.sql: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make: Warning: File 'guix/store/schema.sql' has modification time 15580747586 s in the future PO4A doc/guix-cookbook.de.texi[…]test ! -f guix.po || { \ if test -f ./guix.pot; then \ sed -f remove-potcdate.sed < ./guix.pot > guix.1po && \ sed -f remove-potcdate.sed < guix.po > guix.2po && \ if cmp guix.1po guix.2po >/dev/null 2>&1; then \ rm -f guix.1po guix.2po guix.po; \ else \ rm -f guix.1po guix.2po ./guix.pot && \ mv guix.po ./guix.pot; \ fi; \ else \ mv guix.po ./guix.pot; \ fi; \}make[3]: warning: Clock skew detected. Your build may be incomplete.make[3]: Leaving directory '/tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/po/guix'[…]make[2]: guix/base16.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: Warning: File 'guix/base16.scm' has modification time 15580748038 s in the futuremake[2]: guix/base32.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999[…]make[2]: guix/search-paths.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/import/gnu.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/import/snix.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/scripts/perform-download.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/scripts/authenticate.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/scripts/import/gnu.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/scripts/import/nix.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/scripts/import/texlive.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix/scripts/container.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999make[2]: guix.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
The files in question have mtime = Epoch + 1 as expected:
Toggle snippet (37 lines)$ stat /tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/guix/base16.scm File: /tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/guix/base16.scm Size: 3251 Blocks: 8 IO Block: 4096 regular fileDevice: 801h/2049d Inode: 10880988 Links: 1Access: (0444/-r--r--r--) Uid: (30001/guixbuilder01) Gid: (30000/guixbuild)Access: 2020-09-03 10:18:35.594069572 +0200Modify: 1970-01-01 00:00:01.000000000 +0100Change: 2020-09-03 10:18:27.670122206 +0200 Birth: 2020-09-03 10:18:27.670122206 +0200$ stat /tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/guix/base32.scm File: /tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/guix/base32.scm Size: 13325 Blocks: 32 IO Block: 4096 regular fileDevice: 801h/2049d Inode: 10881034 Links: 1Access: (0444/-r--r--r--) Uid: (30001/guixbuilder01) Gid: (30000/guixbuild)Access: 2020-09-03 10:18:35.594069572 +0200Modify: 1970-01-01 00:00:01.000000000 +0100Change: 2020-09-03 10:18:27.674122179 +0200 Birth: 2020-09-03 10:18:27.674122179 +0200$ stat /gnu/store/0br13w7y2wdfby74wnq7m7yzbx27hm1s-guix-1.1.0-25.44c6e6f-checkout/guix/base{16,32}.scm File: /gnu/store/0br13w7y2wdfby74wnq7m7yzbx27hm1s-guix-1.1.0-25.44c6e6f-checkout/guix/base16.scm Size: 3251 Blocks: 8 IO Block: 4096 regular fileDevice: 811h/2065d Inode: 344654478 Links: 10338Access: (0444/-r--r--r--) Uid: ( 0/ root) Gid: ( 0/ root)Access: 2020-09-03 09:36:43.818923620 +0200Modify: 1970-01-01 00:00:01.000000000 +0100Change: 2020-09-03 09:29:05.830024528 +0200 Birth: 2018-06-25 22:37:25.560482991 +0200 File: /gnu/store/0br13w7y2wdfby74wnq7m7yzbx27hm1s-guix-1.1.0-25.44c6e6f-checkout/guix/base32.scm Size: 13325 Blocks: 32 IO Block: 4096 regular fileDevice: 811h/2065d Inode: 344654504 Links: 9327Access: (0444/-r--r--r--) Uid: ( 0/ root) Gid: ( 0/ root)Access: 2020-09-03 09:36:43.822923593 +0200Modify: 1970-01-01 00:00:01.000000000 +0100Change: 2020-09-03 09:29:07.054016225 +0200 Birth: 2018-06-25 22:37:25.682483782 +0200
In the output of ‘make’ above, guix/import/gnu.scm is listed, but notguix/import/pypi.scm for instance. What’s the difference?
Toggle snippet (19 lines)$ stat /tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/guix/import/{gnu,pypi}.scm File: /tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/guix/import/gnu.scm Size: 4714 Blocks: 16 IO Block: 4096 regular fileDevice: 801h/2049d Inode: 10881084 Links: 1Access: (0444/-r--r--r--) Uid: (30001/guixbuilder01) Gid: (30000/guixbuild)Access: 2020-09-03 10:26:30.745348482 +0200Modify: 1970-01-01 00:00:01.000000000 +0100Change: 2020-09-03 10:26:23.029400312 +0200 Birth: 2020-09-03 10:26:23.029400312 +0200 File: /tmp/guix-build-guix-1.1.0-25.44c6e6f.drv-0/source/guix/import/pypi.scm Size: 23270 Blocks: 48 IO Block: 4096 regular fileDevice: 801h/2049d Inode: 10881093 Links: 1Access: (0444/-r--r--r--) Uid: (30001/guixbuilder01) Gid: (30000/guixbuild)Access: 2020-09-03 10:26:30.745348482 +0200Modify: 1970-01-01 01:00:01.000000000 +0100Change: 2020-09-03 10:26:23.029400312 +0200 Birth: 2020-09-03 10:26:23.029400312 +0200
Nothing obvious.
After checking the clock was fine, I turned off ntpd to be sure andspawned another build, but the result was the same.
This is happening on berlin with a recent kernel:
Toggle snippet (4 lines)$ uname -rm5.4.55-gnu x86_64
The GNU make warnings come from this impenetrable function:
Toggle snippet (23 lines)FILE_TIMESTAMPfile_timestamp_cons (const char *fname, time_t stamp, long int ns){ int offset = ORDINARY_MTIME_MIN + (FILE_TIMESTAMP_HI_RES ? ns : 0); FILE_TIMESTAMP s = stamp; FILE_TIMESTAMP product = (FILE_TIMESTAMP) s << FILE_TIMESTAMP_LO_BITS; FILE_TIMESTAMP ts = product + offset;
if (! (s <= FILE_TIMESTAMP_S (ORDINARY_MTIME_MAX) && product <= ts && ts <= ORDINARY_MTIME_MAX)) { char buf[FILE_TIMESTAMP_PRINT_LEN_BOUND + 1]; const char *f = fname ? fname : _("Current time"); ts = s <= OLD_MTIME ? ORDINARY_MTIME_MIN : ORDINARY_MTIME_MAX; file_timestamp_sprintf (buf, ts); OSS (error, NILF, _("%s: Timestamp out of range; substituting %s"), f, buf); }
return ts;}
What’s OLD_MTIME?
Toggle snippet (8 lines)/* The file does not exist, and we assume that it is older than any actual file. */#define OLD_MTIME 2
/* The smallest and largest ordinary timestamps. */#define ORDINARY_MTIME_MIN (OLD_MTIME + 1)
That would mean that any file with mtime < 3 is considered bogus, butthen, why wouldn’t things fail on other machines as well?
I’m looking for ideas! :-)
Ludo’.
M
M
Mathieu Othacehe wrote on 3 Sep 2020 13:54
control message for bug #38958
(address . control@debbugs.gnu.org)
878sdrdqjc.fsf@cervin.i-did-not-set--mail-host-address--so-tickle-me
merge 38958 42148quit
M
M
Mark H Weaver wrote on 3 Sep 2020 21:42
Re: bug#38958: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
87y2lq3avu.fsf@netris.org
Hi,
Ludovic Courtès <ludo@gnu.org> writes:
Toggle quote (40 lines)> The GNU┬ámake warnings come from this impenetrable function:>> --8<---------------cut here---------------start------------->8---> FILE_TIMESTAMP> file_timestamp_cons (const char *fname, time_t stamp, long int ns)> {> int offset = ORDINARY_MTIME_MIN + (FILE_TIMESTAMP_HI_RES ? ns : 0);> FILE_TIMESTAMP s = stamp;> FILE_TIMESTAMP product = (FILE_TIMESTAMP) s << FILE_TIMESTAMP_LO_BITS;> FILE_TIMESTAMP ts = product + offset;>> if (! (s <= FILE_TIMESTAMP_S (ORDINARY_MTIME_MAX)> && product <= ts && ts <= ORDINARY_MTIME_MAX))> {> char buf[FILE_TIMESTAMP_PRINT_LEN_BOUND + 1];> const char *f = fname ? fname : _("Current time");> ts = s <= OLD_MTIME ? ORDINARY_MTIME_MIN : ORDINARY_MTIME_MAX;> file_timestamp_sprintf (buf, ts);> OSS (error, NILF,> _("%s: Timestamp out of range; substituting %s"), f, buf);> }>> return ts;> }> --8<---------------cut here---------------end--------------->8--->> What’s OLD_MTIME?>> --8<---------------cut here---------------start------------->8---> /* The file does not exist, and we assume that it is older than any> actual file. */> #define OLD_MTIME 2>> /* The smallest and largest ordinary timestamps. */> #define ORDINARY_MTIME_MIN (OLD_MTIME + 1)> --8<---------------cut here---------------end--------------->8--->> That would mean that any file with mtime < 3 is considered bogus, but> then, why wouldn’t things fail on other machines as well?
I spent a bit of time looking at the relevant code in GNU Make. Thespecial MTIME values of 0, 1, and 2 seem to apply only to GNU Make's*internal* representation of the timestamp. 'file_timestamp_cons',which converts a standard POSIX time to the internal representation,seems to properly handle times near the POSIX epoch by addingORDINARY_MTIME_MIN (via 'offset') to the POSIX time, after multiplyingit by 2^30 (if FILE_TIMESTAMP_HI_RES is enabled).
Toggle quote (2 lines)> I’m looking for ideas! :-)
Note that the date printed in the warning (ORDINARY_MTIME_MAX),represented as a POSIX time (seconds past the epoch), is precisely 2^34seconds minus one nanosecond.
The problem doesn't seem to be that 'stamp' is too small, because if itwere, then the following line in 'file_timestamp_cons',
ts = s <= OLD_MTIME ? ORDINARY_MTIME_MIN : ORDINARY_MTIME_MAX;
would substitute ORDINARY_MTIME_MIN, which is close to the POSIX epoch,and the warning message would print a time near 1970, instead of onenear 2514 (ORDINARY_MTIME_MAX).
Rather, it appears that the 'stamp' passed into 'file_timestamp_cons'was close to or larger than 2^34, which is approximately the largesttimestamp that GNU make supports when FILE_TIMESTAMP is 64 bits andFILE_TIMESTAMP_HI_RES is enabled.
My guess is that maybe our near-zero timestamps are somewhere beingadjusted downwards by a timezone conversion, using an unsigned integertype, causing them to wrap around to near the maximum value of thattype.
Note that although 'stamp' usually comes from a file 'mtime' as returnedby stat(2), it can also come from an 'ar' archive member. Inmake-4.3/src/remake.c, 'f_mtime' includes the following code:
Toggle snippet (6 lines) member_date = ar_member_date (file->hname); mtime = (member_date == (time_t) -1 ? NONEXISTENT_MTIME : file_timestamp_cons (file->hname, member_date, 0));
Mark
L
L
Ludovic Courtès wrote on 16 Sep 2020 21:57
control message for bug #38958
(address . control@debbugs.gnu.org)
871rj1mr3v.fsf@gnu.org
severity 38958 importantquit
?
Your comment

Commenting via the web interface is currently disabled.

To comment on this conversation send email to 38958@debbugs.gnu.org