RE: [chrony-users] kernel PPS troubleshooting

["Battocchi, Scott L." <Scott.Battocchi@xxxxxxxxxx>]

Miraslov,
Thanks for the modified source,  I've recompiled it with --enable-trace and do indeed get a lot more information.
I modified the original chrony.conf to drop the external gps (GPSe/PPSe) since they were generating a lot of sample ignored trace messages (no valid fix and no updating pps), so the reports below are with only the GPSi/PPSi sources active in the configuration.

I've tried to copy key portions of the run below to avoid attaching the 5MB trace log, I'm open to other methods of sharing the whole log if there is interest.  I have attached the tracking.log since it shows when PPS was available compared to the long periods where GPS was active (and the PPS was coming into /dev/pps1).  It looks like the pulse is ignored when offdiff is relatively large (>0.2?), but that the offdiff steps very quickly between valid and invalid.  It is also possible I'm interpreting the pulse handling completely incorrectly.

Starting the modified chrony all appears well for a while but within a couple of minutes most of the PPS pulses are ignored.  PPS goes in and out of being ignored for the next ~5 minutes before disappearing for another 90 minutes.  After that brief recovery, it is ignored for the rest of the run:
:~/chronytrace# ./chrony [Jd -d
main.c:355:(main)[26-18:00:28] chronyd version DEVELOPMENT starting
sys_linux.c:1022:(get_version_specific_details)[26-18:00:28] Linux kernel major=3 minor=3 patch=0
sys_linux.c:1080:(get_version_specific_details)[26-18:00:28] hz=100 shift_hz=7 freq_scale=1.00000000 nominal_tick=10000 slew_delta_tick=833 max_tick_bias=1000 shift_pll=2
local.c:565:(lcl_RegisterSystemDrivers)[26-18:00:28] Local freq=297.043ppm
refclock.c:253:(RCL_AddRefclock)[26-18:00:28] refclock PPS added poll=4 dpoll=0 filter=16
refclock.c:253:(RCL_AddRefclock)[26-18:00:28] refclock SHM added poll=4 dpoll=0 filter=16
reference.c:194:(REF_Initialise)[26-18:00:28] Initial frequency 297.043 ppm
sources.c:331:(SRC_SetSelectable)[26-18:00:28] PPSi
sources.c:331:(SRC_SetSelectable)[26-18:00:28] GPSi
refclock.c:416:(RCL_AddPulse)[26-18:00:28] refclock pulse ignored no ref sample
refclock.c:687:(filter_add_sample)[26-18:00:28] filter sample 0 t=Tue 11/26/13 18:00:28.080062 offset=1.059937008 dispersion=0.000003000
refclock.c:440:(RCL_AddPulse)[26-18:00:29] refclock pulse ignored offdiff=-0.459021095 refdisp=0.000003000 disp=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:29] filter sample 1 t=Tue 11/26/13 18:00:29.060753 offset=1.079246196 dispersion=0.000003000
refclock.c:440:(RCL_AddPulse)[26-18:00:30] refclock pulse ignored offdiff=-0.440026443 refdisp=0.000003000 disp=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:30] filter sample 2 t=Tue 11/26/13 18:00:30.076668 offset=1.063331638 dispersion=0.000003000
refclock.c:440:(RCL_AddPulse)[26-18:00:31] refclock pulse ignored offdiff=-0.456248500 refdisp=0.000003000 disp=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:31] filter sample 3 t=Tue 11/26/13 18:00:31.121044 offset=1.018955039 dispersion=0.000003000
refclock.c:440:(RCL_AddPulse)[26-18:00:32] refclock pulse ignored offdiff=0.499073485 refdisp=0.000003000 disp=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:32] filter sample 4 t=Tue 11/26/13 18:00:32.121227 offset=1.018772016 dispersion=0.000003000
refclock.c:440:(RCL_AddPulse)[26-18:00:33] refclock pulse ignored offdiff=0.498576090 refdisp=0.000003000 disp=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:33] filter sample 5 t=Tue 11/26/13 18:00:32.702642 offset=1.437357065 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:34] refclock pulse second=0.479480414 offset=1.520519586 offdiff=-0.083162521 samplediff=0.776838000
refclock.c:687:(filter_add_sample)[26-18:00:34] filter sample 0 t=Tue 11/26/13 18:00:33.479480 offset=1.520519586 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:34] filter sample 6 t=Tue 11/26/13 18:00:33.704596 offset=1.435403234 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:35] refclock pulse second=0.479162252 offset=1.520837748 offdiff=-0.085434514 samplediff=0.774566000
refclock.c:687:(filter_add_sample)[26-18:00:35] filter sample 1 t=Tue 11/26/13 18:00:34.479162 offset=1.520837748 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:35] filter sample 7 t=Tue 11/26/13 18:00:34.692316 offset=1.447683341 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:36] refclock pulse second=0.478844465 offset=1.521155535 offdiff=-0.073472194 samplediff=0.786528000
refclock.c:687:(filter_add_sample)[26-18:00:36] filter sample 2 t=Tue 11/26/13 18:00:35.478844 offset=1.521155535 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:36] filter sample 8 t=Tue 11/26/13 18:00:35.708774 offset=1.431225071 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:37] refclock pulse second=0.478551879 offset=1.521448121 offdiff=-0.090223050 samplediff=0.769777000
refclock.c:687:(filter_add_sample)[26-18:00:37] filter sample 3 t=Tue 11/26/13 18:00:36.478551 offset=1.521448121 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:37] filter sample 9 t=Tue 11/26/13 18:00:36.689137 offset=1.450862826 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:38] refclock pulse second=0.478238465 offset=1.521761535 offdiff=-0.070898709 samplediff=0.789101000
refclock.c:687:(filter_add_sample)[26-18:00:38] filter sample 4 t=Tue 11/26/13 18:00:37.478238 offset=1.521761535 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:38] filter sample 10 t=Tue 11/26/13 18:00:37.700018 offset=1.439981899 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:39] refclock pulse second=0.477923470 offset=1.522076530 offdiff=-0.082094631 samplediff=0.777905000
refclock.c:687:(filter_add_sample)[26-18:00:39] filter sample 5 t=Tue 11/26/13 18:00:38.477923 offset=1.522076530 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:39] filter sample 11 t=Tue 11/26/13 18:00:38.701811 offset=1.438188064 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:40] refclock pulse second=0.477597518 offset=1.522402482 offdiff=-0.084214418 samplediff=0.775786000
refclock.c:687:(filter_add_sample)[26-18:00:40] filter sample 6 t=Tue 11/26/13 18:00:39.477597 offset=1.522402482 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:40] filter sample 12 t=Tue 11/26/13 18:00:39.707686 offset=1.432313023 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:41] refclock pulse second=0.476959778 offset=1.523040222 offdiff=-0.090727199 samplediff=1.769273000
refclock.c:687:(filter_add_sample)[26-18:00:41] filter sample 7 t=Tue 11/26/13 18:00:41.476959 offset=1.523040222 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:41] filter sample 13 t=Tue 11/26/13 18:00:40.698220 offset=1.441779677 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:42] refclock pulse second=0.476646156 offset=1.523353844 offdiff=-0.081574167 samplediff=1.778426000
refclock.c:687:(filter_add_sample)[26-18:00:42] filter sample 8 t=Tue 11/26/13 18:00:42.476646 offset=1.523353844 dispersion=0.000002001
refclock.c:687:(filter_add_sample)[26-18:00:42] filter sample 14 t=Tue 11/26/13 18:00:41.707340 offset=1.432659559 dispersion=0.000003000
refclock.c:447:(RCL_AddPulse)[26-18:00:43] refclock pulse second=0.476345989 offset=1.523654011 offdiff=-0.090994452 samplediff=1.769005000
refclock.c:687:(filter_add_sample)[26-18:00:43] filter sample 9 t=Tue 11/26/13 18:00:43.476345 offset=1.523654011 dispersion=0.000002001
sources.c:311:(SRC_AccumulateSample)[26-18:00:43] ip=[PPSi] t=Tue 11/26/13 18:00:38.144685 ofs=-1.521981 del=0.000000 disp=0.000005 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:00:43] n=1 off=-1.521981 dist=0.010684 var=16.000000 selok=0
refclock.c:687:(filter_add_sample)[26-18:00:43] filter sample 15 t=Tue 11/26/13 18:00:42.691532 offset=1.448467619 dispersion=0.000003000
sources.c:311:(SRC_AccumulateSample)[26-18:00:43] ip=[GPSi] t=Tue 11/26/13 18:00:35.976851 ofs=-1.363149 del=0.010000 disp=0.033655 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:00:43] n=1 off=-1.521981 dist=0.010772 var=16.000000 selok=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:00:43] n=1 off=-1.363149 dist=0.053758 var=16.000000 selok=0
refclock.c:447:(RCL_AddPulse)[26-18:00:44] refclock pulse second=0.476025704 offset=1.523974296 offdiff=-0.075506677 samplediff=1.784493000
refclock.c:687:(filter_add_sample)[26-18:00:44] filter sample 0 t=Tue 11/26/13 18:00:44.476025 offset=1.523974296 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:44] filter sample 0 t=Tue 11/26/13 18:00:43.676178 offset=1.463821854 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:45] refclock pulse second=0.475706042 offset=1.524293958 offdiff=-0.060472104 samplediff=1.799528000
refclock.c:687:(filter_add_sample)[26-18:00:45] filter sample 1 t=Tue 11/26/13 18:00:45.475706 offset=1.524293958 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:45] filter sample 1 t=Tue 11/26/13 18:00:44.670897 offset=1.469102042 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:46] refclock pulse second=0.475401042 offset=1.524598958 offdiff=-0.055496916 samplediff=1.804504000
refclock.c:687:(filter_add_sample)[26-18:00:46] filter sample 2 t=Tue 11/26/13 18:00:46.475401 offset=1.524598958 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:46] filter sample 2 t=Tue 11/26/13 18:00:45.702589 offset=1.437410756 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:47] refclock pulse second=0.475089295 offset=1.524910705 offdiff=-0.087499949 samplediff=1.772500000
refclock.c:687:(filter_add_sample)[26-18:00:47] filter sample 3 t=Tue 11/26/13 18:00:47.475089 offset=1.524910705 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:47] filter sample 3 t=Tue 11/26/13 18:00:46.699143 offset=1.440856572 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:48] refclock pulse second=0.474770384 offset=1.525229616 offdiff=-0.084373044 samplediff=1.775627000
refclock.c:687:(filter_add_sample)[26-18:00:48] filter sample 4 t=Tue 11/26/13 18:00:48.474770 offset=1.525229616 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:48] filter sample 4 t=Tue 11/26/13 18:00:47.696877 offset=1.443122697 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:49] refclock pulse second=0.474454179 offset=1.525545821 offdiff=-0.082423124 samplediff=1.777577000
refclock.c:687:(filter_add_sample)[26-18:00:49] filter sample 5 t=Tue 11/26/13 18:00:49.474454 offset=1.525545821 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:49] filter sample 5 t=Tue 11/26/13 18:00:48.686686 offset=1.453313300 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:50] refclock pulse second=0.474150014 offset=1.525849986 offdiff=-0.072536686 samplediff=1.787464000
refclock.c:687:(filter_add_sample)[26-18:00:50] filter sample 6 t=Tue 11/26/13 18:00:50.474150 offset=1.525849986 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:50] filter sample 6 t=Tue 11/26/13 18:00:49.706359 offset=1.433640818 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:51] refclock pulse second=0.473835601 offset=1.526164399 offdiff=-0.092523581 samplediff=1.767476000
refclock.c:687:(filter_add_sample)[26-18:00:51] filter sample 7 t=Tue 11/26/13 18:00:51.473835 offset=1.526164399 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:51] filter sample 7 t=Tue 11/26/13 18:00:50.675932 offset=1.464067825 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:52] refclock pulse second=0.473518688 offset=1.526481312 offdiff=-0.062413487 samplediff=1.797586000
refclock.c:687:(filter_add_sample)[26-18:00:52] filter sample 8 t=Tue 11/26/13 18:00:52.473518 offset=1.526481312 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:52] filter sample 8 t=Tue 11/26/13 18:00:51.686151 offset=1.453848285 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:53] refclock pulse second=0.473201360 offset=1.526798640 offdiff=-0.072950355 samplediff=1.787050000
refclock.c:687:(filter_add_sample)[26-18:00:53] filter sample 9 t=Tue 11/26/13 18:00:53.473201 offset=1.526798640 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:53] filter sample 9 t=Tue 11/26/13 18:00:52.675065 offset=1.464934915 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:54] refclock pulse second=0.472896945 offset=1.527103055 offdiff=-0.062168140 samplediff=1.797831000
refclock.c:687:(filter_add_sample)[26-18:00:54] filter sample 10 t=Tue 11/26/13 18:00:54.472896 offset=1.527103055 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:54] filter sample 10 t=Tue 11/26/13 18:00:53.692173 offset=1.447826088 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:55] refclock pulse second=0.472581574 offset=1.527418426 offdiff=-0.079592338 samplediff=1.780408000
refclock.c:687:(filter_add_sample)[26-18:00:55] filter sample 11 t=Tue 11/26/13 18:00:55.472581 offset=1.527418426 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:55] filter sample 11 t=Tue 11/26/13 18:00:54.676818 offset=1.463181991 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:56] refclock pulse second=0.472266534 offset=1.527733466 offdiff=-0.064551475 samplediff=1.795448000
refclock.c:687:(filter_add_sample)[26-18:00:56] filter sample 12 t=Tue 11/26/13 18:00:56.472266 offset=1.527733466 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:56] filter sample 12 t=Tue 11/26/13 18:00:55.698191 offset=1.441808181 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:57] refclock pulse second=0.471949040 offset=1.528050960 offdiff=-0.086242779 samplediff=1.773758000
refclock.c:687:(filter_add_sample)[26-18:00:57] filter sample 13 t=Tue 11/26/13 18:00:57.471949 offset=1.528050960 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:57] filter sample 13 t=Tue 11/26/13 18:00:56.692487 offset=1.447512617 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:58] refclock pulse second=0.471644499 offset=1.528355501 offdiff=-0.080842884 samplediff=1.779157000
refclock.c:687:(filter_add_sample)[26-18:00:58] filter sample 14 t=Tue 11/26/13 18:00:58.471644 offset=1.528355501 dispersion=0.000011569
refclock.c:687:(filter_add_sample)[26-18:00:58] filter sample 14 t=Tue 11/26/13 18:00:57.689998 offset=1.450001674 dispersion=0.106426806
refclock.c:447:(RCL_AddPulse)[26-18:00:59] refclock pulse second=0.471332127 offset=1.528667873 offdiff=-0.078666199 samplediff=1.781334000
refclock.c:687:(filter_add_sample)[26-18:00:59] filter sample 15 t=Tue 11/26/13 18:00:59.471332 offset=1.528667873 dispersion=0.000011569
sources.c:311:(SRC_AccumulateSample)[26-18:00:59] ip=[PPSi] t=Tue 11/26/13 18:00:51.973676 ofs=-1.526324 del=0.000000 disp=0.000002 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:00:59] n=2 off=-1.526324 dist=0.015109 var=16.000000 selok=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:00:59] n=1 off=-1.363149 dist=0.085755 var=16.000000 selok=0
refclock.c:687:(filter_add_sample)[26-18:00:59] filter sample 15 t=Tue 11/26/13 18:00:58.682252 offset=1.457747671 dispersion=0.106426806
sources.c:311:(SRC_AccumulateSample)[26-18:00:59] ip=[GPSi] t=Tue 11/26/13 18:00:52.887781 ofs=-1.452218 del=0.010000 disp=0.023863 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:00:59] n=2 off=-1.526324 dist=0.015308 var=16.000000 selok=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:00:59] n=2 off=-1.452218 dist=0.042340 var=16.000000 selok=0
refclock.c:447:(RCL_AddPulse)[26-18:01:00] refclock pulse second=0.471013466 offset=1.528986534 offdiff=-0.071238863 samplediff=1.788761000
refclock.c:687:(filter_add_sample)[26-18:01:00] filter sample 0 t=Tue 11/26/13 18:01:00.471013 offset=1.528986534 dispersion=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:00] filter sample 0 t=Tue 11/26/13 18:00:59.689075 offset=1.450924081 dispersion=0.075462654
refclock.c:447:(RCL_AddPulse)[26-18:01:01] refclock pulse second=0.470697469 offset=1.529302531 offdiff=-0.078378450 samplediff=1.781622000
refclock.c:687:(filter_add_sample)[26-18:01:01] filter sample 1 t=Tue 11/26/13 18:01:01.470697 offset=1.529302531 dispersion=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:01] filter sample 1 t=Tue 11/26/13 18:01:00.718977 offset=1.421022972 dispersion=0.075462654
refclock.c:447:(RCL_AddPulse)[26-18:01:02] refclock pulse second=0.470391720 offset=1.529608280 offdiff=-0.108585308 samplediff=1.751414000
refclock.c:687:(filter_add_sample)[26-18:01:02] filter sample 2 t=Tue 11/26/13 18:01:02.470391 offset=1.529608280 dispersion=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:02] filter sample 2 t=Tue 11/26/13 18:01:01.685987 offset=1.454012800 dispersion=0.075462654
refclock.c:447:(RCL_AddPulse)[26-18:01:03] refclock pulse second=0.470076933 offset=1.529923067 offdiff=-0.075910267 samplediff=1.784089000
refclock.c:687:(filter_add_sample)[26-18:01:03] filter sample 3 t=Tue 11/26/13 18:01:03.470076 offset=1.529923067 dispersion=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:03] filter sample 3 t=Tue 11/26/13 18:01:03.041005 offset=1.098994669 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:04] refclock pulse ignored offdiff=-0.431236771 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:04] filter sample 4 t=Tue 11/26/13 18:01:04.073070 offset=1.066929786 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:05] refclock pulse ignored offdiff=-0.463619774 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:05] filter sample 5 t=Tue 11/26/13 18:01:05.073633 offset=1.066366419 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:06] refclock pulse ignored offdiff=-0.464496679 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:06] filter sample 6 t=Tue 11/26/13 18:01:06.060552 offset=1.079447787 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:07] refclock pulse ignored offdiff=-0.451729392 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:07] filter sample 7 t=Tue 11/26/13 18:01:07.059795 offset=1.080204902 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:08] refclock pulse ignored offdiff=-0.451282731 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:08] filter sample 8 t=Tue 11/26/13 18:01:08.066456 offset=1.073543679 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:09] refclock pulse ignored offdiff=-0.458258201 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:09] filter sample 9 t=Tue 11/26/13 18:01:09.044616 offset=1.095383071 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:10] refclock pulse ignored offdiff=-0.436733097 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:10] filter sample 10 t=Tue 11/26/13 18:01:10.046646 offset=1.093353514 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:11] refclock pulse ignored offdiff=-0.439071442 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:11] filter sample 11 t=Tue 11/26/13 18:01:11.094380 offset=1.045619121 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:12] refclock pulse ignored offdiff=-0.487122956 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:12] filter sample 12 t=Tue 11/26/13 18:01:11.973645 offset=1.166354587 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:13] refclock pulse ignored offdiff=-0.366702571 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:13] filter sample 13 t=Tue 11/26/13 18:01:13.025826 offset=1.114173805 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:14] refclock pulse ignored offdiff=-0.419196391 refdisp=0.075462654 disp=0.000007329
refclock.c:687:(filter_add_sample)[26-18:01:14] filter sample 14 t=Tue 11/26/13 18:01:13.944857 offset=1.195142836 dispersion=0.075462654
refclock.c:440:(RCL_AddPulse)[26-18:01:15] refclock pulse ignored offdiff=-0.338546315 refdisp=0.075462654 disp=0.000007329
sources.c:311:(SRC_AccumulateSample)[26-18:01:15] ip=[PPSi] t=Tue 11/26/13 18:01:01.970544 ofs=-1.529455 del=0.000000 disp=0.000216 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:15] n=3 off=-1.533731 dist=0.000201 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:15] n=2 off=-1.452218 dist=0.074209 var=16.000000 selok=0
refclock.c:687:(filter_add_sample)[26-18:01:15] filter sample 15 t=Tue 11/26/13 18:01:14.979746 offset=1.160253958 dispersion=0.075462654
sources.c:311:(SRC_AccumulateSample)[26-18:01:15] ip=[GPSi] t=Tue 11/26/13 18:01:09.724314 ofs=-1.115685 del=0.010000 disp=0.020239 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:15] n=3 off=-1.533774 dist=0.000202 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:15] n=3 off=-1.038180 dist=27.829232 var=0.016218 selok=1
sources.c:913:(SRC_SelectSource)[26-18:01:15] Selected source PPSi
sourcestats.c:603:(SST_GetTrackingData)[26-18:01:15] n=3 freq=-0.000314 (-314.036ppm) skew=0.000008 (8.416ppm) avoff=-1.529463 offsd=0.000000 disp=0.000086
sourcestats.c:603:(SST_GetTrackingData)[26-18:01:15] n=3 freq=-0.000314 (-314.036ppm) skew=0.000008 (8.416ppm) avoff=-1.529463 offsd=0.000000 disp=0.000086
sources.c:476:(combine_sources)[26-18:01:15] combining index=0 oweight=4.951358e+03 offset=-1.529463e+00 sd=1.825538e-07 fweight=1.188261e+05 freq=-3.140360e-04 skew=8.415662e-06
sourcestats.c:603:(SST_GetTrackingData)[26-18:01:15] n=3 freq=0.012977 (12976.695ppm) skew=4.655233 (4655232.939ppm) avoff=-1.134262 offsd=0..086914 disp=0.020239
sources.c:499:(combine_sources)[26-18:01:15] combined result offset=-1.529463e+00 sd=1.825538e-07 freq=-3.140360e-04 skew=8.415662e-06
local.c:514:(LCL_AccumulateFrequencyAndOffset)[26-18:01:15] old_freq=297.043ppm new_freq=-17.086ppm offset=-1.533786sec
sourcestats.c:630:(SST_SlewSamples)[26-18:01:15] i=1 old_st=[Tue 11/26/13 18:00:38.144685] new_st=[Tue 11/26/13 18:00:39.666666] old_off=-1.521981 new_off=-0.000000
sourcestats.c:630:(SST_SlewSamples)[26-18:01:15] i=2 old_st=[Tue 11/26/13 18:00:51.973676] new_st=[Tue 11/26/13 18:00:53.500000] old_off=-1.526324 new_off=-0.000000
sourcestats.c:630:(SST_SlewSamples)[26-18:01:15] i=3 old_st=[Tue 11/26/13 18:01:01.970544] new_st=[Tue 11/26/13 18:01:03.500007] old_off=-1.529455 new_off=0.000007
sourcestats.c:648:(SST_SlewSamples)[26-18:01:15] old_off_time=[Tue 11/26/13 18:01:01.970544] new=[Tue 11/26/13 18:01:03.500007] old_off=-1.529463 new_off=-0.000000 old_freq=-314.036ppm new_freq=-0.000ppm
sourcestats.c:630:(SST_SlewSamples)[26-18:01:15] i=1 old_st=[Tue 11/26/13 18:00:35.976851] new_st=[Tue 11/26/13 18:00:37.498151] old_off=-1.363149 new_off=0.158151
sourcestats.c:630:(SST_SlewSamples)[26-18:01:15] i=2 old_st=[Tue 11/26/13 18:00:52.887781] new_st=[Tue 11/26/13 18:00:54.414392] old_off=-1.452218 new_off=0.074392
sourcestats.c:630:(SST_SlewSamples)[26-18:01:15] i=3 old_st=[Tue 11/26/13 18:01:09.724314] new_st=[Tue 11/26/13 18:01:11.256212] old_off=-1.115685 new_off=0.416213
sourcestats.c:648:(SST_SlewSamples)[26-18:01:15] old_off_time=[Tue 11/26/13 18:01:09.724314] new=[Tue 11/26/13 18:01:11.256212] old_off=-1.134262 new_off=0.397636 old_freq=12976.695ppm new_freq=13290.731ppm
refclock.c:424:(RCL_AddPulse)[26-18:01:16] refclock pulse ignored samplediff=3.019738000
refclock.c:687:(filter_add_sample)[26-18:01:16] filter sample 0 t=Tue 11/26/13 18:01:17.476782 offset=-0.336782013 dispersion=0.064001808
refclock_pps.c:151:(pps_poll)[26-18:01:17] PPS sample ignored seq=78766 ts=1385488876.526168736
refclock.c:687:(filter_add_sample)[26-18:01:17] filter sample 1 t=Tue 11/26/13 18:01:18.686869 offset=-0.546869261 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:18] refclock pulse ignored offdiff=0.452839934 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:18] filter sample 2 t=Tue 11/26/13 18:01:19.627886 offset=-0.487886722 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:19] refclock pulse ignored offdiff=-0.488183176 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:19] filter sample 3 t=Tue 11/26/13 18:01:20.647812 offset=-0.507813451 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:20] refclock pulse ignored offdiff=0.491883923 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:20] filter sample 4 t=Tue 11/26/13 18:01:21.648493 offset=-0.508493813 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:21] refclock pulse ignored offdiff=0.491215021 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:21] filter sample 5 t=Tue 11/26/13 18:01:22.595493 offset=-0.455493434 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:22] refclock pulse ignored offdiff=-0.455785184 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:22] filter sample 6 t=Tue 11/26/13 18:01:23.628908 offset=-0.488907881 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:23] refclock pulse ignored offdiff=-0.489195816 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:23] filter sample 7 t=Tue 11/26/13 18:01:24.594330 offset=-0.454330543 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:24] refclock pulse ignored offdiff=-0.454624934 refdisp=0.064001808 disp=0.000060375
refclock_shm.c:104:(shm_poll)[26-18:01:24] SHM sample ignored mode=1 count=222 valid=0
refclock.c:440:(RCL_AddPulse)[26-18:01:25] refclock pulse ignored offdiff=-0.454622216 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:25] filter sample 8 t=Tue 11/26/13 18:01:25.649427 offset=-0.509427624 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:26] refclock pulse ignored offdiff=0.490280480 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:26] filter sample 9 t=Tue 11/26/13 18:01:26.595765 offset=-0.455764545 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:27] refclock pulse ignored offdiff=-0.456054608 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:27] filter sample 10 t=Tue 11/26/13 18:01:27.586884 offset=-0.446883818 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:28] refclock pulse ignored offdiff=-0.447179045 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:28] filter sample 11 t=Tue 11/26/13 18:01:28.587918 offset=-0.447918766 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:29] refclock pulse ignored offdiff=-0.448207476 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:29] filter sample 12 t=Tue 11/26/13 18:01:29.595868 offset=-0.455868225 dispersion=0.064001808
refclock.c:440:(RCL_AddPulse)[26-18:01:30] refclock pulse ignored offdiff=-0.456148674 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:30] filter sample 13 t=Tue 11/26/13 18:01:30.594649 offset=-0.454649162 dispersion=0.064001808
refclock_pps.c:151:(pps_poll)[26-18:01:31] PPS sample ignored seq=78779 ts=1385488890.609305184
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:31] n=3 off=-0.000000 dist=0.001159 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:31] n=3 off=0.691272 dist=96.368934 var=0.016218 selok=1
refclock.c:687:(filter_add_sample)[26-18:01:31] filter sample 14 t=Tue 11/26/13 18:01:31.575614 offset=-0.435614669 dispersion=0.064001808
sources.c:311:(SRC_AccumulateSample)[26-18:01:31] ip=[GPSi] t=Tue 11/26/13 18:01:25.163181 ofs=0.467626 del=0.010000 disp=0.018928 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:31] n=3 off=-0.000000 dist=0.001161 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:31] n=4 off=0.533177 dist=0.759693 var=0.007719 selok=1
refclock.c:440:(RCL_AddPulse)[26-18:01:32] refclock pulse ignored offdiff=-0.435898780 refdisp=0.064001808 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:32] filter sample 0 t=Tue 11/26/13 18:01:32.586010 offset=-0.446009869 dispersion=0.056785593
refclock.c:440:(RCL_AddPulse)[26-18:01:33] refclock pulse ignored offdiff=-0.446301566 refdisp=0.056785593 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:33] filter sample 1 t=Tue 11/26/13 18:01:33.655098 offset=-0.515098164 dispersion=0.056785593
refclock.c:440:(RCL_AddPulse)[26-18:01:34] refclock pulse ignored offdiff=0.484617892 refdisp=0.056785593 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:34] filter sample 2 t=Tue 11/26/13 18:01:34.583370 offset=-0.443371210 dispersion=0.056785593
refclock.c:440:(RCL_AddPulse)[26-18:01:35] refclock pulse ignored offdiff=-0.443653862 refdisp=0.056785593 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:01:35] filter sample 3 t=Tue 11/26/13 18:01:35.631835 offset=-0.491835573 dispersion=0.057668908
refclock.c:440:(RCL_AddPulse)[26-18:01:36] refclock pulse ignored offdiff=-0.490999094 refdisp=0.057668908 disp=0.000110690
refclock.c:687:(filter_add_sample)[26-18:01:36] filter sample 4 t=Tue 11/26/13 18:01:36.596844 offset=-0.456844563 dispersion=0.056835908
refclock.c:440:(RCL_AddPulse)[26-18:01:37] refclock pulse ignored offdiff=-0.456380352 refdisp=0.056835908 disp=0.000098111
refclock.c:687:(filter_add_sample)[26-18:01:37] filter sample 5 t=Tue 11/26/13 18:01:37.586605 offset=-0.446605354 dispersion=0.056823329
refclock.c:440:(RCL_AddPulse)[26-18:01:38] refclock pulse ignored offdiff=-0.446140985 refdisp=0.056823329 disp=0.000088677
refclock.c:687:(filter_add_sample)[26-18:01:38] filter sample 6 t=Tue 11/26/13 18:01:38.610670 offset=-0.470670734 dispersion=0.056813895
refclock.c:440:(RCL_AddPulse)[26-18:01:39] refclock pulse ignored offdiff=-0.470216094 refdisp=0.056813895 disp=0.000081601
refclock.c:687:(filter_add_sample)[26-18:01:39] filter sample 7 t=Tue 11/26/13 18:01:39.595541 offset=-0.455541972 dispersion=0.056806819
refclock.c:440:(RCL_AddPulse)[26-18:01:40] refclock pulse ignored offdiff=-0.455090998 refdisp=0.056806819 disp=0.000076295
refclock.c:687:(filter_add_sample)[26-18:01:40] filter sample 8 t=Tue 11/26/13 18:01:40.614260 offset=-0.474260555 dispersion=0.056801513
refclock.c:440:(RCL_AddPulse)[26-18:01:41] refclock pulse ignored offdiff=-0.473818517 refdisp=0.056801513 disp=0.000072315
refclock.c:687:(filter_add_sample)[26-18:01:41] filter sample 9 t=Tue 11/26/13 18:01:41.613012 offset=-0.473013067 dispersion=0.056797533
refclock.c:440:(RCL_AddPulse)[26-18:01:42] refclock pulse ignored offdiff=-0.472564044 refdisp=0.056797533 disp=0.000069330
refclock.c:687:(filter_add_sample)[26-18:01:42] filter sample 10 t=Tue 11/26/13 18:01:42.652850 offset=-0.512850254 dispersion=0.056794548
refclock.c:440:(RCL_AddPulse)[26-18:01:43] refclock pulse ignored offdiff=0.487601719 refdisp=0.056794548 disp=0.000067091
refclock.c:687:(filter_add_sample)[26-18:01:43] filter sample 11 t=Tue 11/26/13 18:01:43.636578 offset=-0.496578710 dispersion=0.056792309
refclock.c:440:(RCL_AddPulse)[26-18:01:44] refclock pulse ignored offdiff=-0.496129432 refdisp=0.056792309 disp=0.000065412
refclock.c:687:(filter_add_sample)[26-18:01:44] filter sample 12 t=Tue 11/26/13 18:01:44.605539 offset=-0.465539046 dispersion=0.056790630
refclock.c:440:(RCL_AddPulse)[26-18:01:45] refclock pulse ignored offdiff=-0.465094038 refdisp=0.056790630 disp=0.000064152
refclock.c:687:(filter_add_sample)[26-18:01:45] filter sample 13 t=Tue 11/26/13 18:01:45.613376 offset=-0.473375729 dispersion=0.056789370
refclock.c:440:(RCL_AddPulse)[26-18:01:46] refclock pulse ignored offdiff=-0.472927548 refdisp=0.056789370 disp=0.000063208
refclock.c:687:(filter_add_sample)[26-18:01:46] filter sample 14 t=Tue 11/26/13 18:01:46.653729 offset=-0.513730309 dispersion=0.056788426
refclock.c:440:(RCL_AddPulse)[26-18:01:47] refclock pulse ignored offdiff=0.486717076 refdisp=0.056788426 disp=0.000062500
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:47] n=3 off=-0.000000 dist=0.002124 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:47] n=4 off=0.678909 dist=2.396252 var=0.007719 selok=1
refclock.c:687:(filter_add_sample)[26-18:01:47] filter sample 15 t=Tue 11/26/13 18:01:47.638281 offset=-0.498281495 dispersion=0.056787718
sources.c:311:(SRC_AccumulateSample)[26-18:01:47] ip=[GPSi] t=Tue 11/26/13 18:01:41.415594 ofs=0.475594 del=0.010000 disp=0.016156 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:47] n=3 off=-0.000000 dist=0.002126 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:01:47] n=5 off=0.513429 dist=0.202569 var=0.007896 selok=1
sources.c:711:(SRC_SelectSource)[26-18:01:47] Can't synchronise: no majority
refclock.c:440:(RCL_AddPulse)[26-18:01:48] refclock pulse ignored offdiff=-0.497837063 refdisp=0.056787718 disp=0.000061968
refclock.c:687:(filter_add_sample)[26-18:01:48] filter sample 0 t=Tue 11/26/13 18:01:48.598387 offset=-0.458388016 dispersion=0.051092348
refclock.c:440:(RCL_AddPulse)[26-18:01:49] refclock pulse ignored offdiff=-0.457939817 refdisp=0.051092348 disp=0.000061570
refclock.c:687:(filter_add_sample)[26-18:01:49] filter sample 1 t=Tue 11/26/13 18:01:49.592368 offset=-0.452369010 dispersion=0.051091950
refclock.c:440:(RCL_AddPulse)[26-18:01:50] refclock pulse ignored offdiff=-0.451923403 refdisp=0.051091950 disp=0.000061271
refclock.c:687:(filter_add_sample)[26-18:01:50] filter sample 2 t=Tue 11/26/13 18:01:50.614369 offset=-0.474369702 dispersion=0.051091651
refclock.c:440:(RCL_AddPulse)[26-18:01:51] refclock pulse ignored offdiff=-0.473919777 refdisp=0.051091651 disp=0.000061047
refclock.c:687:(filter_add_sample)[26-18:01:51] filter sample 3 t=Tue 11/26/13 18:01:51.602161 offset=-0.462161584 dispersion=0.051091427
refclock.c:440:(RCL_AddPulse)[26-18:01:52] refclock pulse ignored offdiff=-0.461717908 refdisp=0.051091427 disp=0.000060879
refclock.c:687:(filter_add_sample)[26-18:01:52] filter sample 4 t=Tue 11/26/13 18:01:52.612480 offset=-0.472481357 dispersion=0.051091259
refclock.c:440:(RCL_AddPulse)[26-18:01:53] refclock pulse ignored offdiff=-0.472031347 refdisp=0.051091259 disp=0.000060753
refclock.c:687:(filter_add_sample)[26-18:01:53] filter sample 5 t=Tue 11/26/13 18:01:53.659939 offset=-0.519939144 dispersion=0.051091133
refclock.c:440:(RCL_AddPulse)[26-18:01:54] refclock pulse ignored offdiff=0.480519024 refdisp=0.051091133 disp=0.000060658
refclock.c:687:(filter_add_sample)[26-18:01:54] filter sample 6 t=Tue 11/26/13 18:01:54.633567 offset=-0.493567379 dispersion=0.051091038
refclock.c:440:(RCL_AddPulse)[26-18:01:55] refclock pulse ignored offdiff=-0.493114865 refdisp=0.051091038 disp=0.000060587
refclock.c:687:(filter_add_sample)[26-18:01:55] filter sample 7 t=Tue 11/26/13 18:01:55.584262 offset=-0.444263273 dispersion=0.051090967
refclock.c:440:(RCL_AddPulse)[26-18:01:56] refclock pulse ignored offdiff=-0.443816310 refdisp=0.051090967 disp=0.000060534
refclock.c:687:(filter_add_sample)[26-18:01:56] filter sample 8 t=Tue 11/26/13 18:01:56.639630 offset=-0.499630231 dispersion=0.051090914
refclock.c:440:(RCL_AddPulse)[26-18:01:57] refclock pulse ignored offdiff=-0.499174307 refdisp=0.051090914 disp=0.000060494
refclock.c:687:(filter_add_sample)[26-18:01:57] filter sample 9 t=Tue 11/26/13 18:01:57.592163 offset=-0.452162706 dispersion=0.051090874
refclock.c:440:(RCL_AddPulse)[26-18:01:58] refclock pulse ignored offdiff=-0.451708181 refdisp=0.051090874 disp=0.000060464
refclock.c:687:(filter_add_sample)[26-18:01:58] filter sample 10 t=Tue 11/26/13 18:01:58.606012 offset=-0.466011973 dispersion=0.051090844
refclock.c:440:(RCL_AddPulse)[26-18:01:59] refclock pulse ignored offdiff=-0.465556553 refdisp=0.051090844 disp=0.000060442
refclock.c:687:(filter_add_sample)[26-18:01:59] filter sample 11 t=Tue 11/26/13 18:01:59.603146 offset=-0.463146043 dispersion=0.051090822
refclock.c:440:(RCL_AddPulse)[26-18:02:00] refclock pulse ignored offdiff=-0.462693138 refdisp=0.051090822 disp=0.000060425
refclock.c:687:(filter_add_sample)[26-18:02:00] filter sample 12 t=Tue 11/26/13 18:02:00.694289 offset=-0.554289133 dispersion=0.051090805
refclock.c:440:(RCL_AddPulse)[26-18:02:01] refclock pulse ignored offdiff=0.446170512 refdisp=0.051090805 disp=0.000060412
refclock.c:687:(filter_add_sample)[26-18:02:01] filter sample 13 t=Tue 11/26/13 18:02:01.618876 offset=-0.478876095 dispersion=0.051090792
refclock.c:440:(RCL_AddPulse)[26-18:02:02] refclock pulse ignored offdiff=-0.478415582 refdisp=0.051090792 disp=0.000060403
refclock.c:687:(filter_add_sample)[26-18:02:02] filter sample 14 t=Tue 11/26/13 18:02:02.606608 offset=-0.466608885 dispersion=0.051090783
refclock.c:440:(RCL_AddPulse)[26-18:02:03] refclock pulse ignored offdiff=-0.466148335 refdisp=0.051090783 disp=0.000060396
refclock.c:687:(filter_add_sample)[26-18:02:03] filter sample 15 t=Tue 11/26/13 18:02:03.648307 offset=-0.508307140 dispersion=0.051090776
sources.c:311:(SRC_AccumulateSample)[26-18:02:03] ip=[GPSi] t=Tue 11/26/13 18:01:55.713524 ofs=0.473524 del=0.010000 disp=0.014836 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:02:03] n=3 off=-0.000000 dist=0.002261 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:02:03] n=6 off=0.506462 dist=0.134783 var=0.006993 selok=1
refclock.c:440:(RCL_AddPulse)[26-18:02:04] refclock pulse ignored offdiff=0.492167116 refdisp=0.051090776 disp=0.000060390
refclock.c:687:(filter_add_sample)[26-18:02:04] filter sample 0 t=Tue 11/26/13 18:02:04.692925 offset=-0.552925109 dispersion=0.046916880
refclock.c:440:(RCL_AddPulse)[26-18:02:05] refclock pulse ignored offdiff=0.447539478 refdisp=0.046916880 disp=0.000060386
refclock.c:687:(filter_add_sample)[26-18:02:05] filter sample 1 t=Tue 11/26/13 18:02:05.639023 offset=-0.499023774 dispersion=0.046916876
refclock.c:440:(RCL_AddPulse)[26-18:02:06] refclock pulse ignored offdiff=-0.498558020 refdisp=0.046916876 disp=0.000060383
refclock.c:687:(filter_add_sample)[26-18:02:06] filter sample 2 t=Tue 11/26/13 18:02:06.598682 offset=-0.458682877 dispersion=0.046916873
refclock.c:440:(RCL_AddPulse)[26-18:02:07] refclock pulse ignored offdiff=-0.458218124 refdisp=0.046916873 disp=0.000060381
refclock.c:687:(filter_add_sample)[26-18:02:07] filter sample 3 t=Tue 11/26/13 18:02:07.597735 offset=-0.457735572 dispersion=0.046916871
refclock.c:440:(RCL_AddPulse)[26-18:02:08] refclock pulse ignored offdiff=-0.457259526 refdisp=0.046916871 disp=0.000060380
refclock.c:687:(filter_add_sample)[26-18:02:08] filter sample 4 t=Tue 11/26/13 18:02:08.649847 offset=-0.509847339 dispersion=0.046916870
refclock.c:440:(RCL_AddPulse)[26-18:02:09] refclock pulse ignored offdiff=0.490624959 refdisp=0.046916870 disp=0.000060378
refclock.c:687:(filter_add_sample)[26-18:02:09] filter sample 5 t=Tue 11/26/13 18:02:09.643556 offset=-0.503556483 dispersion=0.046916868
refclock.c:440:(RCL_AddPulse)[26-18:02:10] refclock pulse ignored offdiff=0.496915109 refdisp=0.046916868 disp=0.000060377
refclock.c:687:(filter_add_sample)[26-18:02:10] filter sample 6 t=Tue 11/26/13 18:02:10.597694 offset=-0.457694369 dispersion=0.046916867
refclock.c:440:(RCL_AddPulse)[26-18:02:11] refclock pulse ignored offdiff=-0.457231152 refdisp=0.046916867 disp=0.000060377
refclock.c:687:(filter_add_sample)[26-18:02:11] filter sample 7 t=Tue 11/26/13 18:02:11.597714 offset=-0.457714830 dispersion=0.046916867
refclock.c:440:(RCL_AddPulse)[26-18:02:12] refclock pulse ignored offdiff=-0.457239944 refdisp=0.046916867 disp=0.000060376
refclock.c:687:(filter_add_sample)[26-18:02:12] filter sample 8 t=Tue 11/26/13 18:02:12.606425 offset=-0.466425355 dispersion=0.046916866
refclock.c:440:(RCL_AddPulse)[26-18:02:13] refclock pulse ignored offdiff=-0.465953800 refdisp=0.046916866 disp=0.000060376
refclock.c:687:(filter_add_sample)[26-18:02:13] filter sample 9 t=Tue 11/26/13 18:02:13.621761 offset=-0.481761827 dispersion=0.046916866
refclock.c:440:(RCL_AddPulse)[26-18:02:14] refclock pulse ignored offdiff=-0.481285727 refdisp=0.046916866 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:02:14] filter sample 10 t=Tue 11/26/13 18:02:14.679453 offset=-0.539453525 dispersion=0.046916865
refclock.c:440:(RCL_AddPulse)[26-18:02:15] refclock pulse ignored offdiff=0.461013409 refdisp=0.046916865 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:02:15] filter sample 11 t=Tue 11/26/13 18:02:15.646272 offset=-0.506272084 dispersion=0.046916865
refclock.c:440:(RCL_AddPulse)[26-18:02:16] refclock pulse ignored offdiff=0.494207854 refdisp=0.046916865 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:02:16] filter sample 12 t=Tue 11/26/13 18:02:16.679748 offset=-0.539748160 dispersion=0.046916865
refclock.c:440:(RCL_AddPulse)[26-18:02:17] refclock pulse ignored offdiff=0.460726238 refdisp=0.046916865 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:02:17] filter sample 13 t=Tue 11/26/13 18:02:17.675011 offset=-0.535011872 dispersion=0.046916865
refclock.c:440:(RCL_AddPulse)[26-18:02:18] refclock pulse ignored offdiff=0.465465320 refdisp=0.046916865 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:02:18] filter sample 14 t=Tue 11/26/13 18:02:18.724055 offset=-0.584055963 dispersion=0.046916865
refclock.c:440:(RCL_AddPulse)[26-18:02:19] refclock pulse ignored offdiff=0.416414774 refdisp=0.046916865 disp=0.000060375
refclock.c:687:(filter_add_sample)[26-18:02:19] filter sample 15 t=Tue 11/26/13 18:02:19.730294 offset=-0.590294196 dispersion=0.046916865
sources.c:311:(SRC_AccumulateSample)[26-18:02:19] ip=[GPSi] t=Tue 11/26/13 18:02:12.143978 ofs=0.503978 del=0.010000 disp=0.014041 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-18:02:19] n=3 off=-0.000000 dist=0.002396 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-18:02:19] n=7 off=0.528172 dist=0.080655 var=0.005400 selok=1

