[ntp:questions] Popcorn on prefer takes out system clock

unruh unruh at invalid.ca
Thu Mar 8 16:01:07 UTC 2012


On 2012-03-08, A C <agcarver+ntp at acarver.net> wrote:
> On 3/7/2012 15:38, unruh wrote:
>> On 2012-03-07, A C<agcarver+ntp at acarver.net>  wrote:
>>> On 3/6/2012 20:34, Dave Hart wrote:
>>>> On Wed, Mar 7, 2012 at 01:32,<Null at blacklist.anitech-systems.invalid>   wrote:
>>>>> Dave Hart wrote:
>>>>>> A C<agcarver+ntp at acarver.net>   wrote:
>>>>>>> 130.207.165.28 944d 8d popcorn 2147483647.997598 s
>>>>>>
>>>>>> I assume you mean in the local ntpd log on your sparc box
>>>>>>    referring to the IP address that used to be marked prefer.
>>>>>> I realize not everyone is a programmer, but the number
>>>>>>    above jumped out at me as suspiciously round in hex
>>>>>>    and binary.  Sure enough, round it to whole seconds
>>>>>>    and you have 2^31 or 0x80000000.  Incredible coincidence?
>>>>>
>>>>> -0.002402 ?
>>>>
>>>> Nope.  NTP's 32:32 l_fp is used for both unsigned timestamps and
>>>> signed differences between timestamps (intervals or offsets).  In both
>>>> cases the fractional part is unsigned and positive.  For offsets, the
>>>> integer part is signed, so -0.002402 would be -1 seconds plus
>>>> 0.997598, or in hex 0xffffffff.0xf.......  In this case we have an
>>>> unambiguously positive value 0x7fffffff.0xf....... or just over +68
>>>> years.
>>>
>>> Interestingly the same remote server just popcorned again but this time
>>> the number was still huge though less than a full overflow:
>>>
>>>
>>> 130.207.165.28 901d 8d popcorn 202238.338413 s
>>
>> Is it delivering a KOD packet? What is that server running? Do you have
>> peers enabled and can you look at the output of the peers file when that
>> weird measurement comes in? It would be nice if one could see all four
>> times in the ntp packet for that situation, to see if it is your machine
>> or the remote machine that is putting in absurd times into the packet
>> (or if ntpd is misinterpreting something and causing the problem
>> itself.) Unfortunately I do not think that there is any debug flag that
>> can tell ntpd to report all four of those times on a bad packet. (I
>> suppose you could hack the source to have it do that)
>
>
> The peer records for that particular server.  Five polls prior to the 
> major event (the popcorn 2147483647.997598 s), the event itself, and 
> five polls after:

Well, I am confused. (It would really really be nice if ntp inserted an
explanation for the peerstats output  into the file, instead of having
to root about in the source code). The peerstats file seems to be
      fprintf(peerstats.fp,
          "%lu %s %s %x %.9f %.9f %.9f %.9f\n",
          day, ulfptoa(&now, 3), stoa(addr), status, offset,
          delay, dispersion, skew);

which would indicate that the there is nothing surprizing that is
happening to the measured offsets during that time, but the dispersion
goes crazy, for no reason that I can see. 


>
> 55992 28127.756 130.207.165.28  9014 -0.170051294  0.078942366 
> 7.937562104  0.000122070
> 55992 28129.677 130.207.165.28  9014 -0.179983358  0.077845506 
> 3.937600648  0.009932064
> 55992 28133.799 130.207.165.28  9014 -0.199691829  0.077621280 
> 0.937640806  0.021355778
> 55992 28408.122 130.207.165.28  9024 -0.006291682  0.078885845 
> 7.937562104  0.000122070
> 55992 28409.830 130.207.165.28  9024 -0.016024622  0.078550234 
> 3.937600653  0.009732940
> 55992 28411.834 130.207.165.28  9024 -0.026350192  0.077996043 
> 9225.801161582  0.015952448
> 55992 28413.833 130.207.165.28  9024 -0.036352381  0.078129313 
> 0.937637060  0.021732520
> 55992 28415.829 130.207.165.28  963a -0.041918036  0.077468683 
> 0.437644685  0.023521481
> 55992 28417.863 130.207.165.28  963a -0.041216188  0.077486681 
> 0.187648967  0.020491380
> 55992 28476.861 130.207.165.28  943a -0.011773862  0.078609389 
> 0.063072171  0.020977043
> 55992 28542.857 130.207.165.28  943a  0.000470710  0.079669255 
> 0.000839328  0.029465863
>
> This is for the later event of 202238.338413 s popcorn
>
> 55993 28733.851 130.207.165.28  944d  0.001442344  0.077783855 
> 0.003718608  0.000174640
> 55993 29065.885 130.207.165.28  904d  0.001781094  0.077855594 
> 0.004514781  0.000271580
> 55993 29263.848 130.207.165.28  944d  0.001515211  0.077869762 
> 0.004768669  0.000225611
> 55993 29397.858 130.207.165.28  944d  0.001499231  0.077956490 
> 0.005274452  0.000200836
> 55993 29525.860 130.207.165.28  944d  0.001522830  0.077973892 
> 0.003356092  0.000185364
> 55993 29781.861 130.207.165.28  944d  202238.340010876  0.077839850 
> 1.518925725  202238.338406371
> 55993 30374.867 130.207.165.28  941d  0.001488131  0.078009916 
> 0.005926894  0.000356562
> 55993 30439.861 130.207.165.28  941d  0.001620819  0.078177454 
> 0.002953087  0.000259219
> 55993 30568.902 130.207.165.28  941d  0.001570695  0.077985387 
> 0.001762402  0.000288896
> 55993 30766.859 130.207.165.28  941d  0.001727346  0.077951527 
> 0.001585799  0.000266961
> 55993 30897.850 130.207.165.28  941d  0.001619869  0.077850728 
> 0.001662438  0.000143900
>
> I happened to notice the time of day is close for each event, the events 
> are almost 24 hours apart.  I'll see what happens later tonight (the 
> clock only shows 22120 seconds right now)



More information about the questions mailing list