GNU bug report logs - #38958
Timestamp out of range; substituting 2514-05-30 01:53:03.999999999

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 38958 in the body.
You can then email your comments to 38958 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Roel Janssen <roel <at> gnu.org>
To: bug-guix <at> gnu.org
Subject: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
Date: Sun, 05 Jan 2020 21:45:01 +0100

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

Message #8 received at 38958 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Roel Janssen <roel <at> gnu.org>
Cc: 38958 <at> debbugs.gnu.org
Subject: Re: bug#38958: Timestamp out of range;
 substituting 2514-05-30 01:53:03.999999999
Date: Wed, 08 Jan 2020 22:58:49 +0100

Hi Roel,

Roel Janssen <roel <at> 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’.

Message #13 received at 38958 <at> debbugs.gnu.org (full text, mbox):

From: Roel Janssen <roel <at> gnu.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 38958 <at> debbugs.gnu.org
Subject: Re: bug#38958: Timestamp out of range; substituting 2514-05-30
 01:53:03.999999999
Date: Fri, 27 Mar 2020 10:26:21 +0100

On Wed, 2020-01-08 at 22:58 +0100, Ludovic Courtès wrote:
> Hi Roel,
> 
> Roel Janssen <roel <at> 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), but
if you'd like I can attach it here.

Kind regards,
Roel Janssen

Message #16 received at 38958 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Roel Janssen <roel <at> gnu.org>
Cc: 38958 <at> debbugs.gnu.org
Subject: Re: bug#38958: Timestamp out of range;
 substituting 2514-05-30 01:53:03.999999999
Date: Fri, 27 Mar 2020 12:54:06 +0100

Roel Janssen <roel <at> gnu.org> skribis:

> On Wed, 2020-01-08 at 22:58 +0100, Ludovic Courtès wrote:
>> Hi Roel,
>> 
>> Roel Janssen <roel <at> 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’, but
now you say it happens while running ‘guix build qtsvg’, right?

Is there a simple way to reproduce it?

Ludo’.

Message #19 received at 38958 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 38958 <at> debbugs.gnu.org
Subject: Re: bug#38958: Timestamp out of range;
 substituting 2514-05-30 01:53:03.999999999
Date: Thu, 03 Sep 2020 10:54:17 +0200

Hi,

Roel Janssen <roel <at> gnu.org> skribis:

> 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 it
on berlin while running “guix build guix --no-offload”:

--8<---------------cut here---------------start------------->8---
mv "doc/contributing.fr.texi.tmp" "doc/contributing.fr.texi"
  PO4A doc/contributing.zh_CN.texi
mv "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.999999999
make: 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.999999999
make[2]: Warning: File 'guix/base16.scm' has modification time 15580748038 s in the future
make[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.999999999
make[2]: guix/import/gnu.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix/import/snix.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix/scripts/perform-download.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix/scripts/authenticate.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix/scripts/import/gnu.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix/scripts/import/nix.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix/scripts/import/texlive.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix/scripts/container.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
make[2]: guix.scm: Timestamp out of range; substituting 2514-05-30 01:53:03.999999999
--8<---------------cut here---------------end--------------->8---

The files in question have mtime = Epoch + 1 as expected:

--8<---------------cut here---------------start------------->8---
$ 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 file
Device: 801h/2049d      Inode: 10880988    Links: 1
Access: (0444/-r--r--r--)  Uid: (30001/guixbuilder01)   Gid: (30000/guixbuild)
Access: 2020-09-03 10:18:35.594069572 +0200
Modify: 1970-01-01 00:00:01.000000000 +0100
Change: 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 file
Device: 801h/2049d      Inode: 10881034    Links: 1
Access: (0444/-r--r--r--)  Uid: (30001/guixbuilder01)   Gid: (30000/guixbuild)
Access: 2020-09-03 10:18:35.594069572 +0200
Modify: 1970-01-01 00:00:01.000000000 +0100
Change: 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 file
Device: 811h/2065d      Inode: 344654478   Links: 10338
Access: (0444/-r--r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2020-09-03 09:36:43.818923620 +0200
Modify: 1970-01-01 00:00:01.000000000 +0100
Change: 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 file
Device: 811h/2065d      Inode: 344654504   Links: 9327
Access: (0444/-r--r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2020-09-03 09:36:43.822923593 +0200
Modify: 1970-01-01 00:00:01.000000000 +0100
Change: 2020-09-03 09:29:07.054016225 +0200
 Birth: 2018-06-25 22:37:25.682483782 +0200
--8<---------------cut here---------------end--------------->8---

In the output of ‘make’ above, guix/import/gnu.scm is listed, but not
guix/import/pypi.scm for instance.  What’s the difference?

--8<---------------cut here---------------start------------->8---
$ 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 file
Device: 801h/2049d      Inode: 10881084    Links: 1
Access: (0444/-r--r--r--)  Uid: (30001/guixbuilder01)   Gid: (30000/guixbuild)
Access: 2020-09-03 10:26:30.745348482 +0200
Modify: 1970-01-01 00:00:01.000000000 +0100
Change: 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 file
Device: 801h/2049d      Inode: 10881093    Links: 1
Access: (0444/-r--r--r--)  Uid: (30001/guixbuilder01)   Gid: (30000/guixbuild)
Access: 2020-09-03 10:26:30.745348482 +0200
Modify: 1970-01-01 01:00:01.000000000 +0100
Change: 2020-09-03 10:26:23.029400312 +0200
 Birth: 2020-09-03 10:26:23.029400312 +0200
--8<---------------cut here---------------end--------------->8---

Nothing obvious.

After checking the clock was fine, I turned off ntpd to be sure and
spawned another build, but the result was the same.

This is happening on berlin with a recent kernel:

--8<---------------cut here---------------start------------->8---
$ uname -rm
5.4.55-gnu x86_64
--8<---------------cut here---------------end--------------->8---

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’m looking for ideas!  :-)

Ludo’.

Message #24 received at 38958 <at> debbugs.gnu.org (full text, mbox):

From: Mark H Weaver <mhw <at> netris.org>
To: Ludovic Courtès <ludo <at> gnu.org>, 38958 <at> debbugs.gnu.org
Subject: Re: bug#38958: Timestamp out of range; substituting 2514-05-30
 01:53:03.999999999
Date: Thu, 03 Sep 2020 15:42:02 -0400

Hi,

Ludovic Courtès <ludo <at> gnu.org> writes:

> 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.  The
special 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 adding
ORDINARY_MTIME_MIN (via 'offset') to the POSIX time, after multiplying
it by 2^30 (if FILE_TIMESTAMP_HI_RES is enabled).

> 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^34
seconds minus one nanosecond.

The problem doesn't seem to be that 'stamp' is too small, because if it
were, 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 one
near 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 largest
timestamp that GNU make supports when FILE_TIMESTAMP is 64 bits and
FILE_TIMESTAMP_HI_RES is enabled.

My guess is that maybe our near-zero timestamps are somewhere being
adjusted downwards by a timezone conversion, using an unsigned integer
type, causing them to wrap around to near the maximum value of that
type.

Note that although 'stamp' usually comes from a file 'mtime' as returned
by stat(2), it can also come from an 'ar' archive member.  In
make-4.3/src/remake.c, 'f_mtime' includes the following code:

--8<---------------cut here---------------start------------->8---
      member_date = ar_member_date (file->hname);
      mtime = (member_date == (time_t) -1
               ? NONEXISTENT_MTIME
               : file_timestamp_cons (file->hname, member_date, 0));
--8<---------------cut here---------------end--------------->8---

      Mark

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.