[~90 minutes from last non-ignored pulse]


refclock.c:440:(RCL_AddPulse)[26-19:36:03] refclock pulse ignored offdiff=-0.441519946 refdisp=0.017114946 disp=0.000695392
refclock.c:687:(filter_add_sample)[26-19:36:04] filter sample 8 t=Tue 11/26/13 19:36:03.760700 offset=0.379299702 dispersion=0.017084556
refclock.c:447:(RCL_AddPulse)[26-19:36:04] refclock pulse second=0.533759865 offset=0.464751002 offdiff=-0.085451300 samplediff=-0.225452000
refclock.c:687:(filter_add_sample)[26-19:36:04] filter sample 0 t=Tue 11/26/13 19:36:03.535248 offset=0.464751002 dispersion=0.000665002
refclock.c:687:(filter_add_sample)[26-19:36:05] filter sample 9 t=Tue 11/26/13 19:36:04.754200 offset=0.385799027 dispersion=0.017057964
refclock.c:447:(RCL_AddPulse)[26-19:36:05] refclock pulse second=0.533695784 offset=0.465001225 offdiff=-0.079202198 samplediff=-0.219202000
refclock.c:687:(filter_add_sample)[26-19:36:05] filter sample 1 t=Tue 11/26/13 19:36:04.534998 offset=0.465001225 dispersion=0.000638410
refclock.c:687:(filter_add_sample)[26-19:36:06] filter sample 10 t=Tue 11/26/13 19:36:05.733010 offset=0.406989028 dispersion=0.017034696
refclock.c:447:(RCL_AddPulse)[26-19:36:06] refclock pulse second=0.533602009 offset=0.465257874 offdiff=-0.058268846 samplediff=-0.198268000
refclock.c:687:(filter_add_sample)[26-19:36:06] filter sample 2 t=Tue 11/26/13 19:36:05.534742 offset=0.465257874 dispersion=0.000615142
refclock.c:687:(filter_add_sample)[26-19:36:07] filter sample 11 t=Tue 11/26/13 19:36:06.734737 offset=0.405263091 dispersion=0.017014337
refclock.c:447:(RCL_AddPulse)[26-19:36:07] refclock pulse second=0.533490749 offset=0.465511648 offdiff=-0.060248557 samplediff=-0.200249000
refclock.c:687:(filter_add_sample)[26-19:36:07] filter sample 3 t=Tue 11/26/13 19:36:06.534488 offset=0.465511648 dispersion=0.000594783
refclock.c:687:(filter_add_sample)[26-19:36:08] filter sample 12 t=Tue 11/26/13 19:36:07.752094 offset=0.387905319 dispersion=0.016996523
refclock.c:447:(RCL_AddPulse)[26-19:36:08] refclock pulse second=0.533353719 offset=0.465773379 offdiff=-0.077868060 samplediff=-0.217868000
refclock.c:687:(filter_add_sample)[26-19:36:08] filter sample 4 t=Tue 11/26/13 19:36:07.534226 offset=0.465773379 dispersion=0.000576969
refclock.c:687:(filter_add_sample)[26-19:36:09] filter sample 13 t=Tue 11/26/13 19:36:08.742291 offset=0.397708464 dispersion=0.016980935
refclock.c:447:(RCL_AddPulse)[26-19:36:09] refclock pulse second=0.533189660 offset=0.466046551 offdiff=-0.068338087 samplediff=-0.208338000
refclock.c:687:(filter_add_sample)[26-19:36:09] filter sample 5 t=Tue 11/26/13 19:36:08.533953 offset=0.466046551 dispersion=0.000561381
refclock.c:687:(filter_add_sample)[26-19:36:10] filter sample 14 t=Tue 11/26/13 19:36:09.741925 offset=0.398074229 dispersion=0.016967296
refclock.c:447:(RCL_AddPulse)[26-19:36:10] refclock pulse second=0.533015809 offset=0.466315875 offdiff=-0.068241646 samplediff=-0.208242000
refclock.c:687:(filter_add_sample)[26-19:36:10] filter sample 6 t=Tue 11/26/13 19:36:09.533683 offset=0.466315875 dispersion=0.000547742
sources.c:311:(SRC_AccumulateSample)[26-19:36:10] ip=[PPSi] t=Tue 11/26/13 19:36:06.534481 ofs=-0.465518 del=0.000000 disp=0.000193 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:10] n=6 off=-0.466675 dist=0.000194 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:10] n=12 off=-0.019124 dist=0.020058 var=0.000232 selok=1
sources.c:711:(SRC_SelectSource)[26-19:36:10] Can't synchronise: no majority
refclock.c:687:(filter_add_sample)[26-19:36:11] filter sample 15 t=Tue 11/26/13 19:36:10.748873 offset=0.391126799 dispersion=0.016955362
sources.c:311:(SRC_AccumulateSample)[26-19:36:11] ip=[GPSi] t=Tue 11/26/13 19:36:03.837247 ofs=-0.202753 del=0.010000 disp=0.036448 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:11] n=6 off=-0.466962 dist=0.000195 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:11] n=13 off=-0.018439 dist=0.019587 var=0.000256 selok=1
refclock.c:447:(RCL_AddPulse)[26-19:36:11] refclock pulse second=0.532834482 offset=0.466580742 offdiff=-0.075453943 samplediff=-0.215454000
refclock.c:687:(filter_add_sample)[26-19:36:11] filter sample 0 t=Tue 11/26/13 19:36:10.533419 offset=0.466580742 dispersion=0.000514765
refclock.c:687:(filter_add_sample)[26-19:36:12] filter sample 0 t=Tue 11/26/13 19:36:11.748480 offset=0.391519386 dispersion=0.045654773
refclock.c:447:(RCL_AddPulse)[26-19:36:12] refclock pulse second=0.532639707 offset=0.466848614 offdiff=-0.075329228 samplediff=-0.215329000
refclock.c:687:(filter_add_sample)[26-19:36:12] filter sample 1 t=Tue 11/26/13 19:36:11.533151 offset=0.466848614 dispersion=0.000504323
refclock.c:687:(filter_add_sample)[26-19:36:13] filter sample 1 t=Tue 11/26/13 19:36:12.739832 offset=0.400167615 dispersion=0.045645635
refclock.c:447:(RCL_AddPulse)[26-19:36:13] refclock pulse second=0.532415225 offset=0.467137056 offdiff=-0.066969441 samplediff=-0.206969000
refclock.c:687:(filter_add_sample)[26-19:36:13] filter sample 2 t=Tue 11/26/13 19:36:12.532863 offset=0.467137056 dispersion=0.000495185
refclock.c:687:(filter_add_sample)[26-19:36:14] filter sample 2 t=Tue 11/26/13 19:36:13.739948 offset=0.400051852 dispersion=0.045637640
refclock.c:447:(RCL_AddPulse)[26-19:36:14] refclock pulse second=0.532198718 offset=0.467409528 offdiff=-0.067357676 samplediff=-0.207358000
refclock.c:687:(filter_add_sample)[26-19:36:14] filter sample 3 t=Tue 11/26/13 19:36:13.532590 offset=0.467409528 dispersion=0.000487190
refclock.c:687:(filter_add_sample)[26-19:36:15] filter sample 3 t=Tue 11/26/13 19:36:14.735553 offset=0.404446505 dispersion=0.045630645
refclock.c:447:(RCL_AddPulse)[26-19:36:15] refclock pulse second=0.531967720 offset=0.467689495 offdiff=-0.063242990 samplediff=-0.203243000
refclock.c:687:(filter_add_sample)[26-19:36:15] filter sample 4 t=Tue 11/26/13 19:36:14.532310 offset=0.467689495 dispersion=0.000480195
refclock.c:687:(filter_add_sample)[26-19:36:16] filter sample 4 t=Tue 11/26/13 19:36:15.749324 offset=0.390675466 dispersion=0.045624524
refclock.c:447:(RCL_AddPulse)[26-19:36:16] refclock pulse second=0.531731880 offset=0.467968183 offdiff=-0.077292717 samplediff=-0.217293000
refclock.c:687:(filter_add_sample)[26-19:36:16] filter sample 5 t=Tue 11/26/13 19:36:15.532031 offset=0.467968183 dispersion=0.000474074
refclock.c:687:(filter_add_sample)[26-19:36:17] filter sample 5 t=Tue 11/26/13 19:36:16.738899 offset=0.401100310 dispersion=0.045619168
refclock.c:447:(RCL_AddPulse)[26-19:36:17] refclock pulse second=0.531480404 offset=0.468257151 offdiff=-0.067156841 samplediff=-0.207157000
refclock.c:687:(filter_add_sample)[26-19:36:17] filter sample 6 t=Tue 11/26/13 19:36:16.531742 offset=0.468257151 dispersion=0.000468718
refclock.c:687:(filter_add_sample)[26-19:36:18] filter sample 6 t=Tue 11/26/13 19:36:17.739552 offset=0.400448217 dispersion=0.045614481
refclock.c:447:(RCL_AddPulse)[26-19:36:18] refclock pulse second=0.531237548 offset=0.468532813 offdiff=-0.068084596 samplediff=-0.208085000
refclock.c:687:(filter_add_sample)[26-19:36:18] filter sample 7 t=Tue 11/26/13 19:36:17.531467 offset=0.468532813 dispersion=0.000464031
refclock.c:687:(filter_add_sample)[26-19:36:19] filter sample 7 t=Tue 11/26/13 19:36:18.748443 offset=0.391556275 dispersion=0.045610380
refclock.c:447:(RCL_AddPulse)[26-19:36:19] refclock pulse second=0.530980163 offset=0.468818903 offdiff=-0.077262628 samplediff=-0.217262000
refclock.c:687:(filter_add_sample)[26-19:36:19] filter sample 8 t=Tue 11/26/13 19:36:18.531181 offset=0.468818903 dispersion=0.000459930
refclock.c:687:(filter_add_sample)[26-19:36:20] filter sample 8 t=Tue 11/26/13 19:36:19.751144 offset=0.388856151 dispersion=0.045606792
refclock.c:447:(RCL_AddPulse)[26-19:36:20] refclock pulse second=0.530723233 offset=0.469100950 offdiff=-0.080244799 samplediff=-0.220245000
refclock.c:687:(filter_add_sample)[26-19:36:20] filter sample 9 t=Tue 11/26/13 19:36:19.530899 offset=0.469100950 dispersion=0.000456342
refclock.c:687:(filter_add_sample)[26-19:36:21] filter sample 9 t=Tue 11/26/13 19:36:20.732765 offset=0.407235068 dispersion=0.045603653
refclock.c:447:(RCL_AddPulse)[26-19:36:21] refclock pulse second=0.530451398 offset=0.469394762 offdiff=-0.062159694 samplediff=-0.202160000
refclock.c:687:(filter_add_sample)[26-19:36:21] filter sample 10 t=Tue 11/26/13 19:36:20.530605 offset=0.469394762 dispersion=0.000453203
refclock.c:687:(filter_add_sample)[26-19:36:22] filter sample 10 t=Tue 11/26/13 19:36:21.730462 offset=0.409537777 dispersion=0.045600906
refclock.c:447:(RCL_AddPulse)[26-19:36:22] refclock pulse second=0.530192545 offset=0.469672845 offdiff=-0.060135068 samplediff=-0.200135000
refclock.c:687:(filter_add_sample)[26-19:36:22] filter sample 11 t=Tue 11/26/13 19:36:21.530327 offset=0.469672845 dispersion=0.000450456
refclock.c:687:(filter_add_sample)[26-19:36:23] filter sample 11 t=Tue 11/26/13 19:36:22.756670 offset=0.383329622 dispersion=0.045598502
refclock.c:447:(RCL_AddPulse)[26-19:36:23] refclock pulse second=0.529923376 offset=0.469958840 offdiff=-0.086629218 samplediff=-0.226629000
refclock.c:687:(filter_add_sample)[26-19:36:23] filter sample 12 t=Tue 11/26/13 19:36:22.530041 offset=0.469958840 dispersion=0.000448052
refclock.c:687:(filter_add_sample)[26-19:36:24] filter sample 12 t=Tue 11/26/13 19:36:23.738134 offset=0.401865495 dispersion=0.045596399
refclock.c:447:(RCL_AddPulse)[26-19:36:24] refclock pulse second=0.529649643 offset=0.470247296 offdiff=-0.068381801 samplediff=-0.208382000
refclock.c:687:(filter_add_sample)[26-19:36:24] filter sample 13 t=Tue 11/26/13 19:36:23.529752 offset=0.470247296 dispersion=0.000445949
refclock.c:687:(filter_add_sample)[26-19:36:25] filter sample 13 t=Tue 11/26/13 19:36:24.754327 offset=0.385672318 dispersion=0.045594558
refclock.c:447:(RCL_AddPulse)[26-19:36:25] refclock pulse second=0.529368062 offset=0.470541760 offdiff=-0.084869442 samplediff=-0.224869000
refclock.c:687:(filter_add_sample)[26-19:36:25] filter sample 14 t=Tue 11/26/13 19:36:24.529458 offset=0.470541760 dispersion=0.000444108
refclock.c:687:(filter_add_sample)[26-19:36:26] filter sample 14 t=Tue 11/26/13 19:36:25.748300 offset=0.391699766 dispersion=0.045592948
refclock.c:447:(RCL_AddPulse)[26-19:36:26] refclock pulse second=0.529106013 offset=0.470815081 offdiff=-0.079115315 samplediff=-0.219115000
refclock.c:687:(filter_add_sample)[26-19:36:26] filter sample 15 t=Tue 11/26/13 19:36:25.529185 offset=0.470815081 dispersion=0.000442498
sources.c:311:(SRC_AccumulateSample)[26-19:36:26] ip=[PPSi] t=Tue 11/26/13 19:36:18.031319 ofs=-0.468680 del=0.000000 disp=0.000122 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:26] n=7 off=-0.471247 dist=0.000124 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:26] n=13 off=-0.018160 dist=0.025000 var=0.000256 selok=1
refclock.c:687:(filter_add_sample)[26-19:36:27] filter sample 15 t=Tue 11/26/13 19:36:26.739212 offset=0.400787012 dispersion=0.045591539
sources.c:311:(SRC_AccumulateSample)[26-19:36:27] ip=[GPSi] t=Tue 11/26/13 19:36:18.343012 ofs=-0.396987 del=0.010000 disp=0.013397 str=0
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:27] n=7 off=-0.471499 dist=0.000125 var=0.000000 selok=1
sourcestats.c:573:(SST_GetSelectionData)[26-19:36:27] n=4 off=-0.453430 dist=0.796693 var=0.003604 selok=1
sources.c:913:(SRC_SelectSource)[26-19:36:27] Selected source PPSi
sourcestats.c:603:(SST_GetTrackingData)[26-19:36:27] n=7 freq=-0.000303 (-303.023ppm) skew=0.000000 (0.233ppm) avoff=-0.468772 offsd=0.000100 disp=0.000122
sourcestats.c:603:(SST_GetTrackingData)[26-19:36:27] n=7 freq=-0.000303 (-303.023ppm) skew=0.000000 (0.233ppm) avoff=-0.468772 offsd=0.000100 disp=0.000122
sources.c:476:(combine_sources)[26-19:36:27] combining index=0 oweight=8.029061e+03 offset=-4.687721e-01 sd=1.003933e-04 fweight=4.300648e+06 freq=-3.030234e-04 skew=2.325231e-07
sourcestats.c:603:(SST_GetTrackingData)[26-19:36:27] n=4 freq=-0.006278 (-6278.034ppm) skew=0.086569 (86568.601ppm) avoff=-0.261378 offsd=0.109205 disp=0.013397
sources.c:499:(combine_sources)[26-19:36:27] combined result offset=-4.687721e-01 sd=1.003933e-04 freq=-3.030234e-04 skew=2.325231e-07
local.c:514:(LCL_AccumulateFrequencyAndOffset)[26-19:36:27] old_freq=272.617ppm new_freq=-30.489ppm offset=-0.471602sec
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=1 old_st=[Tue 11/26/13 18:00:40.963380] new_st=[Tue 11/26/13 18:00:39.693686] old_off=1.296718 new_off=0.027024
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=2 old_st=[Tue 11/26/13 18:00:54.792583] new_st=[Tue 11/26/13 18:00:53.527080] old_off=1.292588 new_off=0.027085
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=3 old_st=[Tue 11/26/13 18:01:04.789606] new_st=[Tue 11/26/13 18:01:03.527132] old_off=1.289611 new_off=0.027137
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=4 old_st=[Tue 11/26/13 18:04:27.226903] new_st=[Tue 11/26/13 18:04:26.025772] old_off=1.226907 new_off=0.025776
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=5 old_st=[Tue 11/26/13 18:04:40.189095] new_st=[Tue 11/26/13 18:04:38.991892] old_off=1.189095 new_off=-0.008108
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=6 old_st=[Tue 11/26/13 18:04:50.693478] new_st=[Tue 11/26/13 18:04:49.499458] old_off=1.193488 new_off=-0.000532
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=7 old_st=[Tue 11/26/13 18:06:02.672371] new_st=[Tue 11/26/13 18:06:01.500163] old_off=1.172381 new_off=0.000173
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=8 old_st=[Tue 11/26/13 18:06:17.667591] new_st=[Tue 11/26/13 18:06:16.499927] old_off=1.167591 new_off=-0.000073
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=9 old_st=[Tue 11/26/13 18:06:24.665553] new_st=[Tue 11/26/13 18:06:23.500009] old_off=1.165549 new_off=0.000006
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=10 old_st=[Tue 11/26/13 19:36:06.534481] new_st=[Tue 11/26/13 19:36:06.999769] old_off=-0.465518 new_off=-0.000230
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=11 old_st=[Tue 11/26/13 19:36:18.031319] new_st=[Tue 11/26/13 19:36:18.500091] old_off=-0.468680 new_off=0.000092
sourcestats.c:648:(SST_SlewSamples)[26-19:36:27] old_off_time=[Tue 11/26/13 19:36:18.031319] new=[Tue 11/26/13 19:36:18.500091] old_off=-0.468772 new_off=-0.000000 old_freq=-303.023ppm new_freq=-0.000ppm
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=94 old_st=[Tue 11/26/13 19:34:27.723774] new_st=[Tue 11/26/13 19:34:28.159120] old_off=-0.016226 new_off=0.419121
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=95 old_st=[Tue 11/26/13 19:34:43.747836] new_st=[Tue 11/26/13 19:34:44.188038] old_off=0.007837 new_off=0.448039
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=96 old_st=[Tue 11/26/13 19:34:59.441236] new_st=[Tue 11/26/13 19:34:59.886193] old_off=0.001236 new_off=0.446193
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=97 old_st=[Tue 11/26/13 19:35:16.536938] new_st=[Tue 11/26/13 19:35:16.987076] old_off=-0.003061 new_off=0.447077
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=98 old_st=[Tue 11/26/13 19:35:31.150366] new_st=[Tue 11/26/13 19:35:31.604932] old_off=0.010367 new_off=0.464933
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=99 old_st=[Tue 11/26/13 19:35:46.121100] new_st=[Tue 11/26/13 19:35:46.580203] old_off=-0.018900 new_off=0.440202
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=100 old_st=[Tue 11/26/13 19:36:03.837247] new_st=[Tue 11/26/13 19:36:04.301718] old_off=-0.202753 new_off=0.261718
sourcestats.c:630:(SST_SlewSamples)[26-19:36:27] i=101 old_st=[Tue 11/26/13 19:36:18.343012] new_st=[Tue 11/26/13 19:36:18.811879] old_off=-0.396987 new_off=0.071879
sourcestats.c:648:(SST_SlewSamples)[26-19:36:27] old_off_time=[Tue 11/26/13 19:36:18.343012] new=[Tue 11/26/13 19:36:18.811879] old_off=-0.261378 new_off=0.207489 old_freq=-6278.034ppm new_freq=-5975.010ppm
refclock.c:440:(RCL_AddPulse)[26-19:36:27] refclock pulse ignored offdiff=0.401280415 refdisp=0.045591539 disp=0.118304694
refclock.c:687:(filter_add_sample)[26-19:36:28] filter sample 0 t=Tue 11/26/13 19:36:28.091548 offset=0.048451163 dispersion=0.160282302
refclock.c:440:(RCL_AddPulse)[26-19:36:28] refclock pulse ignored offdiff=-0.069207930 refdisp=0.160282302 disp=0.118304693
refclock.c:687:(filter_add_sample)[26-19:36:29] filter sample 1 t=Tue 11/26/13 19:36:29.077005 offset=0.062993935 dispersion=0.130802848
refclock.c:440:(RCL_AddPulse)[26-19:36:29] refclock pulse ignored offdiff=-0.083114452 refdisp=0.130802848 disp=0.088825240
refclock.c:687:(filter_add_sample)[26-19:36:30] filter sample 2 t=Tue 11/26/13 19:36:30.113395 offset=0.026604082 dispersion=0.108693257
refclock.c:440:(RCL_AddPulse)[26-19:36:30] refclock pulse ignored offdiff=-0.084564066 refdisp=0.108693257 disp=0.066715649
refclock.c:687:(filter_add_sample)[26-19:36:31] filter sample 3 t=Tue 11/26/13 19:36:31.147057 offset=-0.007057150 dispersion=0.092111065
refclock.c:440:(RCL_AddPulse)[26-19:36:31] refclock pulse ignored offdiff=-0.094952538 refdisp=0.092111065 disp=0.050133457
refclock.c:687:(filter_add_sample)[26-19:36:32] filter sample 4 t=Tue 11/26/13 19:36:32.562452 offset=-0.422452203 dispersion=0.079674420
refclock.c:440:(RCL_AddPulse)[26-19:36:32] refclock pulse ignored offdiff=-0.494169044 refdisp=0.079674420 disp=0.037696812

Thanks for helping me understand how all the pieces fit together.
-Scott

-----Original Message-----
From: Miroslav Lichvar [mailto:mlichvar@xxxxxxxxxx]
Sent: Tuesday, November 26, 2013 4:13 AM
To: chrony-users@xxxxxxxxxxxxxxxxxxxx
Subject: Re: [chrony-users] kernel PPS troubleshooting

On Mon, Nov 25, 2013 at 06:50:01PM -0500, Battocchi, Scott L. wrote:
> I've recently cross-compiled chrony-0308330 to run on our armv5 platform and it seems to silently/selectively ignore our PPS source even when it is present.  Currently all testing is being done with our cheap receiver (GPSi/PPSi below).   After ~hours I get a handful of entries into the refclocks.log for the PPSi source, but no mention on the console that the source is or is not present.  Right this instant we are getting updates to /sys/class/pps/pps1/assert every second but chronyc sources shows the LastRX as 26 minutes ago.
>
> Is there a way to enable more verbose debugging of the chrony source selection/rejection process so that I can see why it is rejecting what look to be good PPS updates?  I'm happy to provide more information, logs, or compile options as necessary.

The configuration looks good. A similar setup works fine here (although I've only one GPS).

There are a number of places where the PPS sample can be dropped. I've added some new trace messages to help us see what's going on. Can you please pull from git, run configure with --enable-trace, recompile and see what refclock messages do you get?

--
Miroslav Lichvar

--
To unsubscribe email chrony-users-request@xxxxxxxxxxxxxxxxxxxx
with "unsubscribe" in the subject.
For help email chrony-users-request@xxxxxxxxxxxxxxxxxxxx
with "help" in the subject.
Trouble?  Email listmaster@xxxxxxxxxxxxxxxxxxxx.

Attachment: tracking.log
Description: tracking.log