Use software timestamping with PHC and hardware timestamping available #380

dsseng · 2024-01-27T07:46:12Z

When I enable PTP hardware clock in config on RPi 5, I get [07:43:11.7057039.737701416][statime][ERROR] Missing recv timestamp (due to raspberrypi/linux#5904). However I can see the PHC frequency gets adjusted.

How can I adjust PHC (/dev/ptp0) while only using software timestamps as they work? Or may I just ignore those errors and it'll still work? I need precision around 0.5-1 ms.

Thanks!

The text was updated successfully, but these errors were encountered:

dsseng · 2024-01-27T07:52:35Z

Also, what precision is generally to be expected from statime in its current state with various configurations? Will it be fine to prefer it to ptp4l with my accuracy requirements due to it being easier for me to understand and debug?

dsseng · 2024-01-27T08:40:06Z

Maybe even when it errors out it's still quite good?

I tried to set timestamping to SoftwareAll, but it gets out of sync and crashes in less than a minute (being more stable and getting stabilized at ± when running with timestamp errors). Stats like this in defaults from master:

[08:46:07.7996690.273284912][statime::filters::kalman][INFO] Estimated offset -0.034686801503121804ns+-1174133.2582486677ns, freq 0.000014357311022746628+-99.99998660531863, delay 0.08377435839334342+-999998.6810881766
[08:46:07.9433162.212371826][statime::filters::kalman][INFO] Estimated offset 31125.072865740138ns+-33.30931256549028ns, freq -8.347503900820003+-0.01706983217142415, delay 2652.459423229703+-18.572105366843157
[08:46:08.1949384.2124938965][statime::filters::kalman][INFO] Estimated offset 35319.14693647293ns+-30.46172644472662ns, freq -12.722520424699248+-0.01637229275303176, delay 2622.005839475987+-17.6204027209198
[08:46:08.4462125.301361084][statime::filters::kalman][INFO] Estimated offset 37199.60930336006ns+-28.93209772278724ns, freq -15.406553620600468+-0.016081510426866886, delay 2614.8277874665637+-16.87171478440738
[08:46:08.6974227.428436279][statime::filters::kalman][INFO] Estimated offset 38456.04984441533ns+-27.79845833470226ns, freq -16.434162762233775+-0.015902475335899325, delay 2612.482328986073+-16.19980214007677
[08:46:08.9490563.869476318][statime::filters::kalman][INFO] Estimated offset 39277.94933217492ns+-26.956992945928928ns, freq -17.10663322403466+-0.01578921943725152, delay 2603.2635565054597+-15.59409186058029
[08:46:09.189874.17221069336][statime::filters::kalman][INFO] Estimated offset -0.04279906198298184ns+-1242381.6323622076ns, freq 0.000015946068474992853+-99.99998042108176, delay 0.10272796345380929+-999998.5560895153
[08:46:09.2006692.886352539][statime::filters::kalman][INFO] Estimated offset 39625.28804951445ns+-26.55766886997467ns, freq -17.606733314029366+-0.01576851525203414, delay 2604.129132829317+-15.087655523762544
[08:46:09.4514043.33114624][statime::filters::kalman][INFO] Estimated offset 40100.919945191185ns+-26.273022793179198ns, freq -17.675757158618243+-0.015746869519127113, delay 2601.302756383717+-14.626244054985387
[08:46:09.7031013.965606689][statime::filters::kalman][INFO] Estimated offset 39234.90804258418ns+-26.79883690400627ns, freq -18.381828499486762+-0.01591380572788276, delay 2608.5678909653243+-14.315725044408744
[08:46:09.9547462.463378906][statime::filters::kalman][INFO] Estimated offset 38936.73149882662ns+-27.251524435156938ns, freq -17.751206751849146+-0.016010494644123612, delay 2606.1132558251984+-14.020195374273246
[08:46:10.2053232.192993164][statime::filters::kalman][INFO] Estimated offset 39081.18349694967ns+-27.63778482919722ns, freq -17.445228267971217+-0.01605757128135808, delay 2603.514753704348+-13.74229023899817
[08:46:10.4563698.768615723][statime::filters::kalman][INFO] Estimated offset 39482.07682663397ns+-27.97752681301813ns, freq -17.409495251405186+-0.016074048210812774, delay 2601.6457526739846+-13.481496663727741
[08:46:10.7074570.655822754][statime::filters::kalman][INFO] Estimated offset 39800.574048241ns+-28.34220687328146ns, freq -17.634422797973908+-0.016090251232127005, delay 2604.8227520766286+-13.244131200912637
[08:46:10.8247096.538543701][statime::filters::kalman][INFO] Estimated offset -0.17059241293364785ns+-1357317.4056869515ns, freq 0.00001310906546093925+-99.99997079489602, delay 0.19305953167073178+-999998.4310910511
[08:46:10.9581725.597381592][statime::filters::kalman][INFO] Estimated offset 40179.555609666924ns+-28.63202707599666ns, freq -17.772212248102566+-0.01608230795984942, delay 2603.9807257492153+-13.018996402052307
[08:46:11.2097601.890563965][statime::filters::kalman][INFO] Estimated offset 40532.77912518289ns+-28.83482785676733ns, freq -17.96395841695188+-0.01605347494267495, delay 2604.1203170740555+-12.802422446991011
[08:46:11.4605128.765106201][statime::filters::kalman][INFO] Estimated offset 40910.36529791917ns+-28.97642126822825ns, freq -18.13788138081851+-0.016017718214112867, delay 2604.7474441976096+-12.596418339402101
[08:46:11.6728110.313415527][statime::filters::kalman][INFO] Estimated offset -0.285371224893281ns+-1416044.0008864957ns, freq 0.00007594711735546448+-99.99995865419264, delay 0.28630845293865964+-999998.3060927796

dsseng · 2024-01-27T11:29:32Z

After some minutes it'll fail like that (overadjusting the frequency by more than 1e9 ppm)

``` [11:22:20.7639591.693878174][statime::filters::kalman][INFO] Steered frequency by -0.1320306063964214ppm (target: -9.168540308114729ppm) [11:22:20.9055912.494659424][statime][ERROR] Missing recv timestamp [11:22:20.9056565.761566162][statime::port::state::slave][DEBUG] Received FollowUp 1026 [11:22:21.149624.34768676758][statime][DEBUG] Interclock measurement: 1706354541014941848 1706354541014923251 1706354541014947570 [11:22:21.150289.53552246094][statime::filters::kalman][INFO] New entry 5721.999999999997 [11:22:21.150434.9708557129][statime::filters::kalman][INFO] New uncertainty estimate: 136.46959220564383ns [11:22:21.150747.29919433594][statime::filters::kalman][INFO] Wander uncertainty: 264.63834421138546ns [11:22:21.150878.4294128418][statime::filters::kalman][INFO] Wander uncertainty: 264.5966785027631ns [11:22:21.150969.0284729004][statime::filters::kalman][INFO] wander score: 11 [11:22:21.151503.0860900879][statime::filters::kalman][INFO] Estimated offset 17131.61845804479ns+-43.41563408689763ns, freq -8.665466355160529+-0.02870302658676305, delay 2597.555683266344+-13.748049643622014 [11:22:21.152037.1437072754][statime::filters::kalman][INFO] Steered frequency by -0.09965712613813338ppm (target: -8.565809229022395ppm) [11:22:21.2015686.03515625][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:21.2037270.0691223145][statime::port::state::slave][DEBUG] Received DelayResp [11:22:21.2037792.2058105469][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354541201718844 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -621198 }) } [11:22:21.2038552.7610778809][statime::filters::kalman][INFO] Wander uncertainty: 102161886.29810876ns [11:22:21.2039473.056793213][statime::filters::kalman][INFO] wander score: 0 [11:22:21.2040102.481842041][statime::filters::kalman][INFO] Estimated offset -1.4367670406215003ns+-2371318.5261771264ns, freq 0.0004260230099286856+-99.99951496313635, delay 0.5660787382751057+-999996.3061557212 [11:22:21.2041077.6138305664][statime::filters::kalman][INFO] Steered frequency by -0.00029236051038206455ppm (target: 0.0007183835203107502ppm) [11:22:21.2654206.7527770996][statime][DEBUG] Interclock measurement: 1706354541265403933 1706354541265386069 1706354541265409377 [11:22:21.2654855.251312256][statime::filters::kalman][INFO] New entry 5444.000000000001 [11:22:21.2655565.7386779785][statime::filters::kalman][INFO] New uncertainty estimate: 137.8606834610775ns [11:22:21.2656047.3442077637][statime::filters::kalman][INFO] Wander uncertainty: 277.4332701399245ns [11:22:21.2656724.452972412][statime::filters::kalman][INFO] Wander uncertainty: 277.3918815780983ns [11:22:21.2657277.5840759277][statime::filters::kalman][INFO] wander score: 11 [11:22:21.2657985.6872558594][statime::filters::kalman][INFO] Estimated offset 16104.491715631293ns+-43.563110326944425ns, freq -8.055295548750236+-0.02872907303113814, delay 2599.985223394714+-13.614990150658809 [11:22:21.2658855.91506958][statime::filters::kalman][INFO] Steered frequency by -0.0030496909345885115ppm (target: -8.052245857815647ppm) [11:22:21.5173447.132110596][statime][DEBUG] Interclock measurement: 1706354541517323788 1706354541517306887 1706354541517329158 [11:22:21.5174429.416656494][statime::filters::kalman][INFO] New entry 5370.000000000001 [11:22:21.5175573.825836182][statime::filters::kalman][INFO] New uncertainty estimate: 139.38892415618878ns [11:22:21.5175902.843475342][statime::filters::kalman][INFO] Wander uncertainty: 290.49206608936777ns [11:22:21.5175998.210906982][statime::filters::kalman][INFO] Wander uncertainty: 290.4509584624009ns [11:22:21.5176050.662994385][statime::filters::kalman][INFO] wander score: 11 [11:22:21.5176498.889923096][statime::filters::kalman][INFO] Estimated offset 15163.4410422308ns+-43.78699430981308ns, freq -7.557415217012874+-0.028783910542611126, delay 2601.5770657812795+-13.488612650359519 [11:22:21.5176856.517791748][statime::filters::kalman][INFO] Steered frequency by 0.024305304102525405ppm (target: -7.5817205211153995ppm) [11:22:21.7691314.220428467][statime][DEBUG] Interclock measurement: 1706354541769110513 1706354541769095105 1706354541769116346 [11:22:21.7692902.088165283][statime::filters::kalman][INFO] New entry 5833 [11:22:21.7693336.009979248][statime::filters::kalman][INFO] New uncertainty estimate: 117.85810007815527ns [11:22:21.7693657.875061035][statime::filters::kalman][INFO] Wander uncertainty: 303.73033339515496ns [11:22:21.7694368.362426758][statime::filters::kalman][INFO] Wander uncertainty: 303.68950746637984ns [11:22:21.7694728.374481201][statime::filters::kalman][INFO] wander score: 11 [11:22:21.7695696.3539123535][statime::filters::kalman][INFO] Estimated offset 14561.0727279526ns+-42.30686809330098ns, freq -6.989070203702029+-0.028308665915646843, delay 2609.6158560207386+-13.317019481794206 [11:22:21.7696321.0105896][statime::filters::kalman][INFO] Steered frequency by 0.29146616027427097ppm (target: -7.2805363639763ppm) [11:22:21.9071424.007415771][statime][ERROR] Missing recv timestamp [11:22:21.9073257.446289063][statime::port::state::slave][DEBUG] Received FollowUp 1027 [11:22:22.206139.08767700195][statime][DEBUG] Interclock measurement: 1706354542020593682 1706354542020579123 1706354542020599330 [11:22:22.207490.9210205078][statime::filters::kalman][INFO] New entry 5648.000000000001 [11:22:22.207891.46423339844][statime::filters::kalman][INFO] New uncertainty estimate: 118.15732191351663ns [11:22:22.208644.86694335938][statime::filters::kalman][INFO] Wander uncertainty: 317.1354042191064ns [11:22:22.209021.56829833984][statime::filters::kalman][INFO] Wander uncertainty: 317.09485954065906ns [11:22:22.209579.4677734375][statime::filters::kalman][INFO] wander score: 11 [11:22:22.210309.02862548828][statime::filters::kalman][INFO] Estimated offset 13864.7921206184ns+-41.25685199565838ns, freq -6.763415318359078+-0.028070199139910844, delay 2614.925106459318+-13.152735140649094 [11:22:22.211226.9401550293][statime::filters::kalman][INFO] Steered frequency by 0.16898074195012214ppm (target: -6.9323960603092ppm) [11:22:22.2714042.6635742188][statime][DEBUG] Interclock measurement: 1706354542271384242 1706354542271370561 1706354542271389927 [11:22:22.2715048.7899780273][statime::filters::kalman][INFO] New entry 5685.000000000001 [11:22:22.2715988.1591796875][statime::filters::kalman][INFO] New uncertainty estimate: 112.07615498458726ns [11:22:22.2716310.0242614746][statime::filters::kalman][INFO] Wander uncertainty: 330.6825163373828ns [11:22:22.2716403.007507324][statime::filters::kalman][INFO] Wander uncertainty: 330.6422512157585ns [11:22:22.2716453.0754089355][statime::filters::kalman][INFO] wander score: 11 [11:22:22.2716913.2232666016][statime::filters::kalman][INFO] Estimated offset 13244.949727078074ns+-39.972166176082425ns, freq -6.417668399397998+-0.027799800307253653, delay 2621.0225074075256+-12.97698869333402 [11:22:22.2717268.466949463][statime::filters::kalman][INFO] Steered frequency by 0.20480646414103898ppm (target: -6.622474863539037ppm) [11:22:22.4683325.290679932][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 514, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:22.4747660.160064697][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:22.4766559.600830078][statime::port::state::slave][DEBUG] Received DelayResp [11:22:22.4768030.643463135][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354542474861615 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -509637 }) } [11:22:22.4769141.674041748][statime::filters::kalman][INFO] Wander uncertainty: 102289188.82525025ns [11:22:22.4770112.037658691][statime::filters::kalman][INFO] wander score: 0 [11:22:22.4771382.808685303][statime::filters::kalman][INFO] Estimated offset -1.311101834200276ns+-2487335.619926573ns, freq 0.0006893668346125349+-99.99945076484947, delay 0.6934834957891466+-999996.1811633079 [11:22:22.4772355.556488037][statime::filters::kalman][INFO] Steered frequency by 0.00003381591751239687ppm (target: 0.000655550917100138ppm) [11:22:22.5226709.842681885][statime][DEBUG] Interclock measurement: 1706354542522651657 1706354542522638519 1706354542522657157 [11:22:22.5227715.969085693][statime::filters::kalman][INFO] New entry 5500 [11:22:22.5228786.468505859][statime::filters::kalman][INFO] New uncertainty estimate: 112.4628612533512ns [11:22:22.5229241.847991943][statime::filters::kalman][INFO] Wander uncertainty: 344.4318181892303ns [11:22:22.5229756.832122803][statime::filters::kalman][INFO] Wander uncertainty: 344.3918315843334ns [11:22:22.5230762.958526611][statime::filters::kalman][INFO] wander score: 11 [11:22:22.5231909.75189209][statime::filters::kalman][INFO] Estimated offset 12622.96250066903ns+-39.11400774937448ns, freq -6.136122635349103+-0.02769410979244438, delay 2624.3639334632376+-12.809356590055183 [11:22:22.5233271.12197876][statime::filters::kalman][INFO] Steered frequency by 0.17535861498541117ppm (target: -6.311481250334515ppm) [11:22:22.7749116.42074585][statime][DEBUG] Interclock measurement: 1706354542774887892 1706354542774875777 1706354542774893522 [11:22:22.7750265.598297119][statime::filters::kalman][INFO] New entry 5630 [11:22:22.7751538.7535095215][statime::filters::kalman][INFO] New uncertainty estimate: 109.99182291821153ns [11:22:22.7752323.150634766][statime::filters::kalman][INFO] Wander uncertainty: 358.4091326053988ns [11:22:22.7752475.738525391][statime::filters::kalman][INFO] Wander uncertainty: 358.3694234847578ns [11:22:22.7752552.032470703][statime::filters::kalman][INFO] wander score: 11 [11:22:22.7753212.451934814][statime::filters::kalman][INFO] Estimated offset 11978.26739468622ns+-38.33449316685596ns, freq -5.862414745997947+-0.027601839018623765, delay 2629.3948729436847+-12.640897551236728 [11:22:22.7753701.210021973][statime::filters::kalman][INFO] Steered frequency by 0.12671895134516298ppm (target: -5.98913369734311ppm) [11:22:22.9087734.22241211][statime][ERROR] Missing recv timestamp [11:22:22.9090583.324432373][statime::port::state::slave][DEBUG] Received FollowUp 1028 [11:22:23.264735.22186279297][statime][DEBUG] Interclock measurement: 1706354543026452187 1706354543026441035 1706354543026457835 [11:22:23.266532.89794921875][statime::filters::kalman][INFO] New entry 5647.999999999999 [11:22:23.267064.57138061523][statime::filters::kalman][INFO] New uncertainty estimate: 110.07339697571986ns [11:22:23.267727.3750305176][statime::filters::kalman][INFO] Wander uncertainty: 372.52134827416575ns [11:22:23.268759.72747802734][statime::filters::kalman][INFO] Wander uncertainty: 372.4819133796674ns [11:22:23.269563.1980895996][statime::filters::kalman][INFO] wander score: 11 [11:22:23.270364.28451538086][statime::filters::kalman][INFO] Estimated offset 11298.377767428374ns+-37.804251294517016ns, freq -5.590883911129352+-0.027569712062178144, delay 2634.393116616357+-12.479249494481873 [11:22:23.271599.29275512695][statime::filters::kalman][INFO] Steered frequency by 0.05830497258483547ppm (target: -5.649188883714188ppm) [11:22:23.2777607.4409484863][statime][DEBUG] Interclock measurement: 1706354543277737133 1706354543277726573 1706354543277742818 [11:22:23.2778794.765472412][statime::filters::kalman][INFO] New entry 5685.000000000001 [11:22:23.2780013.084411621][statime::filters::kalman][INFO] New uncertainty estimate: 106.28882355213486ns [11:22:23.2780745.029449463][statime::filters::kalman][INFO] Wander uncertainty: 386.7871668995066ns [11:22:23.2781620.0256347656][statime::filters::kalman][INFO] Wander uncertainty: 386.748003087181ns [11:22:23.2782077.7893066406][statime::filters::kalman][INFO] wander score: 11 [11:22:23.2783055.305480957][statime::filters::kalman][INFO] Estimated offset 10739.40016403214ns+-37.141751153248975ns, freq -5.22860273276734+-0.027461260952652014, delay 2639.973834327891+-12.312565405028238 [11:22:23.2784409.523010254][statime::filters::kalman][INFO] Steered frequency by 0.14109734924873063ppm (target: -5.36970008201607ppm) [11:22:23.5300343.036651611][statime][DEBUG] Interclock measurement: 1706354543530010427 1706354543530000551 1706354543530016112 [11:22:23.5301549.434661865][statime::filters::kalman][INFO] New entry 5684.999999999999 [11:22:23.5302839.279174805][statime::filters::kalman][INFO] New uncertainty estimate: 106.66268053707859ns [11:22:23.5303406.715393066][statime::filters::kalman][INFO] Wander uncertainty: 401.2770292332561ns [11:22:23.5303890.705108643][statime::filters::kalman][INFO] Wander uncertainty: 401.2381344566339ns [11:22:23.5304965.972900391][statime::filters::kalman][INFO] wander score: 11 [11:22:23.5305764.675140381][statime::filters::kalman][INFO] Estimated offset 10175.920645260645ns+-36.740332039927345ns, freq -4.977615279563176+-0.02742003015813082, delay 2645.22881723361+-12.153613189590727 [11:22:23.5306296.348571777][statime::filters::kalman][INFO] Steered frequency by 0.11034504306714599ppm (target: -5.087960322630322ppm) [11:22:23.7821600.437164307][statime][DEBUG] Interclock measurement: 1706354543782135774 1706354543782126629 1706354543782141551 [11:22:23.7822859.287261963][statime::filters::kalman][INFO] New entry 5777.000000000001 [11:22:23.7824218.273162842][statime::filters::kalman][INFO] New uncertainty estimate: 108.20104309019626ns [11:22:23.7824785.7093811035][statime::filters::kalman][INFO] Wander uncertainty: 415.92437251881523ns [11:22:23.7825355.529785156][statime::filters::kalman][INFO] Wander uncertainty: 415.8857433047694ns [11:22:23.7826378.345489502][statime::filters::kalman][INFO] wander score: 11 [11:22:23.7827556.133270264][statime::filters::kalman][INFO] Estimated offset 9611.832585988059ns+-36.60066298344638ns, freq -4.7274975668287125+-0.027435251597494853, delay 2651.2149123777303+-12.005058125794399 [11:22:23.7828979.4921875][statime::filters::kalman][INFO] Steered frequency by 0.07841872616531731ppm (target: -4.80591629299403ppm) [11:22:23.9099800.58670044][statime::port::state::slave][DEBUG] Received FollowUp 1029 [11:22:23.9100279.808044434][statime][ERROR] Missing recv timestamp [11:22:24.334742.06924438477][statime][DEBUG] Interclock measurement: 1706354544033449571 1706354544033441147 1706354544033455404 [11:22:24.335993.76678466797][statime::filters::kalman][INFO] New entry 5833 [11:22:24.337216.854095459][statime::filters::kalman][INFO] New uncertainty estimate: 111.07224608697932ns [11:22:24.337719.9172973633][statime::filters::kalman][INFO] Wander uncertainty: 430.6876619949732ns [11:22:24.338721.27532958984][statime::filters::kalman][INFO] Wander uncertainty: 430.6492940402249ns [11:22:24.339286.32736206055][statime::filters::kalman][INFO] wander score: 11 [11:22:24.340762.1383666992][statime::filters::kalman][INFO] Estimated offset 9046.377178617891ns+-36.732072951038234ns, freq -4.480974059875081+-0.027505145720874778, delay 2657.270809407664+-11.86919945548727 [11:22:24.341501.23596191406][statime::filters::kalman][INFO] Steered frequency by 0.04221452943386428ppm (target: -4.523188589308945ppm) [11:22:24.2205944.061279297][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:24.2227251.5296936035][statime::port::state::slave][DEBUG] Received DelayResp [11:22:24.2227952.480316162][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354544220757500 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -703442 }) } [11:22:24.2229537.9638671875][statime::filters::kalman][INFO] Wander uncertainty: 102463762.35081238ns [11:22:24.2230017.1852111816][statime::filters::kalman][INFO] wander score: 0 [11:22:24.2230877.8762817383][statime::filters::kalman][INFO] Estimated offset -1.3997231307365896ns+-2648121.2745271097ns, freq 0.0006124294983926459+-99.9993764817492, delay 0.869337360919018+-999996.0561716985 [11:22:24.2232275.0091552734][statime::filters::kalman][INFO] Steered frequency by -0.0000874320669756489ppm (target: 0.0006998615653682948ppm) [11:22:24.2845752.239227295][statime][DEBUG] Interclock measurement: 1706354544284552108 1706354544284544105 1706354544284557904 [11:22:24.2846515.17868042][statime::filters::kalman][INFO] New entry 5796 [11:22:24.2847166.061401367][statime::filters::kalman][INFO] New uncertainty estimate: 113.25698502634661ns [11:22:24.2847881.317138672][statime::filters::kalman][INFO] Wander uncertainty: 445.5992297363535ns [11:22:24.2849307.060241699][statime::filters::kalman][INFO] Wander uncertainty: 445.5611192729361ns [11:22:24.2849826.8127441406][statime::filters::kalman][INFO] wander score: 11 [11:22:24.2851378.917694092][statime::filters::kalman][INFO] Estimated offset 8549.316231745714ns+-37.011254118985306ns, freq -4.198614839766733+-0.027584352125933975, delay 2662.4442460205532+-11.742959479494147 [11:22:24.2852325.439453125][statime::filters::kalman][INFO] Steered frequency by 0.07604327610612405ppm (target: -4.274658115872857ppm) [11:22:24.4699711.799621582][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 515, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:24.5364902.019500732][statime][DEBUG] Interclock measurement: 1706354544536469776 1706354544536462043 1706354544536475406 [11:22:24.5365474.224090576][statime::filters::kalman][INFO] New entry 5630 [11:22:24.5365595.817565918][statime::filters::kalman][INFO] New uncertainty estimate: 113.25833124664264ns [11:22:24.5365939.140319824][statime::filters::kalman][INFO] Wander uncertainty: 460.7187445658094ns [11:22:24.5366070.27053833][statime::filters::kalman][INFO] Wander uncertainty: 460.68088878800137ns [11:22:24.5366148.948669434][statime::filters::kalman][INFO] wander score: 11 [11:22:24.5366835.594177246][statime::filters::kalman][INFO] Estimated offset 8137.9706822117205ns+-37.252977077687355ns, freq -3.9362848653578015+-0.027615001723847045, delay 2665.6540982883016+-11.620766200491913 [11:22:24.5367333.889007568][statime::filters::kalman][INFO] Steered frequency by 0.1327004757480581ppm (target: -4.06898534110586ppm) [11:22:24.7882058.620452881][statime][DEBUG] Interclock measurement: 1706354544788181957 1706354544788174841 1706354544788187716 [11:22:24.7882871.627807617][statime::filters::kalman][INFO] New entry 5758.999999999999 [11:22:24.7883522.510528564][statime::filters::kalman][INFO] New uncertainty estimate: 110.7896055302498ns [11:22:24.7885313.034057617][statime::filters::kalman][INFO] Wander uncertainty: 475.9837547812302ns [11:22:24.7885591.983795166][statime::filters::kalman][INFO] Wander uncertainty: 475.94614978798745ns [11:22:24.7885999.67956543][statime::filters::kalman][INFO] wander score: 11 [11:22:24.7886779.308319092][statime::filters::kalman][INFO] Estimated offset 7765.4705626779105ns+-37.25435572038076ns, freq -3.738222837217094+-0.027546173925960427, delay 2670.2580119874656+-11.497055372043068 [11:22:24.7888200.283050537][statime::filters::kalman][INFO] Steered frequency by 0.14451244412186126ppm (target: -3.882735281338955ppm) [11:22:24.9106619.358062744][statime][ERROR] Missing recv timestamp [11:22:24.9108214.378356934][statime::port::state::slave][DEBUG] Received FollowUp 1030 [11:22:25.403418.54095458984][statime][DEBUG] Interclock measurement: 1706354545040318996 1706354545040312259 1706354545040324625 [11:22:25.404589.1761779785][statime::filters::kalman][INFO] New entry 5629 [11:22:25.405755.04302978516][statime::filters::kalman][INFO] New uncertainty estimate: 110.62308636945174ns [11:22:25.406491.756439209][statime::filters::kalman][INFO] Wander uncertainty: 491.43095158699003ns [11:22:25.407328.60565185547][statime::filters::kalman][INFO] Wander uncertainty: 491.3935940718934ns [11:22:25.407748.2223510742][statime::filters::kalman][INFO] wander score: 11 [11:22:25.409109.59243774414][statime::filters::kalman][INFO] Estimated offset 7413.308678383499ns+-37.24178863265226ns, freq -3.5652749392021335+-0.027483452006377744, delay 2673.307735599098+-11.376950202552921 [11:22:25.409972.6676940918][statime::filters::kalman][INFO] Steered frequency by 0.1413793999896158ppm (target: -3.7066543391917492ppm) [11:22:25.2915740.0131225586][statime][DEBUG] Interclock measurement: 1706354545291549731 1706354545291543497 1706354545291555490 [11:22:25.2916915.4167175293][statime::filters::kalman][INFO] New entry 5759 [11:22:25.2918267.250061035][statime::filters::kalman][INFO] New uncertainty estimate: 112.05220692432994ns [11:22:25.2918767.9290771484][statime::filters::kalman][INFO] Wander uncertainty: 506.97669736959716ns [11:22:25.2919228.0769348145][statime::filters::kalman][INFO] Wander uncertainty: 506.9395827207712ns [11:22:25.2919678.6880493164][statime::filters::kalman][INFO] wander score: 11 [11:22:25.2921187.8776550293][statime::filters::kalman][INFO] Estimated offset 7065.914371475806ns+-37.318844720986945ns, freq -3.411504400517305+-0.027465056140992858, delay 2677.4734290766924+-11.26357529096217 [11:22:25.2922091.484069824][statime::filters::kalman][INFO] Steered frequency by 0.12145278522059799ppm (target: -3.532957185737903ppm) [11:22:25.4856960.773468018][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:25.4876601.696014404][statime::port::state::slave][DEBUG] Received DelayResp [11:22:25.4877266.883850098][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354545485904271 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -644413 }) } [11:22:25.4878251.552581787][statime::filters::kalman][INFO] Wander uncertainty: 102590265.42412144ns [11:22:25.4879446.029663086][statime::filters::kalman][INFO] wander score: 0 [11:22:25.4880428.314208984][statime::filters::kalman][INFO] Estimated offset -1.7467739246621166ns+-2765677.929992442ns, freq 0.0006583206235230227+-99.99929400308356, delay 1.030433862024408+-999995.9311808634 [11:22:25.4882118.701934814][statime::filters::kalman][INFO] Steered frequency by -0.00021506633880803553ppm (target: 0.0008733869623310582ppm) [11:22:25.5435593.128204346][statime][DEBUG] Interclock measurement: 1706354545543537182 1706354545543530915 1706354545543542590 [11:22:25.5437555.313110352][statime::filters::kalman][INFO] New entry 5407.999999999999 [11:22:25.5437965.393066406][statime::filters::kalman][INFO] New uncertainty estimate: 113.50187400755003ns [11:22:25.5438742.637634277][statime::filters::kalman][INFO] Wander uncertainty: 522.7221388073586ns [11:22:25.5439038.276672363][statime::filters::kalman][INFO] Wander uncertainty: 522.6852640288049ns [11:22:25.5439128.875732422][statime::filters::kalman][INFO] wander score: 11 [11:22:25.5439860.820770264][statime::filters::kalman][INFO] Estimated offset 6785.614405997389ns+-37.48867868776905ns, freq -3.2252506079129746+-0.027482463562219405, delay 2677.9849523736434+-11.156427177908887 [11:22:25.5440542.697906494][statime::filters::kalman][INFO] Steered frequency by 0.16755659508572007ppm (target: -3.3928072029986946ppm) [11:22:25.7946116.924285889][statime][DEBUG] Interclock measurement: 1706354545794586019 1706354545794580473 1706354545794591760 [11:22:25.7947373.390197754][statime::filters::kalman][INFO] New entry 5741.000000000001 [11:22:25.7947902.679443359][statime::filters::kalman][INFO] New uncertainty estimate: 112.63437986789727ns [11:22:25.7949573.993682861][statime::filters::kalman][INFO] Wander uncertainty: 538.5596806441672ns [11:22:25.7949867.248535156][statime::filters::kalman][INFO] Wander uncertainty: 538.5230411481975ns [11:22:25.7950284.481048584][statime::filters::kalman][INFO] wander score: 11 [11:22:25.7951114.177703857][statime::filters::kalman][INFO] Estimated offset 6485.324267287079ns+-37.53494511349888ns, freq -3.11536931335336+-0.027456600163614717, delay 2681.6904349457536+-11.050734361568825 [11:22:25.7952749.729156494][statime::filters::kalman][INFO] Steered frequency by 0.12729282029017952ppm (target: -3.2426621336435395ppm) [11:22:25.9115428.924560547][statime][ERROR] Missing recv timestamp [11:22:25.9116461.277008057][statime::port::state::slave][DEBUG] Received FollowUp 1031 [11:22:26.471248.6267089844][statime][DEBUG] Interclock measurement: 1706354546047100797 1706354546047095651 1706354546047106556 [11:22:26.473442.07763671875][statime::filters::kalman][INFO] New entry 5758.999999999999 [11:22:26.473759.1743469238][statime::filters::kalman][INFO] New uncertainty estimate: 106.19867830718775ns [11:22:26.474495.88775634766][statime::filters::kalman][INFO] Wander uncertainty: 554.6399648663369ns [11:22:26.475025.1770019531][statime::filters::kalman][INFO] Wander uncertainty: 554.6035583345067ns [11:22:26.476052.76107788086][statime::filters::kalman][INFO] wander score: 11 [11:22:26.477221.0121154785][statime::filters::kalman][INFO] Estimated offset 6241.461614855578ns+-37.071063811109816ns, freq -2.9541319261658607+-0.027263887105834758, delay 2685.8844154135913+-10.935197098172056 [11:22:26.478620.5291748047][statime::filters::kalman][INFO] Steered frequency by 0.16659888126192834ppm (target: -3.120730807427789ppm) [11:22:26.2987682.819366455][statime][DEBUG] Interclock measurement: 1706354546298745093 1706354546298740109 1706354546298750741 [11:22:26.2988829.6127319336][statime::filters::kalman][INFO] New entry 5647.999999999999 [11:22:26.2990093.231201172][statime::filters::kalman][INFO] New uncertainty estimate: 104.15833703255406ns [11:22:26.2990877.628326416][statime::filters::kalman][INFO] Wander uncertainty: 570.8133019619978ns [11:22:26.2991375.9231567383][statime::filters::kalman][INFO] Wander uncertainty: 570.7771239433464ns [11:22:26.2991502.285003662][statime::filters::kalman][INFO] wander score: 11 [11:22:26.2992217.540740967][statime::filters::kalman][INFO] Estimated offset 6034.992645123369ns+-36.536030537059126ns, freq -2.830008087765524+-0.027092832963565815, delay 2688.8641344025023+-10.81885610722485 [11:22:26.2992749.2141723633][statime::filters::kalman][INFO] Steered frequency by 0.1874882347961604ppm (target: -3.0174963225616844ppm) [11:22:26.4707098.007202148][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:26.4711446.762084961][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 516, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:26.4729046.821594238][statime::port::state::slave][DEBUG] Received DelayResp [11:22:26.4729423.522949219][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354546470930081 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -808190 }) } [11:22:26.4730091.094970703][statime::filters::kalman][INFO] Wander uncertainty: 102688758.99147306ns [11:22:26.4730238.914489746][statime::filters::kalman][INFO] wander score: 0 [11:22:26.4730768.203735352][statime::filters::kalman][INFO] Estimated offset -2.536990526627322ns+-2857734.5570058795ns, freq 0.0008192983749337244+-99.9992049136227, delay 1.232472207241874+-999995.8061907949 [11:22:26.4731519.2222595215][statime::filters::kalman][INFO] Steered frequency by -0.0004491968883799366ppm (target: 0.001268495263313661ppm) [11:22:26.5504364.967346191][statime][DEBUG] Interclock measurement: 1706354546550419971 1706354546550415047 1706354546550425360 [11:22:26.5504899.024963379][statime::filters::kalman][INFO] New entry 5389 [11:22:26.5505070.686340332][statime::filters::kalman][INFO] New uncertainty estimate: 104.19575830323951ns [11:22:26.5505416.393280029][statime::filters::kalman][INFO] Wander uncertainty: 587.1354648605123ns [11:22:26.5505595.2072143555][statime::filters::kalman][INFO] Wander uncertainty: 587.0995117831551ns [11:22:26.5505745.410919189][statime::filters::kalman][INFO] wander score: 11 [11:22:26.5506505.966186523][statime::filters::kalman][INFO] Estimated offset 5839.635273620597ns+-36.14886768214983ns, freq -2.7330615132878027+-0.02700580725914418, delay 2688.9827835137435+-10.70633216481056 [11:22:26.5507020.950317383][statime::filters::kalman][INFO] Steered frequency by 0.1867561235224957ppm (target: -2.9198176368102984ppm) [11:22:26.7821602.821350098][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:26.7840270.99609375][statime::port::state::slave][DEBUG] Received DelayResp [11:22:26.7840642.929077148][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354546782254143 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -673686 }) } [11:22:26.7841327.19039917][statime::filters::kalman][INFO] Wander uncertainty: 102719888.55264539ns [11:22:26.7841484.546661377][statime::filters::kalman][INFO] wander score: 0 [11:22:26.7841973.304748535][statime::filters::kalman][INFO] Estimated offset -3.5467142855249763ns+-2886916.0029468895ns, freq 0.001222884334299022+-99.99911339198809, delay 1.4008851872499999+-999995.6812013653 [11:22:26.7842569.351196289][statime::filters::kalman][INFO] Steered frequency by -0.0005504728084634661ppm (target: 0.0017733571427624882ppm) [11:22:26.8014497.756958008][statime][DEBUG] Interclock measurement: 1706354546801432626 1706354546801428065 1706354546801438033 [11:22:26.8015065.1931762695][statime::filters::kalman][INFO] New entry 5407 [11:22:26.8015255.928039551][statime::filters::kalman][INFO] New uncertainty estimate: 107.82106733140735ns [11:22:26.8015613.555908203][statime::filters::kalman][INFO] Wander uncertainty: 603.5596392311522ns [11:22:26.8015921.115875244][statime::filters::kalman][INFO] Wander uncertainty: 603.523906965342ns [11:22:26.8016085.624694824][statime::filters::kalman][INFO] wander score: 11 [11:22:26.8016812.801361084][statime::filters::kalman][INFO] Estimated offset 5591.83556431553ns+-36.14849260973847ns, freq -2.6738670419424047+-0.02706093907217844, delay 2689.263428241396+-10.604590717797397 [11:22:26.8017358.779907227][statime::filters::kalman][INFO] Steered frequency by 0.12205074021536033ppm (target: -2.795917782157765ppm) [11:22:26.9126589.298248291][statime][ERROR] Missing recv timestamp [11:22:26.9127376.079559326][statime::port::state::slave][DEBUG] Received FollowUp 1032 [11:22:26.9959928.9894104][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:26.9980182.647705078][statime::port::state::slave][DEBUG] Received DelayResp [11:22:26.9980416.297912598][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354546996059739 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -851564 }) } [11:22:26.9981031.41784668][statime::filters::kalman][INFO] Wander uncertainty: 102741267.15944266ns [11:22:26.9981102.94342041][statime::filters::kalman][INFO] wander score: 0 [11:22:26.9981551.170349121][statime::filters::kalman][INFO] Estimated offset -4.967662486236831ns+-2906979.0978965536ns, freq 0.0017152482383675375+-99.9990203686946, delay 1.6137647912343493+-999995.5562125631 [11:22:26.9982063.77029419][statime::filters::kalman][INFO] Steered frequency by -0.0007685830047508778ppm (target: 0.0024838312431184153ppm) [11:22:27.524404.0489196777][statime][DEBUG] Interclock measurement: 1706354547052422006 1706354547052417864 1706354547052427487 [11:22:27.524897.575378418][statime::filters::kalman][INFO] New entry 5480.999999999999 [11:22:27.525019.1688537598][statime::filters::kalman][INFO] New uncertainty estimate: 106.39014476550827ns [11:22:27.525331.4971923828][statime::filters::kalman][INFO] Wander uncertainty: 620.1257306713212ns [11:22:27.525455.4748535156][statime::filters::kalman][INFO] Wander uncertainty: 620.0902157154445ns [11:22:27.525534.1529846191][statime::filters::kalman][INFO] wander score: 11 [11:22:27.526208.8775634766][statime::filters::kalman][INFO] Estimated offset 5347.756711410684ns+-36.054534783566226ns, freq -2.5629817155643067+-0.027060411673784698, delay 2690.262006007909+-10.503082542302806 [11:22:27.526688.0989074707][statime::filters::kalman][INFO] Steered frequency by 0.11089664014103517ppm (target: -2.673878355705342ppm) [11:22:27.3041849.136352539][statime][DEBUG] Interclock measurement: 1706354547304160882 1706354547304157302 1706354547304166697 [11:22:27.3042724.132537842][statime::filters::kalman][INFO] New entry 5815.000000000001 [11:22:27.3042874.336242676][statime::filters::kalman][INFO] New uncertainty estimate: 108.91739989551718ns [11:22:27.3043200.969696045][statime::filters::kalman][INFO] Wander uncertainty: 636.8841054101366ns [11:22:27.3043324.9473571777][statime::filters::kalman][INFO] Wander uncertainty: 636.8488049717876ns [11:22:27.3043401.2413024902][statime::filters::kalman][INFO] wander score: 11 [11:22:27.3044047.3556518555][statime::filters::kalman][INFO] Estimated offset 5075.084011879051ns+-36.196153519499134ns, freq -2.469408662272263+-0.027131371736244365, delay 2694.230173305808+-10.409098649296618 [11:22:27.3044528.9611816406][statime::filters::kalman][INFO] Steered frequency by 0.06813334366726265ppm (target: -2.5375420059395255ppm) [11:22:27.5559928.417205811][statime][DEBUG] Interclock measurement: 1706354547555968831 1706354547555965441 1706354547555974572 [11:22:27.5560731.887817383][statime::filters::kalman][INFO] New entry 5741 [11:22:27.5560877.323150635][statime::filters::kalman][INFO] New uncertainty estimate: 102.29065955529887ns [11:22:27.5561213.493347168][statime::filters::kalman][INFO] Wander uncertainty: 653.7889052695083ns [11:22:27.5561335.08682251][statime::filters::kalman][INFO] Wander uncertainty: 653.7538160172109ns [11:22:27.5561416.149139404][statime::filters::kalman][INFO] wander score: 11 [11:22:27.5562102.794647217][statime::filters::kalman][INFO] Estimated offset 4882.739357999808ns+-35.78731303044749ns, freq -2.3092045499294698+-0.02698730566985223, delay 2697.8082953633934+-10.305321985980294 [11:22:27.5562601.089477539][statime::filters::kalman][INFO] Steered frequency by 0.13216512907043443ppm (target: -2.441369678999904ppm) [11:22:27.6625368.595123291][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:27.6648635.8642578125][statime::port::state::slave][DEBUG] Received DelayResp [11:22:27.6648859.977722168][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354547662610249 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -1002464 }) } [11:22:27.6649422.645568848][statime::filters::kalman][INFO] Wander uncertainty: 102807916.12798072ns [11:22:27.6649491.786956787][statime::filters::kalman][INFO] wander score: 0 [11:22:27.6649661.064147949][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:27.6649744.510650635][statime::filters::kalman][INFO] Estimated offset -1002464ns+-999999.9310821295ns, freq 0+-100, delay 0+-999999.9310821295 [11:22:27.6650006.7710876465][statime::filters::kalman][INFO] Stepped clock by 0.001002464s [11:22:27.8083856.105804443][statime][DEBUG] Interclock measurement: 1706354547808361963 1706354547809361163 1706354547808367519 [11:22:27.8084661.960601807][statime::filters::kalman][INFO] New entry 5556.000000000094 [11:22:27.8084867.000579834][statime::filters::kalman][INFO] New uncertainty estimate: 102.58859271302285ns [11:22:27.8085324.764251709][statime::filters::kalman][INFO] Wander uncertainty: 670.874132507257ns [11:22:27.8085525.035858154][statime::filters::kalman][INFO] Wander uncertainty: 670.8392515892891ns [11:22:27.8085682.392120361][statime::filters::kalman][INFO] wander score: 11 [11:22:27.8086400.032043457][statime::filters::kalman][INFO] Estimated offset -235684.65248718375ns+-35.52189291618003ns, freq -125.51885121605969+-0.026917671476997466, delay 2699.394692484158+-10.205283507594377 [11:22:27.8086972.236633301][statime::filters::kalman][INFO] Steered frequency by -243.36117745965157ppm (target: 117.84232624359187ppm) [11:22:27.8649001.121520996][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:27.8668088.912963867][statime::port::state::slave][DEBUG] Received DelayResp [11:22:27.8668308.25805664][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354547865957247 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: 293687 }) } [11:22:27.8668863.773345947][statime::filters::kalman][INFO] Wander uncertainty: 102828148.73657988ns [11:22:27.8668935.298919678][statime::filters::kalman][INFO] wander score: 0 [11:22:27.8669354.915618896][statime::filters::kalman][INFO] Estimated offset 0.0734517644415231ns+-1000204.5016217743ns, freq 0.00000014856482376115445+-100.00000009605435, delay -0.07342170316149718+-999999.80608221 [11:22:27.8669853.210449219][statime::filters::kalman][INFO] Steered frequency by 0.000036874447044522704ppm (target: -0.00003672588222076155ppm) [11:22:27.9138193.130493164][statime][ERROR] Missing recv timestamp [11:22:27.9138860.702514648][statime::port::state::slave][DEBUG] Received FollowUp 1033 [11:22:28.602853.2981872559][statime][DEBUG] Interclock measurement: 1706354548060261999 1706354548061200742 1706354548060268093 [11:22:28.603566.1697387695][statime::filters::kalman][INFO] New entry 6094 [11:22:28.603687.7632141113][statime::filters::kalman][INFO] New uncertainty estimate: 118.10587616147936ns [11:22:28.603990.5548095703][statime::filters::kalman][INFO] Wander uncertainty: 688.065726381258ns [11:22:28.604109.7640991211][statime::filters::kalman][INFO] Wander uncertainty: 688.0310501155611ns [11:22:28.604186.0580444336][statime::filters::kalman][INFO] wander score: 11 [11:22:28.604796.4096069336][statime::filters::kalman][INFO] Estimated offset -344700.0323103659ns+-36.402543786689655ns, freq 46.45829454504112+-0.027256215759267285, delay 2704.5030229000017+-10.132373201729461 [11:22:28.605244.6365356445][statime::filters::kalman][INFO] Steered frequency by -125.89172161014181ppm (target: 172.35001615518294ppm) [11:22:28.3119525.909423828][statime][DEBUG] Interclock measurement: 1706354548311928784 1706354548312774340 1706354548311934434 [11:22:28.3120355.6060791016][statime::filters::kalman][INFO] New entry 5650.000000000056 [11:22:28.3120577.335357666][statime::filters::kalman][INFO] New uncertainty estimate: 115.36907815159185ns [11:22:28.3121025.562286377][statime::filters::kalman][INFO] Wander uncertainty: 705.3796178619986ns [11:22:28.3121261.5966796875][statime::filters::kalman][INFO] Wander uncertainty: 705.3451428529746ns [11:22:28.3121368.885040283][statime::filters::kalman][INFO] wander score: 11 [11:22:28.3122086.524963379][statime::filters::kalman][INFO] Estimated offset -412424.007634878ns+-36.95072051920299ns, freq 115.32112957598663+-0.027398145110656733, delay 2706.32347865293+-10.057576984975523 [11:22:28.3122596.7407226563][statime::filters::kalman][INFO] Steered frequency by -84.67887042401337ppm (target: 200ppm) [11:22:28.4729032.516479492][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 517, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:28.5634450.912475586][statime][DEBUG] Interclock measurement: 1706354548563421890 1706354548564153299 1706354548563427355 [11:22:28.5635104.179382324][statime::filters::kalman][INFO] New entry 5465.000000000071 [11:22:28.5635232.925415039][statime::filters::kalman][INFO] New uncertainty estimate: 113.64296630377916ns [11:22:28.5635576.248168945][statime::filters::kalman][INFO] Wander uncertainty: 722.8185043883686ns [11:22:28.5635704.99420166][statime::filters::kalman][INFO] Wander uncertainty: 722.7842273585072ns [11:22:28.5635781.288146973][statime::filters::kalman][INFO] wander score: 11 [11:22:28.5636439.323425293][statime::filters::kalman][INFO] Estimated offset -440918.0251008204ns+-37.25200307041623ns, freq 159.78305222238149+-0.02742684225764249, delay 2706.717611067922+-9.982199113474095 [11:22:28.5636906.623840332][statime::filters::kalman][INFO] Steered frequency by -40.216947777618515ppm (target: 200ppm) [11:22:28.5959272.384643555][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:28.5979590.41595459][statime::port::state::slave][DEBUG] Received DelayResp [11:22:28.5979769.229888916][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354548596706402 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: 82980 }) } [11:22:28.5980255.603790283][statime::filters::kalman][INFO] Wander uncertainty: 102901216.99612066ns [11:22:28.5980317.59262085][statime::filters::kalman][INFO] wander score: 0 [11:22:28.5980720.520019531][statime::filters::kalman][INFO] Estimated offset 0.06761276766656515ns+-1004343.5643243431ns, freq -0.00003653231233246713+-100.00000035259603, delay -0.09416664947498243+-999999.6810824003 [11:22:28.5981199.741363525][statime::filters::kalman][INFO] Steered frequency by -0.000002725928499184553ppm (target: -0.000033806383833282576ppm) [11:22:28.8146107.196807861][statime][DEBUG] Interclock measurement: 1706354548814587450 1706354548815195058 1706354548814593026 [11:22:28.8146755.695343018][statime::filters::kalman][INFO] New entry 5576.000000000084 [11:22:28.8146874.904632568][statime::filters::kalman][INFO] New uncertainty estimate: 113.39527062092426ns [11:22:28.8147201.5380859375][statime::filters::kalman][INFO] Wander uncertainty: 740.3702323465965ns [11:22:28.8147320.747375488][statime::filters::kalman][INFO] Wander uncertainty: 740.3361499687502ns [11:22:28.8147392.272949219][statime::filters::kalman][INFO] wander score: 11 [11:22:28.8148007.392883301][statime::filters::kalman][INFO] Estimated offset -437392.0098633774ns+-37.44496577708168ns, freq 176.29996087375716+-0.02742202394464126, delay 2707.952302516709+-9.90823330941915 [11:22:28.8148450.85144043][statime::filters::kalman][INFO] Steered frequency by -57.95361401255195ppm (target: 200ppm) [11:22:28.9149327.278137207][statime][ERROR] Missing recv timestamp [11:22:28.9150171.279907227][statime::port::state::slave][DEBUG] Received FollowUp 1034 [11:22:29.665311.8133544922][statime][DEBUG] Interclock measurement: 1706354549066507182 1706354549066979677 1706354549066512537 [11:22:29.666754.2457580566][statime::filters::kalman][INFO] New entry 5355.000000000019 [11:22:29.667362.2131347656][statime::filters::kalman][INFO] New uncertainty estimate: 118.73048226699784ns [11:22:29.667929.6493530273][statime::filters::kalman][INFO] Wander uncertainty: 758.1096626372241ns [11:22:29.668463.7069702148][statime::filters::kalman][INFO] Wander uncertainty: 758.0757724767312ns [11:22:29.669128.8948059082][statime::filters::kalman][INFO] wander score: 11 [11:22:29.670223.2360839844][statime::filters::kalman][INFO] Estimated offset -397076.5794454583ns+-37.95390583612994ns, freq 224.8237306831697+-0.027540707906063455, delay 2707.5310558762685+-9.84247943325788 [11:22:29.671210.2890014648][statime::filters::kalman][INFO] Steered frequency by -115.9072280251039ppm (target: 198.53828972272916ppm) [11:22:29.3177735.8055114746][statime][DEBUG] Interclock measurement: 1706354549317748422 1706354549318086475 1706354549317754018 [11:22:29.3179242.6109313965][statime::filters::kalman][INFO] New entry 5596.000000000019 [11:22:29.3179745.674133301][statime::filters::kalman][INFO] New uncertainty estimate: 116.23151951614173ns [11:22:29.3180527.687072754][statime::filters::kalman][INFO] Wander uncertainty: 775.9349742419319ns [11:22:29.3180799.4842529297][statime::filters::kalman][INFO] Wander uncertainty: 775.9012728316333ns [11:22:29.3181226.2535095215][statime::filters::kalman][INFO] wander score: 11 [11:22:29.3182218.074798584][statime::filters::kalman][INFO] Estimated offset -316648.3756720446ns+-38.15531766283585ns, freq 338.1687286361656+-0.027540924862984362, delay 2708.810087488592+-9.775195891660342 [11:22:29.3220777.5115966797][statime::filters::kalman][INFO] Steered frequency by -231.8144560502078ppm (target: 158.32418783602228ppm) [11:22:29.5726282.596588135][statime][DEBUG] Interclock measurement: 1706354549572603009 1706354549572804734 1706354549572608883 [11:22:29.5727565.288543701][statime::filters::kalman][INFO] New entry 5874.0000000000055 [11:22:29.5728087.425231934][statime::filters::kalman][INFO] New uncertainty estimate: 114.25646731183093ns [11:22:29.5728936.195373535][statime::filters::kalman][INFO] Wander uncertainty: 794.1519788341021ns [11:22:29.5729203.224182129][statime::filters::kalman][INFO] Wander uncertainty: 794.1184659418093ns [11:22:29.5729651.45111084][statime::filters::kalman][INFO] wander score: 11 [11:22:29.5730485.916137695][statime::filters::kalman][INFO] Estimated offset -178279.48324944038ns+-38.19873854329796ns, freq 567.042278060609+-0.02749957723773148, delay 2712.103359500433+-9.70702050197729 [11:22:29.5731360.912322998][statime::filters::kalman][INFO] Steered frequency by -463.6289121004156ppm (target: 89.13974162472019ppm) [11:22:29.8237128.257751465][statime][DEBUG] Interclock measurement: 1706354549823687560 1706354549823754753 1706354549823693434 [11:22:29.8238582.611083984][statime::filters::kalman][INFO] New entry 5874.0000000000055 [11:22:29.8238847.255706787][statime::filters::kalman][INFO] New uncertainty estimate: 115.37947340434255ns [11:22:29.8239572.048187256][statime::filters::kalman][INFO] Wander uncertainty: 812.2317901106238ns [11:22:29.8239850.997924805][statime::filters::kalman][INFO] Wander uncertainty: 812.1984601062051ns [11:22:29.8240294.456481934][statime::filters::kalman][INFO] wander score: 11 [11:22:29.8241186.141967773][statime::filters::kalman][INFO] Estimated offset 48527.11041161352ns+-38.23916313408309ns, freq 1014.9259199285284+-0.02748508466592059, delay 2715.240063285563+-9.641621503101682 [11:22:29.8242135.047912598][statime::filters::kalman][INFO] Steered frequency by -927.2578242008312ppm (target: -24.26355520580676ppm) [11:22:29.9167902.46963501][statime][ERROR] Missing recv timestamp [11:22:29.9168894.290924072][statime::port::state::slave][DEBUG] Received FollowUp 1035 [11:22:29.9942376.613616943][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:29.9963862.895965576][statime::port::state::slave][DEBUG] Received DelayResp [11:22:29.9964418.411254883][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354549994397306 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: 24960 }) } [11:22:29.9965488.910675049][statime::filters::kalman][INFO] Wander uncertainty: 103040973.38356727ns [11:22:29.9965906.143188477][statime::filters::kalman][INFO] wander score: 0 [11:22:29.9966940.879821777][statime::filters::kalman][INFO] Estimated offset 0.026935141637636353ns+-1026803.116240752ns, freq -0.00003366094365075543+-100.00000037237255, delay -0.10040661049820905+-999999.556082703 [11:22:29.9967606.06765747][statime::filters::kalman][INFO] Steered frequency by -0.000020193372831937254ppm (target: -0.000013467570818818176ppm) [11:22:30.760529.0412902832][statime][DEBUG] Interclock measurement: 1706354550076037348 1706354550075968672 1706354550076042666 [11:22:30.761258.602142334][statime::filters::kalman][INFO] New entry 5317.999999999992 [11:22:30.761685.3713989258][statime::filters::kalman][INFO] New uncertainty estimate: 123.01522452001115ns [11:22:30.762042.9992675781][statime::filters::kalman][INFO] Wander uncertainty: 830.5340284524844ns [11:22:30.762753.4866333008][statime::filters::kalman][INFO] Wander uncertainty: 830.5008794761312ns [11:22:30.762932.300567627][statime::filters::kalman][INFO] wander score: 11 [11:22:30.763821.6018676758][statime::filters::kalman][INFO] Estimated offset 445341.3942433001ns+-38.79238195338033ns, freq 1896.2887980224853+-0.027660338689541455, delay 2714.545677390819+-9.585563986794321 [11:22:30.764753.8185119629][statime::filters::kalman][INFO] Steered frequency by -1854.5156484016625ppm (target: -200ppm) [11:22:30.3276298.0461120605][statime][DEBUG] Interclock measurement: 1706354550327607650 1706354550327404511 1706354550327613486 [11:22:30.3277637.9585266113][statime::filters::kalman][INFO] New entry 5836.000000000003 [11:22:30.3277890.682220459][statime::filters::kalman][INFO] New uncertainty estimate: 125.16040514526972ns [11:22:30.3278536.796569824][statime::filters::kalman][INFO] Wander uncertainty: 848.9098964234943ns [11:22:30.3279092.311859131][statime::filters::kalman][INFO] Wander uncertainty: 848.8769252001143ns [11:22:30.3279690.742492676][statime::filters::kalman][INFO] wander score: 11 [11:22:30.3280229.5684814453][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:30.3280971.050262451][statime::filters::kalman][INFO] Estimated offset 206057.0000228554ns+-707106.7352234834ns, freq 0+-100, delay 2917.9999771445787+-707106.7352234834 [11:22:30.3281822.2045898438][statime::filters::kalman][INFO] Steered frequency by -3709.031296803325ppm (target: -103.02850001142771ppm) [11:22:30.4738597.869873047][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 518, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:30.5784525.8712768555][statime][DEBUG] Interclock measurement: 1706354550578428209 1706354550578090769 1706354550578434267 [11:22:30.5785171.985626221][statime::filters::kalman][INFO] New entry 6058.000000000029 [11:22:30.5785298.3474731445][statime::filters::kalman][INFO] New uncertainty estimate: 133.28940136458053ns [11:22:30.5785634.517669678][statime::filters::kalman][INFO] Wander uncertainty: 867.3594210555991ns [11:22:30.5785760.879516602][statime::filters::kalman][INFO] Wander uncertainty: 867.3266244129929ns [11:22:30.5785837.173461914][statime::filters::kalman][INFO] wander score: 11 [11:22:30.5786495.208740234][statime::filters::kalman][INFO] Estimated offset 340480.2110508024ns+-94.24917472588473ns, freq 543.4869204442045+-0.7289791547971624, delay 3017.7889476545092+-94.24917388868616 [11:22:30.5786969.6617126465][statime::filters::kalman][INFO] Steered frequency by -7418.06259360665ppm (target: -170.2401055254012ppm) [11:22:30.8302440.643310547][statime][DEBUG] Interclock measurement: 1706354550830220324 1706354550829747288 1706354550830225864 [11:22:30.8303740.02456665][statime::filters::kalman][INFO] New entry 5540.000000000005 [11:22:30.8304378.986358643][statime::filters::kalman][INFO] New uncertainty estimate: 134.2075231654052ns [11:22:30.8305130.0048828125][statime::filters::kalman][INFO] Wander uncertainty: 886.0084745542358ns [11:22:30.8305408.954620361][statime::filters::kalman][INFO] Wander uncertainty: 885.9758505714418ns [11:22:30.8305835.723876953][statime::filters::kalman][INFO] wander score: 11 [11:22:30.8306338.787078857][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:30.8307068.347930908][statime::filters::kalman][INFO] Estimated offset 475806.0000249461ns+-707106.7356382958ns, freq 0+-100, delay 2769.999975053851+-707106.7356382958 [11:22:30.8307921.886444092][statime::filters::kalman][INFO] Steered frequency by -14836.1251872133ppm (target: -200ppm) [11:22:30.9180655.479431152][statime][ERROR] Missing recv timestamp [11:22:30.9181725.978851318][statime::port::state::slave][DEBUG] Received FollowUp 1036 [11:22:31.746052.2651672363][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:31.767436.0275268555][statime::port::state::slave][DEBUG] Received DelayResp [11:22:31.768077.3735046387][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354551074144466 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -18728 }) } [11:22:31.769016.7427062988][statime::filters::kalman][INFO] Wander uncertainty: 103148938.31115906ns [11:22:31.769593.7156677246][statime::filters::kalman][INFO] wander score: 0 [11:22:31.770373.3444213867][statime::filters::kalman][INFO] Estimated offset 0.007120571280874625ns+-1056558.5688350121ns, freq -0.00001362725271143222+-99.99999945828252, delay -0.09572459259366767+-999999.4310831224 [11:22:31.771262.6457214355][statime::filters::kalman][INFO] Steered frequency by -0.000010066967070994907ppm (target: -0.0000035602856404373126ppm) [11:22:31.823440.5517578125][statime][DEBUG] Interclock measurement: 1706354551082326599 1706354551081718087 1706354551082331954 [11:22:31.824468.1358337402][statime::filters::kalman][INFO] New entry 5355.000000000074 [11:22:31.824699.4018554688][statime::filters::kalman][INFO] New uncertainty estimate: 139.79933595935296ns [11:22:31.825328.8269042969][statime::filters::kalman][INFO] Wander uncertainty: 904.8085089443982ns [11:22:31.825555.3245544434][statime::filters::kalman][INFO] Wander uncertainty: 904.7760552860888ns [11:22:31.825943.9468383789][statime::filters::kalman][INFO] wander score: 11 [11:22:31.826280.1170349121][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:31.826959.6099853516][statime::filters::kalman][INFO] Estimated offset 611189.5000261643ns+-707106.7359091521ns, freq 0+-100, delay 2677.4999738356983+-707106.7359091521 [11:22:31.827784.538269043][statime::filters::kalman][INFO] Steered frequency by -29672.2503744266ppm (target: -200ppm) [11:22:31.3343083.8584899902][statime][DEBUG] Interclock measurement: 1706354551334283569 1706354551333540685 1706354551334289813 [11:22:31.3344585.89553833][statime::filters::kalman][INFO] New entry 6243.999999999976 [11:22:31.3345146.1791992188][statime::filters::kalman][INFO] New uncertainty estimate: 157.78037001252164ns [11:22:31.3345975.875854492][statime::filters::kalman][INFO] Wander uncertainty: 923.7242541198791ns [11:22:31.3346281.051635742][statime::filters::kalman][INFO] Wander uncertainty: 923.6919681902517ns [11:22:31.3346714.973449707][statime::filters::kalman][INFO] wander score: 11 [11:22:31.3347234.7259521484][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:31.3348016.7388916016][statime::filters::kalman][INFO] Estimated offset 746006.0000388605ns+-707106.7368550473ns, freq 0+-100, delay 3121.999961139442+-707106.7368550473 [11:22:31.3348946.5713500977][statime::filters::kalman][INFO] Steered frequency by -59344.5007488532ppm (target: -200ppm) [11:22:31.5854353.904724121][statime][DEBUG] Interclock measurement: 1706354551585412257 1706354551584534024 1706354551585417982 [11:22:31.5855503.082275391][statime::filters::kalman][INFO] New entry 5725.000000000045 [11:22:31.5855994.22454834][statime::filters::kalman][INFO] New uncertainty estimate: 157.89430928068236ns [11:22:31.5856726.169586182][statime::filters::kalman][INFO] Wander uncertainty: 942.7030662274918ns [11:22:31.5857317.4476623535][statime::filters::kalman][INFO] Wander uncertainty: 942.6709450458562ns [11:22:31.5857706.069946289][statime::filters::kalman][INFO] wander score: 11 [11:22:31.5858278.274536133][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:31.5859017.372131348][statime::filters::kalman][INFO] Estimated offset 881095.500035682ns+-707106.7368614054ns, freq 0+-100, delay 2862.499964318078+-707106.7368614054 [11:22:31.5860040.187835693][statime::filters::kalman][INFO] Steered frequency by -118689.0014977064ppm (target: -200ppm) [11:22:31.8365750.312805176][statime][DEBUG] Interclock measurement: 1706354551836551210 1706354551835538163 1706354551836556972 [11:22:31.8366878.032684326][statime::filters::kalman][INFO] New entry 5762.000000000085 [11:22:31.8367342.948913574][statime::filters::kalman][INFO] New uncertainty estimate: 157.75330213556748ns [11:22:31.8367719.650268555][statime::filters::kalman][INFO] Wander uncertainty: 961.8069599675096ns [11:22:31.8367838.8595581055][statime::filters::kalman][INFO] Wander uncertainty: 961.7750011679161ns [11:22:31.8367912.769317627][statime::filters::kalman][INFO] wander score: 11 [11:22:31.8368117.809295654][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:31.8368468.284606934][statime::filters::kalman][INFO] Estimated offset 1015928.0000358485ns+-707106.7368535375ns, freq 0+-100, delay 2880.9999641516047+-707106.7368535375 [11:22:31.8358695.507049561][statime::filters::kalman][INFO] Stepped clock by -0.0010159280000358484s [11:22:31.9215271.472930908][statime][ERROR] Missing recv timestamp [11:22:31.9217038.15460205][statime::port::state::slave][DEBUG] Received FollowUp 1037 [11:22:32.872468.9483642578][statime][DEBUG] Interclock measurement: 1706354552087223962 1706354552087107142 1706354552087229446 [11:22:32.873641.9677734375][statime::filters::kalman][INFO] New entry 5484.000000000004 [11:22:32.874087.8105163574][statime::filters::kalman][INFO] New uncertainty estimate: 158.2281682438523ns [11:22:32.874772.0718383789][statime::filters::kalman][INFO] Wander uncertainty: 981.0765489200496ns [11:22:32.875227.4513244629][statime::filters::kalman][INFO] Wander uncertainty: 981.0447505282308ns [11:22:32.875730.5145263672][statime::filters::kalman][INFO] wander score: 11 [11:22:32.876767.635345459][statime::filters::kalman][INFO] Estimated offset 119559.63476513594ns+-111.88310513832539ns, freq 475.5542983085128+-0.8877200849010843, delay 2744.365238215451+-111.8831037378229 [11:22:32.877346.9924926758][statime::filters::kalman][INFO] Steered frequency by -237378.0029954128ppm (target: -59.77981738256797ppm) [11:22:32.2150952.8160095215][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:32.2172150.6118774414][statime::port::state::slave][DEBUG] Received DelayResp [11:22:32.2172422.409057617][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354552215069431 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -84965 }) } [11:22:32.2173035.144805908][statime::filters::kalman][INFO] Wander uncertainty: 103263020.48815267ns [11:22:32.2173111.4387512207][statime::filters::kalman][INFO] wander score: 0 [11:22:32.2173569.2024230957][statime::filters::kalman][INFO] Estimated offset -0.02260645518726725ns+-1098706.4747959452ns, freq -0.0000045270717790443+-99.99999743928065, delay -0.07448337669675587+-999999.3060836665 [11:22:31.3344585.89553833][statime::filters::kalman][INFO] New entry 6243.999999999976 [11:22:31.3345146.1791992188][statime::filters::kalman][INFO] New uncertainty estimate: 157.78037001252164ns [11:22:31.3345975.875854492][statime::filters::kalman][INFO] Wander uncertainty: 923.7242541198791ns [11:22:31.3346281.051635742][statime::filters::kalman][INFO] Wander uncertainty: 923.6919681902517ns [11:22:31.3346714.973449707][statime::filters::kalman][INFO] wander score: 11 [11:22:31.3347234.7259521484][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:31.3348016.7388916016][statime::filters::kalman][INFO] Estimated offset 746006.0000388605ns+-707106.7368550473ns, freq 0+-100, delay 3121.999961139442+-707106.7368550473 [11:22:31.3348946.5713500977][statime::filters::kalman][INFO] Steered frequency by -59344.5007488532ppm (target: -200ppm) [11:22:31.5854353.904724121][statime][DEBUG] Interclock measurement: 1706354551585412257 1706354551584534024 1706354551585417982 [11:22:31.5855503.082275391][statime::filters::kalman][INFO] New entry 5725.000000000045 [11:22:31.5855994.22454834][statime::filters::kalman][INFO] New uncertainty estimate: 157.89430928068236ns [11:22:31.5856726.169586182][statime::filters::kalman][INFO] Wander uncertainty: 942.7030662274918ns [11:22:31.5857317.4476623535][statime::filters::kalman][INFO] Wander uncertainty: 942.6709450458562ns [11:22:31.5857706.069946289][statime::filters::kalman][INFO] wander score: 11 [11:22:31.5858278.274536133][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:31.5859017.372131348][statime::filters::kalman][INFO] Estimated offset 881095.500035682ns+-707106.7368614054ns, freq 0+-100, delay 2862.499964318078+-707106.7368614054 [11:22:31.5860040.187835693][statime::filters::kalman][INFO] Steered frequency by -118689.0014977064ppm (target: -200ppm) [11:22:31.8365750.312805176][statime][DEBUG] Interclock measurement: 1706354551836551210 1706354551835538163 1706354551836556972 [11:22:31.8366878.032684326][statime::filters::kalman][INFO] New entry 5762.000000000085 [11:22:31.8367342.948913574][statime::filters::kalman][INFO] New uncertainty estimate: 157.75330213556748ns [11:22:31.8367719.650268555][statime::filters::kalman][INFO] Wander uncertainty: 961.8069599675096ns [11:22:31.8367838.8595581055][statime::filters::kalman][INFO] Wander uncertainty: 961.7750011679161ns [11:22:31.8367912.769317627][statime::filters::kalman][INFO] wander score: 11 [11:22:31.8368117.809295654][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:31.8368468.284606934][statime::filters::kalman][INFO] Estimated offset 1015928.0000358485ns+-707106.7368535375ns, freq 0+-100, delay 2880.9999641516047+-707106.7368535375 [11:22:31.8358695.507049561][statime::filters::kalman][INFO] Stepped clock by -0.0010159280000358484s [11:22:31.9215271.472930908][statime][ERROR] Missing recv timestamp [11:22:31.9217038.15460205][statime::port::state::slave][DEBUG] Received FollowUp 1037 [11:22:32.872468.9483642578][statime][DEBUG] Interclock measurement: 1706354552087223962 1706354552087107142 1706354552087229446 [11:22:32.873641.9677734375][statime::filters::kalman][INFO] New entry 5484.000000000004 [11:22:32.874087.8105163574][statime::filters::kalman][INFO] New uncertainty estimate: 158.2281682438523ns [11:22:32.874772.0718383789][statime::filters::kalman][INFO] Wander uncertainty: 981.0765489200496ns [11:22:32.875227.4513244629][statime::filters::kalman][INFO] Wander uncertainty: 981.0447505282308ns [11:22:32.875730.5145263672][statime::filters::kalman][INFO] wander score: 11 [11:22:32.876767.635345459][statime::filters::kalman][INFO] Estimated offset 119559.63476513594ns+-111.88310513832539ns, freq 475.5542983085128+-0.8877200849010843, delay 2744.365238215451+-111.8831037378229 [11:22:32.877346.9924926758][statime::filters::kalman][INFO] Steered frequency by -237378.0029954128ppm (target: -59.77981738256797ppm) [11:22:32.9199395.179748535][statime][ERROR] Missing recv timestamp [11:22:32.9200055.599212646][statime::port::state::slave][DEBUG] Received FollowUp 1038 [11:22:33.934045.3147888184][statime][DEBUG] Interclock measurement: 1706354553093371516 1706354553092856737 1706354553093377315 [11:22:33.934896.4691162109][statime::filters::kalman][INFO] New entry 5798.999999999908 [11:22:33.935118.1983947754][statime::filters::kalman][INFO] New uncertainty estimate: 162.71367465383173ns [11:22:33.935554.5043945313][statime::filters::kalman][INFO] Wander uncertainty: 1059.331801415965ns [11:22:33.935807.2280883789][statime::filters::kalman][INFO] Wander uncertainty: 1059.3006219543086ns [11:22:33.935955.0476074219][statime::filters::kalman][INFO] wander score: 11 [11:22:33.936229.2289733887][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:33.936670.3033447266][statime::filters::kalman][INFO] Estimated offset 517678.50003838324ns+-707106.737134548ns, freq 0+-100, delay 2899.4999616167456+-707106.737134548 [11:22:33.937268.7339782715][statime::filters::kalman][INFO] Steered frequency by -3798048.0479266047ppm (target: -200ppm) [11:22:33.3452632.427215576][statime][DEBUG] Interclock measurement: 1706354553345237895 1706354553344619455 1706354553345243897 [11:22:33.3453440.6661987305][statime::filters::kalman][INFO] New entry 6001.999999999961 [11:22:33.3453640.937805176][statime::filters::kalman][INFO] New uncertainty estimate: 167.737023859924ns [11:22:33.3454167.8428649902][statime::filters::kalman][INFO] Wander uncertainty: 1079.223748128648ns [11:22:33.3454384.8037719727][statime::filters::kalman][INFO] Wander uncertainty: 1079.1927182513355ns [11:22:33.3454692.3637390137][statime::filters::kalman][INFO] wander score: 11 [11:22:33.3454997.5395202637][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:33.3455426.6929626465][statime::filters::kalman][INFO] Estimated offset 621441.0000422177ns+-707106.7374279919ns, freq 0+-100, delay 3000.9999577823432+-707106.7374279919 [11:22:33.3455972.671508789][statime::filters::kalman][INFO] Steered frequency by -7596096.0958532095ppm (target: -200ppm) [11:22:33.5970904.82711792][statime][DEBUG] Interclock measurement: 1706354553597066667 1706354553596344074 1706354553597072336 [11:22:33.5971679.6875][statime::filters::kalman][INFO] New entry 5669.00000000003 [11:22:33.5971875.190734863][statime::filters::kalman][INFO] New uncertainty estimate: 164.23433666169555ns [11:22:33.5972259.044647217][statime::filters::kalman][INFO] Wander uncertainty: 1099.232341868073ns [11:22:33.5972437.858581543][statime::filters::kalman][INFO] Wander uncertainty: 1099.201459500886ns [11:22:33.5972568.988800049][statime::filters::kalman][INFO] wander score: 11 [11:22:33.5972812.175750732][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:33.5973217.487335205][statime::filters::kalman][INFO] Estimated offset 725427.5000382273ns+-707106.7372224374ns, freq 0+-100, delay 2834.4999617726435+-707106.7372224374 [11:22:33.5973725.318908691][statime::filters::kalman][INFO] Steered frequency by -15192192.191706419ppm (target: -200ppm) [11:22:33.8489165.306091309][statime][DEBUG] Interclock measurement: 1706354553848892754 1706354553848066353 1706354553848898515 [11:22:33.8489947.319030762][statime::filters::kalman][INFO] New entry 5760.999999999961 [11:22:33.8490138.053894043][statime::filters::kalman][INFO] New uncertainty estimate: 164.3717695622628ns [11:22:33.8490536.212921143][statime::filters::kalman][INFO] Wander uncertainty: 1119.3596585380023ns [11:22:33.8490734.100341797][statime::filters::kalman][INFO] Wander uncertainty: 1119.3289216712308ns [11:22:33.8491015.434265137][statime::filters::kalman][INFO] wander score: 11 [11:22:33.8491301.536560059][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:33.8491723.537445068][statime::filters::kalman][INFO] Estimated offset 829281.5000389128ns+-707106.7372304209ns, freq 0+-100, delay 2880.4999610871882+-707106.7372304209 [11:22:33.8492257.595062256][statime::filters::kalman][INFO] Steered frequency by -30384384.383412838ppm (target: -200ppm) [11:22:33.9165229.797363281][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:33.9182548.522949219][statime::port::state::slave][DEBUG] Received DelayResp [11:22:33.9182815.551757813][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354553915771258 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: 45927 }) } [11:22:33.9183490.27633667][statime::filters::kalman][INFO] Wander uncertainty: 103433075.3329145ns [11:22:33.9183626.174926758][statime::filters::kalman][INFO] wander score: 0 [11:22:33.9184088.706970215][statime::filters::kalman][INFO] Estimated offset 0.01255304291108109ns+-1179361.1009041194ns, freq 0.000012021082564426738+-99.99999340345806, delay -0.08596506972945775+-999999.1810843508 [11:22:33.9184620.380401611][statime::filters::kalman][INFO] Steered frequency by 0.000018297604019967284ppm (target: -0.000006276521455540545ppm) [11:22:33.9217038.15460205][statime][ERROR] Missing recv timestamp [11:22:33.9217472.076416016][statime::port::state::slave][DEBUG] Received FollowUp 1039 [11:22:34.1011066.4367675781][statime][DEBUG] Interclock measurement: 1706354554101087202 1706354554100155052 1706354554101092630 [11:22:34.1011703.0143737793][statime::filters::kalman][INFO] New entry 5428.00000000003 [11:22:34.1011888.9808654785][statime::filters::kalman][INFO] New uncertainty estimate: 167.03432951911566ns [11:22:34.1012270.450592041][statime::filters::kalman][INFO] Wander uncertainty: 1139.6348819830614ns [11:22:34.1012446.8803405762][statime::filters::kalman][INFO] Wander uncertainty: 1139.6042888590596ns [11:22:34.1012580.394744873][statime::filters::kalman][INFO] wander score: 11 [11:22:34.1012825.9658813477][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:34.1013216.9723510742][statime::filters::kalman][INFO] Estimated offset 934864.0000378609ns+-707106.7373864066ns, freq 0+-100, delay 2713.999962139076+-707106.7373864066 [11:22:34.1013727.1881103516][statime::filters::kalman][INFO] Steered frequency by -60768768.766825676ppm (target: -200ppm) [11:22:34.3532490.7302856445][statime][DEBUG] Interclock measurement: 1706354554353223810 1706354554352184110 1706354554353229720 [11:22:34.3533346.652984619][statime::filters::kalman][INFO] New entry 5910.00000000003 [11:22:34.3533551.6929626465][statime::filters::kalman][INFO] New uncertainty estimate: 169.6434695295685ns [11:22:34.3534157.2761535645][statime::filters::kalman][INFO] Wander uncertainty: 1160.0233309172095ns [11:22:34.3534379.005432129][statime::filters::kalman][INFO] Wander uncertainty: 1159.9928795733863ns [11:22:34.3534526.824951172][statime::filters::kalman][INFO] wander score: 11 [11:22:34.3534808.1588745117][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:34.3535251.6174316406][statime::filters::kalman][INFO] Estimated offset 1042655.0000425208ns+-707106.7375416942ns, freq 0+-100, delay 2954.999957479175+-707106.7375416942 [11:22:34.3525292.8733825684][statime::filters::kalman][INFO] Stepped clock by -0.0010426550000425209s [11:22:34.4741699.695587158][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 520, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:34.6036961.078643799][statime][DEBUG] Interclock measurement: 1706354554603671190 1706354554603539909 1706354554603676971 [11:22:34.6037812.232971191][statime::filters::kalman][INFO] New entry 5781.000000000005 [11:22:34.6038036.346435547][statime::filters::kalman][INFO] New uncertainty estimate: 165.86390256286717ns [11:22:34.6038482.189178467][statime::filters::kalman][INFO] Wander uncertainty: 1180.4761771689266ns [11:22:34.6038691.997528076][statime::filters::kalman][INFO] Wander uncertainty: 1180.4458653593567ns [11:22:34.6038839.817047119][statime::filters::kalman][INFO] wander score: 11 [11:22:34.6039602.756500244][statime::filters::kalman][INFO] Estimated offset 134168.58080722895ns+-117.28221516888811ns, freq 533.7153367671368+-0.9433721248650438, delay 2893.419194371612+-117.28221355570082 [11:22:34.6040203.57131958][statime::filters::kalman][INFO] Steered frequency by -121537537.53365135ppm (target: -67.08429040361447ppm) [11:22:34.8545560.836791992][statime][DEBUG] Interclock measurement: 1706354554854530148 1706354554854263668 1706354554854536170 [11:22:34.8546400.07019043][statime::filters::kalman][INFO] New entry 6022.000000000005 [11:22:34.8546602.725982666][statime::filters::kalman][INFO] New uncertainty estimate: 166.66837364716346ns [11:22:34.8547041.416168213][statime::filters::kalman][INFO] Wander uncertainty: 1200.993177874935ns [11:22:34.8547275.066375732][statime::filters::kalman][INFO] Wander uncertainty: 1200.963003415645ns [11:22:34.8547549.2477417][statime::filters::kalman][INFO] wander score: 11 [11:22:34.8547856.80770874][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:34.8548319.339752197][statime::filters::kalman][INFO] Estimated offset 269491.0000418203ns+-707106.7373648185ns, freq 0+-100, delay 3010.9999581796956+-707106.7373648185 [11:22:34.8548908.233642578][statime::filters::kalman][INFO] Steered frequency by -243075075.0673027ppm (target: -134.74550002091016ppm) [11:22:34.9228599.071502686][statime][ERROR] Missing recv timestamp [11:22:34.9229218.95980835][statime::port::state::slave][DEBUG] Received FollowUp 1040 [11:22:35.1053421.4973449707][statime][DEBUG] Interclock measurement: 1706354555105318146 1706354555104928986 1706354555105323796 [11:22:35.1054191.5893554688][statime::filters::kalman][INFO] New entry 5650.000000000002 [11:22:35.1054406.1660766602][statime::filters::kalman][INFO] New uncertainty estimate: 164.2339361590264ns [11:22:35.1054801.9409179688][statime::filters::kalman][INFO] Wander uncertainty: 1221.6189772180462ns [11:22:35.1055006.980895996][statime::filters::kalman][INFO] Wander uncertainty: 1221.5889382768007ns [11:22:35.1055135.726928711][statime::filters::kalman][INFO] wander score: 11 [11:22:35.1055376.5296936035][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:35.1055762.767791748][statime::filters::kalman][INFO] Estimated offset 391985.00003809907ns+-707106.7372224141ns, freq 0+-100, delay 2824.9999619009363+-707106.7372224141 [11:22:35.1056280.1361083984][statime::filters::kalman][INFO] Steered frequency by -486150150.1346054ppm (target: -195.99250001904952ppm) [11:22:35.3571505.546569824][statime][DEBUG] Interclock measurement: 1706354555357126153 1706354555356633805 1706354555357131989 [11:22:35.3572301.8646240234][statime::filters::kalman][INFO] New entry 5836.000000000057 [11:22:35.3572499.7520446777][statime::filters::kalman][INFO] New uncertainty estimate: 164.45912694490664ns [11:22:35.3572890.7585144043][statime::filters::kalman][INFO] Wander uncertainty: 1242.44336588501ns [11:22:35.3573100.5668640137][statime::filters::kalman][INFO] Wander uncertainty: 1242.4134612461362ns [11:22:35.3573241.2338256836][statime::filters::kalman][INFO] wander score: 11 [11:22:35.3573484.420776367][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:35.3573904.037475586][statime::filters::kalman][INFO] Estimated offset 495266.00003946136ns+-707106.7372354988ns, freq 0+-100, delay 2917.9999605387366+-707106.7372354988 [11:22:35.3574447.6318359375][statime::filters::kalman][INFO] Steered frequency by -972300300.2692108ppm (target: -200ppm) [11:22:35.4467694.7593688965][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:35.4491548.538208008][statime::port::state::slave][DEBUG] Received DelayResp [11:22:35.4491853.713989258][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354555446343092 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -45522 }) } [11:22:35.4492535.591125488][statime::filters::kalman][INFO] Wander uncertainty: 103586118.75823553ns [11:22:35.4492678.642272949][statime::filters::kalman][INFO] wander score: 0 [11:22:35.4493322.372436523][statime::filters::kalman][INFO] Estimated offset -0.015294442705541944ns+-1267164.491709744ns, freq -0.0000071622350961051245+-99.99998659740628, delay -0.07458459453191787+-999999.0560851926 [11:22:35.4493875.503540039][statime::filters::kalman][INFO] Steered frequency by -0.000014809456448876095ppm (target: 0.000007647221352770972ppm) [11:22:35.6087415.2183532715][statime][DEBUG] Interclock measurement: 1706354555608724342 1706354555608128264 1706354555608729751 [11:22:35.6087973.117828369][statime::filters::kalman][INFO] New entry 5409.000000000056 [11:22:35.6088163.85269165][statime::filters::kalman][INFO] New uncertainty estimate: 168.8411581740219ns [11:22:35.6088509.559631348][statime::filters::kalman][INFO] Wander uncertainty: 1263.3645178575043ns [11:22:35.6088705.062866211][statime::filters::kalman][INFO] Wander uncertainty: 1263.3347456765835ns [11:22:35.6088852.882385254][statime::filters::kalman][INFO] wander score: 11 [11:22:35.6089134.216308594][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:35.6089549.0646362305][statime::filters::kalman][INFO] Estimated offset 598782.5000385491ns+-707106.737493687ns, freq 0+-100, delay 2704.499961450977+-707106.737493687 [11:22:35.6090216.636657715][statime::filters::kalman][INFO] Steered frequency by -1944600600.5384216ppm (target: -200ppm) [11:22:35.8595833.778381348][statime][DEBUG] Interclock measurement: 1706354555859557265 1706354555858858743 1706354555859563212 [11:22:35.8596799.373626709][statime::filters::kalman][INFO] New entry 5946.999999999962 [11:22:35.8597021.102905273][statime::filters::kalman][INFO] New uncertainty estimate: 170.2991541826302ns [11:22:35.8597455.024719238][statime::filters::kalman][INFO] Wander uncertainty: 1284.33503685235ns [11:22:35.8597671.98562622][statime::filters::kalman][INFO] Wander uncertainty: 1284.3053950379488ns [11:22:35.8597822.189331055][statime::filters::kalman][INFO] wander score: 11 [11:22:35.8598093.98651123][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:35.8598594.665527344][statime::filters::kalman][INFO] Estimated offset 701495.5000431185ns+-707106.7375810969ns, freq 0+-100, delay 2973.499956881546+-707106.7375810969 [11:22:35.8599500.65612793][statime::filters::kalman][INFO] Steered frequency by -3889201201.0768433ppm (target: -200ppm) [11:22:35.9240753.650665283][statime][ERROR] Missing recv timestamp [11:22:35.9241414.070129395][statime::port::state::slave][DEBUG] Received FollowUp 1041 [11:22:36.33977.03170776367][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:36.54364.20440673828][statime::port::state::slave][DEBUG] Received DelayResp [11:22:36.54609.77554321289][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354556002704473 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -218697 }) } [11:22:36.55265.42663574219][statime::filters::kalman][INFO] Wander uncertainty: 103641749.9059368ns [11:22:36.55520.53451538086][statime::filters::kalman][INFO] wander score: 0 [11:22:36.56054.59213256836][statime::filters::kalman][INFO] Estimated offset -0.10377113840094847ns+-1302075.5064552696ns, freq 0.000003087895572193414+-99.99997818306673, delay -0.019910593415731984+-999998.9310861932 [11:22:36.56619.64416503906][statime::filters::kalman][INFO] Steered frequency by -0.00004879767362828082ppm (target: 0.00005188556920047424ppm) [11:22:36.1110002.9945373535][statime][DEBUG] Interclock measurement: 1706354556110975942 1706354556110172181 1706354556110981611 [11:22:36.1110901.8325805664][statime::filters::kalman][INFO] New entry 5669.00000000003 [11:22:36.1111116.4093017578][statime::filters::kalman][INFO] New uncertainty estimate: 163.32421249494396ns [11:22:36.1111552.7153015137][statime::filters::kalman][INFO] Wander uncertainty: 1305.4670741051614ns [11:22:36.1111762.523651123][statime::filters::kalman][INFO] Wander uncertainty: 1305.4375613034583ns [11:22:36.1111907.958984375][statime::filters::kalman][INFO] wander score: 11 [11:22:36.1112177.3719787598][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:36.1112637.5198364258][statime::filters::kalman][INFO] Estimated offset 806595.5000378048ns+-707106.7371697369ns, freq 0+-100, delay 2834.499962195152+-707106.7371697369 [11:22:36.1113231.1820983887][statime::filters::kalman][INFO] Steered frequency by -7778402402.153687ppm (target: -200ppm) [11:22:36.2657103.5385131836][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:36.2676124.5727539063][statime::port::state::slave][DEBUG] Received DelayResp [11:22:36.2676446.4378356934][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354556264937653 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -42352 }) } [11:22:36.2677125.930786133][statime::filters::kalman][INFO] Wander uncertainty: 103667970.87374647ns [11:22:36.2677352.4284362793][statime::filters::kalman][INFO] wander score: 0 [11:22:36.2677853.1074523926][statime::filters::kalman][INFO] Estimated offset -0.10869168170479794ns+-1319023.5766118322ns, freq 0.00005097486527621763+-99.99996906638358, delay -0.009322669765021089+-999998.8060873535 [11:22:36.2678453.9222717285][statime::filters::kalman][INFO] Steered frequency by -0.0000033709755761813454ppm (target: 0.000054345840852398976ppm) [11:22:36.3632223.606109619][statime][DEBUG] Interclock measurement: 1706354556363199735 1706354556362288180 1706354556363205256 [11:22:36.3632981.777191162][statime::filters::kalman][INFO] New entry 5520.999999999976 [11:22:36.3633172.5120544434][statime::filters::kalman][INFO] New uncertainty estimate: 164.81567019287385ns [11:22:36.3633577.823638916][statime::filters::kalman][INFO] Wander uncertainty: 1326.7794449649184ns [11:22:36.3633730.411529541][statime::filters::kalman][INFO] Wander update predict: 7859039397044.938ns, actual: 917076ns [11:22:36.3633866.310119629][statime::filters::kalman][INFO] p: 1 [11:22:36.3633973.5984802246][statime::filters::kalman][INFO] Wander update [11:22:36.3634142.8756713867][statime::filters::kalman][INFO] Wander uncertainty: 166.21035644455657ns [11:22:36.3634278.7742614746][statime::filters::kalman][INFO] wander score: 12 [11:22:36.3634533.8821411133][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:36.3634960.651397705][statime::filters::kalman][INFO] Estimated offset 914315.5000374934ns+-707106.7372562526ns, freq 0+-100, delay 2760.4999625065893+-707106.7372562526 [11:22:36.3635509.0141296387][statime::filters::kalman][INFO] Steered frequency by -15556804804.307373ppm (target: -200ppm) [11:22:36.4760963.916778564][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 521, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:36.6145982.74230957][statime][DEBUG] Interclock measurement: 1706354556614574830 1706354556613556139 1706354556614580462 [11:22:36.6146752.834320068][statime::filters::kalman][INFO] New entry 5631.999999999989 [11:22:36.6146965.026855469][statime::filters::kalman][INFO] New uncertainty estimate: 162.25939383312885ns [11:22:36.6147365.570068359][statime::filters::kalman][INFO] Wander uncertainty: 1415109.8340974406ns [11:22:36.6147508.62121582][statime::filters::kalman][INFO] Wander update predict: 7820504631317.596ns, actual: 1024323ns [11:22:36.6147632.598876953][statime::filters::kalman][INFO] p: 1 [11:22:36.6147732.734680176][statime::filters::kalman][INFO] Wander update [11:22:36.6147902.011871338][statime::filters::kalman][INFO] Wander uncertainty: 167.78169038168832ns [11:22:36.6148033.142089844][statime::filters::kalman][INFO] wander score: 13 [11:22:36.6148293.018341064][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:36.6148688.793182373][statime::filters::kalman][INFO] Estimated offset 1021507.00003707ns+-707106.7371084505ns, freq 0+-100, delay 2815.99996293001+-707106.7371084505 [11:22:36.6138930.320739746][statime::filters::kalman][INFO] Stepped clock by -0.00102150700003707s [11:22:36.6681814.193725586][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:36.6702737.808227539][statime::port::state::slave][DEBUG] Received DelayResp [11:22:36.6703038.215637207][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354556668247063 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -231901 }) } [11:22:36.6703727.245330811][statime::filters::kalman][INFO] Wander uncertainty: 103708298.20265418ns [11:22:36.6703879.833221436][statime::filters::kalman][INFO] wander score: 0 [11:22:36.6704385.280609131][statime::filters::kalman][INFO] Estimated offset -0.19176323152639316ns+-1345670.3660270455ns, freq 0.00004912540272395134+-99.99995913267296, delay 0.048652195911984136+-999998.6810886824 [11:22:36.6704995.632171631][statime::filters::kalman][INFO] Steered frequency by -0.00004675621303924523ppm (target: 0.00009588161576319658ppm) [11:22:36.8654887.676239014][statime][DEBUG] Interclock measurement: 1706354556865462193 1706354556865330498 1706354556865468196 [11:22:36.8655712.604522705][statime::filters::kalman][INFO] New entry 6003.000000000004 [11:22:36.8655922.412872314][statime::filters::kalman][INFO] New uncertainty estimate: 165.475230519013ns [11:22:36.8656339.645385742][statime::filters::kalman][INFO] Wander uncertainty: 1415108.7146453988ns [11:22:36.8656511.306762695][statime::filters::kalman][INFO] Wander update predict: 7824607897572.291ns, actual: 137698ns [11:22:36.8656821.250915527][statime::filters::kalman][INFO] p: 1 [11:22:36.8656947.612762451][statime::filters::kalman][INFO] Wander update [11:22:36.8657152.652740479][statime::filters::kalman][INFO] Wander uncertainty: 162.25939226021183ns [11:22:36.8657302.856445313][statime::filters::kalman][INFO] wander score: 14 [11:22:36.8658101.558685303][statime::filters::kalman][INFO] Estimated offset 134693.59818661926ns+-117.00739551095661ns, freq 533.9213235878467+-0.9199726410539647, delay 3004.401808133627+-117.00739390911346 [11:22:36.8658816.814422607][statime::filters::kalman][INFO] Steered frequency by -31113609608.614746ppm (target: -67.34679909330963ppm) [11:22:36.9250142.574310303][statime][ERROR] Missing recv timestamp [11:22:36.9250888.82446289][statime::port::state::slave][DEBUG] Received FollowUp 1042 [11:22:36.9663755.893707275][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:36.9685668.9453125][statime::port::state::slave][DEBUG] Received DelayResp [11:22:36.9686024.188995361][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354556966301985 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -308757 }) } [11:22:36.9686801.433563232][statime::filters::kalman][INFO] Wander uncertainty: 103738101.02734415ns [11:22:36.9687149.52468872][statime::filters::kalman][INFO] wander score: 0 [11:22:36.9687740.802764893][statime::filters::kalman][INFO] Estimated offset -0.3072754160865701ns+-1365794.135145696ns, freq 0.00008870097577947983+-99.99994846427818, delay 0.1258408487644427+-999998.5560901826 [11:22:36.9688344.00177002][statime::filters::kalman][INFO] Steered frequency by -0.00006493673226380523ppm (target: 0.00015363770804328506ppm) [11:22:37.1172285.0799560547][statime][DEBUG] Interclock measurement: 1706354557117204094 1706354557116948676 1706354557117209707 [11:22:37.1173090.934753418][statime::filters::kalman][INFO] New entry 5613.0000000000155 [11:22:37.1173317.4324035645][statime::filters::kalman][INFO] New uncertainty estimate: 159.33371698084963ns [11:22:37.1173746.5858459473][statime::filters::kalman][INFO] Wander uncertainty: 1415110.0187762426ns [11:22:37.1174073.2192993164][statime::filters::kalman][INFO] Wander update predict: 7820758341808.597ns, actual: 261031ns [11:22:37.1174242.4964904785][statime::filters::kalman][INFO] p: 1 [11:22:37.1174356.9374084473][statime::filters::kalman][INFO] Wander update [11:22:37.1174557.2090148926][statime::filters::kalman][INFO] Wander uncertainty: 165.72168741649602ns [11:22:37.1174712.1810913086][statime::filters::kalman][INFO] wander score: 15 [11:22:37.1175012.5885009766][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:37.1175460.8154296875][statime::filters::kalman][INFO] Estimated offset 258224.50003562466ns+-707106.7369421254ns, freq 0+-100, delay 2806.499964375368+-707106.7369421254 [11:22:37.1176044.9409484863][statime::filters::kalman][INFO] Steered frequency by -62227219217.22949ppm (target: -129.11225001781233ppm) [11:22:37.3691289.4248962402][statime][DEBUG] Interclock measurement: 1706354557369105669 1706354557368742355 1706354557369111523 [11:22:37.3692042.827606201][statime::filters::kalman][INFO] New entry 5854.0000000000155 [11:22:37.3692238.3308410645][statime::filters::kalman][INFO] New uncertainty estimate: 159.15733080062236ns [11:22:37.3692617.416381836][statime::filters::kalman][INFO] Wander uncertainty: 492.01773964462404ns [11:22:37.3692805.767059326][statime::filters::kalman][INFO] Wander uncertainty: 592.9259893948912ns [11:22:37.3692960.739135742][statime::filters::kalman][INFO] wander score: 15 [11:22:37.3693211.078643799][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:37.3693614.0060424805][statime::filters::kalman][INFO] Estimated offset 366241.000037072ns+-707106.7369321946ns, freq 0+-100, delay 2926.999962928003+-707106.7369321946 [11:22:37.3694121.837615967][statime::filters::kalman][INFO] Steered frequency by -124454438434.45898ppm (target: -183.120500018536ppm) [11:22:37.6210329.532623291][statime][DEBUG] Interclock measurement: 1706354557621008986 1706354557620537174 1706354557621014469 [11:22:37.6211228.370666504][statime::filters::kalman][INFO] New entry 5482.9999999999745 [11:22:37.6211457.252502441][statime::filters::kalman][INFO] New uncertainty estimate: 161.17221179482854ns [11:22:37.6211895.942687988][statime::filters::kalman][INFO] Wander uncertainty: 714.5480624026143ns [11:22:37.6212115.287780762][statime::filters::kalman][INFO] Wander uncertainty: 821.4723882242076ns [11:22:37.6212282.180786133][statime::filters::kalman][INFO] wander score: 15 [11:22:37.6212577.819824219][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:37.6213040.351867676][statime::filters::kalman][INFO] Estimated offset 474553.50003560726ns+-707106.7370462909ns, freq 0+-100, delay 2741.49996439272+-707106.7370462909 [11:22:37.6213653.087615967][statime::filters::kalman][INFO] Steered frequency by -248908876868.91797ppm (target: -200ppm) [11:22:37.8728826.04598999][statime][DEBUG] Interclock measurement: 1706354557872858503 1706354557872278773 1706354557872864172 [11:22:37.8729650.974273682][statime::filters::kalman][INFO] New entry 5669.00000000003 [11:22:37.8729872.703552246][statime::filters::kalman][INFO] New uncertainty estimate: 160.1196235656479ns [11:22:37.8730313.777923584][statime::filters::kalman][INFO] Wander uncertainty: 941.5062551706849ns [11:22:37.8730528.354644775][statime::filters::kalman][INFO] Wander uncertainty: 1051.388854621005ns [11:22:37.8730683.326721191][statime::filters::kalman][INFO] wander score: 15 [11:22:37.8730986.11831665][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:37.8731422.424316406][statime::filters::kalman][INFO] Estimated offset 582564.5000363358ns+-707106.7369865071ns, freq 0+-100, delay 2834.4999636641382+-707106.7369865071 [11:22:37.8732023.239135742][statime::filters::kalman][INFO] Steered frequency by -497817753737.83594ppm (target: -200ppm) [11:22:37.9270541.667938232][statime][ERROR] Missing recv timestamp [11:22:37.9271414.279937744][statime::port::state::slave][DEBUG] Received FollowUp 1043 [11:22:38.1245989.7994995117][statime][DEBUG] Interclock measurement: 1706354558124574277 1706354558123885671 1706354558124580112 [11:22:38.1246807.57522583][statime::filters::kalman][INFO] New entry 5834.999999999933 [11:22:38.1247014.9993896484][statime::filters::kalman][INFO] New uncertainty estimate: 152.1768323577853ns [11:22:38.1247458.4579467773][statime::filters::kalman][INFO] Wander uncertainty: 1170.2221964618182ns [11:22:38.1247668.2662963867][statime::filters::kalman][INFO] Wander uncertainty: 1281.8431858863382ns [11:22:38.1247816.0858154297][statime::filters::kalman][INFO] wander score: 15 [11:22:38.1248090.2671813965][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:38.1248569.4885253906][statime::filters::kalman][INFO] Estimated offset 691523.5000337814ns+-707106.7365480114ns, freq 0+-100, delay 2917.4999662185382+-707106.7365480114 [11:22:38.1249253.749847412][statime::filters::kalman][INFO] Steered frequency by -995635507475.6719ppm (target: -200ppm) [11:22:38.3754973.4115600586][statime][DEBUG] Interclock measurement: 1706354558375473503 1706354558374673510 1706354558375479154 [11:22:38.3755729.1984558105][statime::filters::kalman][INFO] New entry 5650.999999999964 [11:22:38.3755919.933319092][statime::filters::kalman][INFO] New uncertainty estimate: 151.9201811197235ns [11:22:38.3756296.6346740723][statime::filters::kalman][INFO] Wander uncertainty: 1399.1539689062454ns [11:22:38.3756492.1379089355][statime::filters::kalman][INFO] Wander uncertainty: 1511.9106204691338ns [11:22:38.3756644.7257995605][statime::filters::kalman][INFO] wander score: 15 [11:22:38.3756892.681121826][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:38.3757309.913635254][statime::filters::kalman][INFO] Estimated offset 802818.5000326058ns+-707106.7365342146ns, freq 0+-100, delay 2825.4999673940724+-707106.7365342146 [11:22:38.3757946.491241455][statime::filters::kalman][INFO] Steered frequency by -1991271014951.3438ppm (target: -200ppm) [11:22:38.4410362.243652344][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:38.4428763.389587402][statime::port::state::slave][DEBUG] Received DelayResp [11:22:38.4428994.655609131][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354558440273095 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -152074 }) } [11:22:38.4429497.718811035][statime::filters::kalman][INFO] Wander uncertainty: 103885484.97051097ns [11:22:38.4429628.849029541][statime::filters::kalman][INFO] wander score: 0 [11:22:38.4430081.844329834][statime::filters::kalman][INFO] Estimated offset -0.16313877969755358ns+-1470154.9236677976ns, freq 0.00014954060814970985+-99.99993468432888, delay 0.16385899049036842+-999998.4310919113 [11:22:38.4430720.806121826][statime::filters::kalman][INFO] Steered frequency by 0.00006797121830093307ppm (target: 0.00008156938984877679ppm) [11:22:38.4774174.690246582][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 522, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:38.6269428.730010986][statime][DEBUG] Interclock measurement: 1706354558626919191 1706354558626007949 1706354558626924990 [11:22:38.6270115.375518799][statime::filters::kalman][INFO] New entry 5798.999999999908 [11:22:38.6270251.274108887][statime::filters::kalman][INFO] New uncertainty estimate: 146.1741049283709ns [11:22:38.6270594.596862793][statime::filters::kalman][INFO] Wander uncertainty: 1629.1427289858984ns [11:22:38.6270685.195922852][statime::filters::kalman][INFO] Wander update predict: 1930730858694075.3ns, actual: 917041ns [11:22:38.6270799.63684082][statime::filters::kalman][INFO] p: 1 [11:22:38.6270844.93637085][statime::filters::kalman][INFO] Wander update [11:22:38.6270959.377288818][statime::filters::kalman][INFO] Wander uncertainty: 154.5600015667925ns [11:22:38.6271035.671234131][statime::filters::kalman][INFO] wander score: 16 [11:22:38.6271228.790283203][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:38.6271591.1865234375][statime::filters::kalman][INFO] Estimated offset 914141.5000309766ns+-707106.7362314187ns, freq 0+-100, delay 2899.499969023332+-707106.7362314187 [11:22:38.6272056.102752686][statime::filters::kalman][INFO] Steered frequency by -3982542029902.6875ppm (target: -200ppm) [11:22:38.8787345.886230469][statime][DEBUG] Interclock measurement: 1706354558878709036 1706354558877686188 1706354558878714816 [11:22:38.8788063.526153564][statime::filters::kalman][INFO] New entry 5779.9999999999345 [11:22:38.8788201.808929443][statime::filters::kalman][INFO] New uncertainty estimate: 144.49109108600152ns [11:22:38.8788549.900054932][statime::filters::kalman][INFO] Wander uncertainty: 1415108.541777465ns [11:22:38.8788642.883300781][statime::filters::kalman][INFO] Wander update predict: 2003278266474696ns, actual: 1028628ns [11:22:38.8788709.64050293][statime::filters::kalman][INFO] p: 1 [11:22:38.8788759.708404541][statime::filters::kalman][INFO] Wander update [11:22:38.8788883.686065674][statime::filters::kalman][INFO] Wander uncertainty: 148.30404013117314ns [11:22:38.8788971.900939941][statime::filters::kalman][INFO] wander score: 17 [11:22:38.8789021.968841553][statime::filters::kalman][INFO] Updated wander estimate: 1.6e-15 [11:22:38.8789234.161376953][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:38.8789608.478546143][statime::filters::kalman][INFO] Estimated offset 1025738.0000301681ns+-707106.7361449406ns, freq 0+-100, delay 2889.9999698317224+-707106.7361449406 [11:22:38.8779768.943786621][statime::filters::kalman][INFO] Stepped clock by -0.0010257380000301681s [11:22:38.9273772.239685059][statime][ERROR] Missing recv timestamp [11:22:38.9275102.615356445][statime::port::state::slave][DEBUG] Received FollowUp 1044 [11:22:39.1291248.7983703613][statime][DEBUG] Interclock measurement: 1706354559129100517 1706354559128973466 1706354559129106204 [11:22:39.1292564.868927002][statime::filters::kalman][INFO] New entry 5687.0000000000155 [11:22:39.1292843.8186645508][statime::filters::kalman][INFO] New uncertainty estimate: 136.4426427406872ns [11:22:39.1293480.396270752][statime::filters::kalman][INFO] Wander uncertainty: 1415108.4401292875ns [11:22:39.1293942.928314209][statime::filters::kalman][INFO] Wander update predict: 2003045657075699.5ns, actual: 132738ns [11:22:39.1294353.0082702637][statime::filters::kalman][INFO] p: 1 [11:22:39.1294724.941253662][statime::filters::kalman][INFO] Wander update [11:22:39.1295177.936553955][statime::filters::kalman][INFO] Wander uncertainty: 144.491090672415ns [11:22:39.1295740.6044006348][statime::filters::kalman][INFO] wander score: 1 [11:22:39.1296751.4991760254][statime::filters::kalman][INFO] Estimated offset 129892.5866278968ns+-96.47880765233843ns, freq 516.8019403328544+-0.7905065265748794, delay 2845.413372900814+-96.47880675424307 [11:22:39.1297659.8739624023][statime::filters::kalman][INFO] Steered frequency by -7965084059805.375ppm (target: -64.9462933139484ppm) [11:22:39.3824315.071105957][statime][DEBUG] Interclock measurement: 1706354559382406410 1706354559382173305 1706354559382412024 [11:22:39.3825285.4347229004][statime::filters::kalman][INFO] New entry 5614.000000000005 [11:22:39.3825519.08493042][statime::filters::kalman][INFO] New uncertainty estimate: 120.50294468359671ns [11:22:39.3825969.696044922][statime::filters::kalman][INFO] Wander uncertainty: 1415113.8391510632ns [11:22:39.3826146.125793457][statime::filters::kalman][INFO] Wander update predict: 2012651379457691ns, actual: 238719ns [11:22:39.3826291.561126709][statime::filters::kalman][INFO] p: 1 [11:22:39.3826406.0020446777][statime::filters::kalman][INFO] Wander update [11:22:39.3826608.657836914][statime::filters::kalman][INFO] Wander uncertainty: 136.77842034470683ns [11:22:39.3826761.245727539][statime::filters::kalman][INFO] wander score: 2 [11:22:39.3827042.579650879][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:39.3827507.495880127][statime::filters::kalman][INFO] Estimated offset 235912.00002038016ns+-707106.7350212215ns, freq 0+-100, delay 2806.9999796198326+-707106.7350212215 [11:22:39.3828096.389770508][statime::filters::kalman][INFO] Steered frequency by -15930168119610.75ppm (target: -117.95600001019008ppm) [11:22:39.6333324.909210205][statime][DEBUG] Interclock measurement: 1706354559633308580 1706354559632970684 1706354559633314360 [11:22:39.6334145.069122314][statime::filters::kalman][INFO] New entry 5779.999999999989 [11:22:39.6334340.572357178][statime::filters::kalman][INFO] New uncertainty estimate: 120.7530951149381ns [11:22:39.6334743.499755859][statime::filters::kalman][INFO] Wander uncertainty: 421.36792887338197ns [11:22:39.6334931.85043335][statime::filters::kalman][INFO] Wander uncertainty: 502.21065308591255ns [11:22:39.6335062.9806518555][statime::filters::kalman][INFO] wander score: 2 [11:22:39.6335313.320159912][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:39.6335711.479187012][statime::filters::kalman][INFO] Estimated offset 340786.00002107ns+-707106.73503189ns, freq 0+-100, delay 2889.9999789299986+-707106.73503189 [11:22:39.6336228.847503662][statime::filters::kalman][INFO] Steered frequency by -31860336239221.5ppm (target: -170.393000010535ppm) [11:22:39.6347775.459289551][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:39.6368451.118469238][statime::port::state::slave][DEBUG] Received DelayResp [11:22:39.6368677.616119385][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354559634505484 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -359001 }) } [11:22:39.6369175.910949707][statime::filters::kalman][INFO] Wander uncertainty: 104004897.56960514ns [11:22:39.6369309.425354004][statime::filters::kalman][INFO] wander score: 0 [11:22:39.6369764.804840088][statime::filters::kalman][INFO] Estimated offset -0.28395728708573587ns+-1559811.4859233075ns, freq 0.00007082554637686655+-99.99991736881891, delay 0.25360836321942254+-999998.3060938839 [11:22:39.6370368.003845215][statime::filters::kalman][INFO] Steered frequency by -0.00007115309716600139ppm (target: 0.00014197864354286794ppm) [11:22:39.8844983.577728271][statime][DEBUG] Interclock measurement: 1706354559884474573 1706354559884031403 1706354559884480186 [11:22:39.8845784.664154053][statime::filters::kalman][INFO] New entry 5613.0000000000155 [11:22:39.8845996.856689453][statime::filters::kalman][INFO] New uncertainty estimate: 121.33909264216621ns [11:22:39.8846433.162689209][statime::filters::kalman][INFO] Wander uncertainty: 612.7059622216642ns [11:22:39.8846635.818481445][statime::filters::kalman][INFO] Wander uncertainty: 698.0450263913363ns [11:22:39.8846790.790557861][statime::filters::kalman][INFO] wander score: 2 [11:22:39.8847076.892852783][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:39.8847668.170928955][statime::filters::kalman][INFO] Estimated offset 445976.5000206603ns+-707106.7350569684ns, freq 0+-100, delay 2806.4999793397096+-707106.7350569684 [11:22:39.8848233.222961426][statime::filters::kalman][INFO] Steered frequency by -63720672478443ppm (target: -200ppm) [11:22:39.9287011.623382568][statime][ERROR] Missing recv timestamp [11:22:39.9287853.240966797][statime::port::state::slave][DEBUG] Received FollowUp 1045 [11:22:40.1362488.2698059082][statime][DEBUG] Interclock measurement: 1706354560136223154 1706354560135673581 1706354560136229416 [11:22:40.1363332.2715759277][statime::filters::kalman][INFO] New entry 6261.9999999999345 [11:22:40.1363542.079925537][statime::filters::kalman][INFO] New uncertainty estimate: 135.61425369941415ns [11:22:40.1363987.922668457][statime::filters::kalman][INFO] Wander uncertainty: 808.0817705226145ns [11:22:40.1364212.0361328125][statime::filters::kalman][INFO] Wander uncertainty: 895.6195604718597ns [11:22:40.1364378.9291381836][statime::filters::kalman][INFO] wander score: 2 [11:22:40.1364653.1105041504][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:40.1365101.3374328613][statime::filters::kalman][INFO] Estimated offset 552704.0000287914ns+-707106.7357053943ns, freq 0+-100, delay 3130.9999712084996+-707106.7357053943 [11:22:40.1365671.157836914][statime::filters::kalman][INFO] Steered frequency by -127441344956886ppm (target: -200ppm) [11:22:40.3873674.8695373535][statime][DEBUG] Interclock measurement: 1706354560387344719 1706354560386685820 1706354560387350499 [11:22:40.3874411.5829467773][statime::filters::kalman][INFO] New entry 5780.000000000043 [11:22:40.3874614.2387390137][statime::filters::kalman][INFO] New uncertainty estimate: 130.33503469964876ns [11:22:40.3874986.171722412][statime::filters::kalman][INFO] Wander uncertainty: 1004.4941486956487ns [11:22:40.3875188.8275146484][statime::filters::kalman][INFO] Wander uncertainty: 1093.3132194165335ns [11:22:40.3875336.6470336914][statime::filters::kalman][INFO] wander score: 2 [11:22:40.3875594.139099121][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:40.3875992.2981262207][statime::filters::kalman][INFO] Estimated offset 661789.0000245465ns+-707106.7354571989ns, freq 0+-100, delay 2889.9999754534833+-707106.7354571989 [11:22:40.3876497.745513916][statime::filters::kalman][INFO] Steered frequency by -254882689913772ppm (target: -200ppm) [11:22:40.4782879.35256958][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 523, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:40.5137014.389038086][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:40.5156166.553497314][statime::port::state::slave][DEBUG] Received DelayResp [11:22:40.5156466.960906982][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354560513083629 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -252242 }) } [11:22:40.5157189.36920166][statime::filters::kalman][INFO] Wander uncertainty: 104092747.5730619ns [11:22:40.5157351.493835449][statime::filters::kalman][INFO] wander score: 0 [11:22:40.5157892.70401001][statime::filters::kalman][INFO] Estimated offset -0.3265489113662276ns+-1628212.4142350869ns, freq 0.0001338757637531907+-99.9998971696998, delay 0.316668114771565+-999998.1810961082 [11:22:40.5158479.2137146][statime::filters::kalman][INFO] Steered frequency by -0.000029398691929923113ppm (target: 0.0001632744556831138ppm) [11:22:40.6392052.173614502][statime][DEBUG] Interclock measurement: 1706354560639182324 1706354560638414219 1706354560639188141 [11:22:40.6392750.7400512695][statime::filters::kalman][INFO] New entry 5816.9999999999745 [11:22:40.6392946.243286133][statime::filters::kalman][INFO] New uncertainty estimate: 129.3630000668182ns [11:22:40.6393320.560455322][statime::filters::kalman][INFO] Wander uncertainty: 1202.266100672149ns [11:22:40.6393501.758575439][statime::filters::kalman][INFO] Wander uncertainty: 1291.921902457953ns [11:22:40.6393640.041351318][statime::filters::kalman][INFO] Wander update predict: 240325653457031330ns, actual: 768105ns [11:22:40.6393759.250640869][statime::filters::kalman][INFO] p: 1 [11:22:40.6393857.002258301][statime::filters::kalman][INFO] Wander update [11:22:40.6393995.28503418][statime::filters::kalman][INFO] wander score: 3 [11:22:40.6394240.856170654][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:40.6394643.783569336][statime::filters::kalman][INFO] Estimated offset 771013.5000243366ns+-707106.7354125743ns, freq 0+-100, delay 2908.4999756634224+-707106.7354125743 [11:22:40.6395149.230957031][statime::filters::kalman][INFO] Steered frequency by -509765379827544ppm (target: -200ppm) [11:22:40.8910572.528839111][statime][DEBUG] Interclock measurement: 1706354560891033712 1706354560890156417 1706354560891039529 [11:22:40.8911335.468292236][statime::filters::kalman][INFO] New entry 5816.9999999999745 [11:22:40.8911519.050598145][statime::filters::kalman][INFO] New uncertainty estimate: 128.75863383201803ns [11:22:40.8911890.983581543][statime::filters::kalman][INFO] Wander uncertainty: 1415110.1549348927ns [11:22:40.8912038.803100586][statime::filters::kalman][INFO] Wander update predict: 256545398917976800ns, actual: 883112ns [11:22:40.8912155.628204346][statime::filters::kalman][INFO] p: 1 [11:22:40.8912250.995635986][statime::filters::kalman][INFO] Wander update [11:22:40.8912420.272827148][statime::filters::kalman][INFO] Wander uncertainty: 132.75944823472318ns [11:22:40.8912553.787231445][statime::filters::kalman][INFO] wander score: 4 [11:22:40.8912799.35836792][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:40.8913202.285766602][statime::filters::kalman][INFO] Estimated offset 880203.5000241097ns+-707106.7353849971ns, freq 0+-100, delay 2908.499975890285+-707106.7353849971 [11:22:40.8913717.269897461][statime::filters::kalman][INFO] Steered frequency by -1019530759655088ppm (target: -200ppm) [11:22:40.9299666.88156128][statime][ERROR] Missing recv timestamp [11:22:40.9300575.256347656][statime::port::state::slave][DEBUG] Received FollowUp 1046 [11:22:41.1425879.0016174316][statime][DEBUG] Interclock measurement: 1706354561142563835 1706354561141576596 1706354561142569523 [11:22:41.1426706.314086914][statime::filters::kalman][INFO] New entry 5688.000000000004 [11:22:41.1426913.7382507324][statime::filters::kalman][INFO] New uncertainty estimate: 128.86526315646347ns [11:22:41.1427335.7391357422][statime::filters::kalman][INFO] Wander uncertainty: 1415109.060533314ns [11:22:41.1427495.4795837402][statime::filters::kalman][INFO] Wander update predict: 512588679700916160ns, actual: 992927ns [11:22:41.1427631.3781738281][statime::filters::kalman][INFO] p: 1 [11:22:41.1427733.8981628418][statime::filters::kalman][INFO] Wander update [11:22:41.1427907.943725586][statime::filters::kalman][INFO] Wander uncertainty: 132.2615341696979ns [11:22:41.1428050.9948730469][statime::filters::kalman][INFO] wander score: 5 [11:22:41.1428298.9501953125][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:41.1428720.9510803223][statime::filters::kalman][INFO] Estimated offset 990083.000023614ns+-707106.735389853ns, freq 0+-100, delay 2843.999976385903+-707106.735389853 [11:22:41.1429264.5454406738][statime::filters::kalman][INFO] Steered frequency by -2039061519310176ppm (target: -200ppm) [11:22:41.3783681.3926696777][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:41.3804059.0286254883][statime::port::state::slave][DEBUG] Received DelayResp [11:22:41.3804366.5885925293][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354561377476774 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -251055 }) } [11:22:41.3805088.996887207][statime::filters::kalman][INFO] Wander uncertainty: 104179179.21624044ns [11:22:41.3805243.968963623][statime::filters::kalman][INFO] wander score: 0 [11:22:41.3805773.2582092285][statime::filters::kalman][INFO] Estimated offset -0.366276398464923ns+-1697257.8870670272ns, freq 0.00015466719433531505+-99.99987409339897, delay 0.37943102311664517+-999998.056098604 [11:22:41.3806347.8469848633][statime::filters::kalman][INFO] Steered frequency by -0.00002847100489714643ppm (target: 0.00018313819923246148ppm) [11:22:41.3938157.558441162][statime][DEBUG] Interclock measurement: 1706354561393798206 1706354561392698395 1706354561393803578 [11:22:41.3938663.0058288574][statime::filters::kalman][INFO] New entry 5372.0000000000155 [11:22:41.3938858.5090637207][statime::filters::kalman][INFO] New uncertainty estimate: 132.94772195938933ns [11:22:41.3939189.910888672][statime::filters::kalman][INFO] Wander uncertainty: 1415106.8664674738ns [11:22:41.3939354.419708252][statime::filters::kalman][INFO] Wander update predict: 1023891856515525900ns, actual: 1105183ns [11:22:41.3939499.855041504][statime::filters::kalman][INFO] p: 1 [11:22:41.3939611.9117736816][statime::filters::kalman][INFO] Wander update [11:22:41.3939793.109893799][statime::filters::kalman][INFO] Wander uncertainty: 132.93424816653743ns [11:22:41.3939945.697784424][statime::filters::kalman][INFO] wander score: 6 [11:22:41.3940207.9582214355][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:41.3940610.885620117][statime::filters::kalman][INFO] Estimated offset 1102497.0000237378ns+-707106.7355787993ns, freq 0+-100, delay 2685.9999762623497+-707106.7355787993 [11:22:41.3929994.1062927246][statime::filters::kalman][INFO] Stepped clock by -0.0011024970000237378s [11:22:41.6435194.01550293][statime][DEBUG] Interclock measurement: 1706354561643494139 1706354561643362814 1706354561643499809 [11:22:41.6436066.627502441][statime::filters::kalman][INFO] New entry 5669.999999999992 [11:22:41.6436285.972595215][statime::filters::kalman][INFO] New uncertainty estimate: 132.94041041674203ns [11:22:41.6436700.820922852][statime::filters::kalman][INFO] Wander uncertainty: 1415104.269529135ns [11:22:41.6436865.329742432][statime::filters::kalman][INFO] Wander update predict: 1023010232792479700ns, actual: 136995ns [11:22:41.6437008.380889893][statime::filters::kalman][INFO] p: 1 [11:22:41.6437115.669250488][statime::filters::kalman][INFO] Wander update [11:22:41.6437301.6357421875][statime::filters::kalman][INFO] Wander uncertainty: 132.94772069477727ns [11:22:41.6437468.528747559][statime::filters::kalman][INFO] wander score: 7 [11:22:41.6438217.1630859375][statime::filters::kalman][INFO] Estimated offset 134158.11743523015ns+-94.00240533638045ns, freq 534.3071347269702+-0.749719261926532, delay 2836.8825620763564+-94.0024045057149 [11:22:41.6438808.441162109][statime::filters::kalman][INFO] Steered frequency by -4078123038620352ppm (target: -67.07905871761508ppm) [11:22:41.7692921.161651611][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:41.7719783.782958984][statime::port::state::slave][DEBUG] Received DelayResp [11:22:41.7720079.42199707][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354561769188183 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -263890 }) } [11:22:41.7720782.75680542][statime::filters::kalman][INFO] Wander uncertainty: 104218346.8852133ns [11:22:41.7720935.344696045][statime::filters::kalman][INFO] wander score: 0 [11:22:41.7721495.628356934][statime::filters::kalman][INFO] Estimated offset -0.49183059187155714ns+-1729061.456983353ns, freq 0.000173832491850575+-99.9998494186605, delay 0.44540252897134436+-999997.9311013573 [11:22:41.7722222.805023193][statime::filters::kalman][INFO] Steered frequency by -0.00007208280408520356ppm (target: 0.0002459152959357786ppm) [11:22:41.8946456.909179688][statime][DEBUG] Interclock measurement: 1706354561894623381 1706354561894356272 1706354561894628865 [11:22:41.8947227.001190186][statime::filters::kalman][INFO] New entry 5483.99999999999 [11:22:41.8947420.120239258][statime::filters::kalman][INFO] New uncertainty estimate: 136.3564765959986ns [11:22:41.8947834.968566895][statime::filters::kalman][INFO] Wander uncertainty: 1415103.8968353001ns [11:22:41.8947987.55645752][statime::filters::kalman][INFO] Wander update predict: 1022717262263162100ns, actual: 272593ns [11:22:41.8948118.686676025][statime::filters::kalman][INFO] p: 1 [11:22:41.8948366.641998291][statime::filters::kalman][INFO] Wander update [11:22:41.8948574.06616211][statime::filters::kalman][INFO] Wander uncertainty: 133.1230118484065ns [11:22:41.8948726.654052734][statime::filters::kalman][INFO] wander score: 8 [11:22:41.8949005.603790283][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:41.8949420.45211792][statime::filters::kalman][INFO] Estimated offset 269851.0000254912ns+-707106.7357410789ns, freq 0+-100, delay 2741.9999745088676+-707106.7357410789 [11:22:41.8949964.046478271][statime::filters::kalman][INFO] Steered frequency by -8156246077240704ppm (target: -134.92550001274557ppm) [11:22:41.9309580.326080322][statime][ERROR] Missing recv timestamp [11:22:41.9310007.095336914][statime::port::state::slave][DEBUG] Received FollowUp 1047 [11:22:42.1454839.7064208984][statime][DEBUG] Interclock measurement: 1706354562145460436 1706354562145073071 1706354562145466087 [11:22:42.1455612.1826171875][statime::filters::kalman][INFO] New entry 5651.000000000017 [11:22:42.1455800.5332946777][statime::filters::kalman][INFO] New uncertainty estimate: 131.38301055961404ns [11:22:42.1456210.6132507324][statime::filters::kalman][INFO] Wander uncertainty: 399.2090267811239ns [11:22:42.1456398.9639282227][statime::filters::kalman][INFO] Wander uncertainty: 479.6957445706434ns [11:22:42.1456527.7099609375][statime::filters::kalman][INFO] wander score: 8 [11:22:42.1456770.896911621][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:42.1457166.6717529297][statime::filters::kalman][INFO] Estimated offset 390190.50002438616ns+-707106.7355056843ns, freq 0+-100, delay 2825.4999756138277+-707106.7355056843 [11:22:42.1457672.119140625][statime::filters::kalman][INFO] Steered frequency by -16312492154481408ppm (target: -195.09525001219308ppm) [11:22:42.3963780.403137207][statime][DEBUG] Interclock measurement: 1706354562396354720 1706354562395858870 1706354562396360537 [11:22:42.3964564.800262451][statime::filters::kalman][INFO] New entry 5816.9999999999745 [11:22:42.3964776.9927978516][statime::filters::kalman][INFO] New uncertainty estimate: 129.8110832660578ns [11:22:42.3965179.920196533][statime::filters::kalman][INFO] Wander uncertainty: 580.0748217240043ns [11:22:42.3965380.1918029785][statime::filters::kalman][INFO] Wander uncertainty: 665.2704535949716ns [11:22:42.3965528.0113220215][statime::filters::kalman][INFO] wander score: 8 [11:22:42.3965792.655944824][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:42.3966221.809387207][statime::filters::kalman][INFO] Estimated offset 498758.5000245055ns+-707106.7354331036ns, freq 0+-100, delay 2908.4999754945375+-707106.7354331036 [11:22:42.3966770.1721191406][statime::filters::kalman][INFO] Steered frequency by -32624984308962816ppm (target: -200ppm) [11:22:42.4791939.258575439][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 524, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:42.6478455.066680908][statime][DEBUG] Interclock measurement: 1706354562647820802 1706354562647216048 1706354562647826564 [11:22:42.6479249.000549316][statime::filters::kalman][INFO] New entry 5761.999999999976 [11:22:42.6479463.577270508][statime::filters::kalman][INFO] New uncertainty estimate: 129.701003474981ns [11:22:42.6479849.815368652][statime::filters::kalman][INFO] Wander uncertainty: 764.9621321923275ns [11:22:42.6480035.781860352][statime::filters::kalman][INFO] Wander uncertainty: 852.4690169823044ns [11:22:42.6480183.6013793945][statime::filters::kalman][INFO] wander score: 8 [11:22:42.6480438.709259033][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:42.6480863.094329834][statime::filters::kalman][INFO] Estimated offset 607635.0000242325ns+-707106.7354280537ns, freq 0+-100, delay 2880.999975767389+-707106.7354280537 [11:22:42.6481413.841247559][statime::filters::kalman][INFO] Steered frequency by -65249968617925630ppm (target: -200ppm) [11:22:42.8996481.895446777][statime][DEBUG] Interclock measurement: 1706354562899623758 1706354562898909947 1706354562899629501 [11:22:42.8997304.439544678][statime::filters::kalman][INFO] New entry 5743.000000000003 [11:22:42.8997516.632080078][statime::filters::kalman][INFO] New uncertainty estimate: 123.94337286606704ns [11:22:42.8997955.322265625][statime::filters::kalman][INFO] Wander uncertainty: 951.6372157824065ns [11:22:42.8998153.20968628][statime::filters::kalman][INFO] Wander uncertainty: 1040.4977715025755ns [11:22:42.8998315.334320068][statime::filters::kalman][INFO] wander score: 8 [11:22:42.8998746.871948242][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:42.8999195.098876953][statime::filters::kalman][INFO] Estimated offset 716682.5000220559ns+-707106.7351698906ns, freq 0+-100, delay 2871.4999779440645+-707106.7351698906 [11:22:42.8999767.303466797][statime::filters::kalman][INFO] Steered frequency by -130499937235851260ppm (target: -200ppm) [11:22:42.9332075.119018555][statime][ERROR] Missing recv timestamp [11:22:42.9332950.115203857][statime::port::state::slave][DEBUG] Received FollowUp 1048 [11:22:43.1507501.6021728516][statime][DEBUG] Interclock measurement: 1706354563150724307 1706354563149900286 1706354563150730550 [11:22:43.1508386.1351013184][statime::filters::kalman][INFO] New entry 6243.000000000069 [11:22:43.1508593.5592651367][statime::filters::kalman][INFO] New uncertainty estimate: 139.98696475893098ns [11:22:43.1509017.9443359375][statime::filters::kalman][INFO] Wander uncertainty: 1138.5951778240337ns [11:22:43.1509222.9843139648][statime::filters::kalman][INFO] Wander uncertainty: 1228.3355039243656ns [11:22:43.1509366.0354614258][statime::filters::kalman][INFO] wander score: 8 [11:22:43.1509642.6010131836][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:43.1510093.2121276855][statime::filters::kalman][INFO] Estimated offset 827142.500030585ns+-707106.7359184322ns, freq 0+-100, delay 3121.4999694150265+-707106.7359184322 [11:22:43.1510679.7218322754][statime::filters::kalman][INFO] Steered frequency by -260999874471702530ppm (target: -200ppm) [11:22:43.4026024.341583252][statime][DEBUG] Interclock measurement: 1706354563402577220 1706354563401640265 1706354563402582926 [11:22:43.4026868.3433532715][statime::filters::kalman][INFO] New entry 5706.00000000007 [11:22:43.4027082.920074463][statime::filters::kalman][INFO] New uncertainty estimate: 139.40722540803367ns [11:22:43.4027521.6102600098][statime::filters::kalman][INFO] Wander uncertainty: 1326.596702774983ns [11:22:43.4027729.034423828][statime::filters::kalman][INFO] Wander uncertainty: 1416.9547655655772ns [11:22:43.4027879.238128662][statime::filters::kalman][INFO] Wander update predict: 253267493467057420000ns, actual: 936955ns [11:22:43.4028012.752532959][statime::filters::kalman][INFO] p: 1 [11:22:43.4028131.9618225098][statime::filters::kalman][INFO] Wander update [11:22:43.4028277.3971557617][statime::filters::kalman][INFO] wander score: 9 [11:22:43.4028553.9627075195][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:43.4029002.1896362305][statime::filters::kalman][INFO] Estimated offset 939808.0000277231ns+-707106.7358897985ns, freq 0+-100, delay 2852.9999722768966+-707106.7358897985 [11:22:43.4029562.473297119][statime::filters::kalman][INFO] Steered frequency by -521999748943405060ppm (target: -200ppm) [11:22:43.6534438.133239746][statime][DEBUG] Interclock measurement: 1706354563653419333 1706354563652370383 1706354563653425021 [11:22:43.6535265.4457092285][statime::filters::kalman][INFO] New entry 5688.000000000004 [11:22:43.6535475.254058838][statime::filters::kalman][INFO] New uncertainty estimate: 133.26119604358553ns [11:22:43.6535904.407501221][statime::filters::kalman][INFO] Wander uncertainty: 1415106.619480705ns [11:22:43.6536078.453063965][statime::filters::kalman][INFO] Wander update predict: 261885072771965800000ns, actual: 1054638ns [11:22:43.6536216.735839844][statime::filters::kalman][INFO] p: 1 [11:22:43.6536467.0753479][statime::filters::kalman][INFO] Wander update [11:22:43.6536681.652069092][statime::filters::kalman][INFO] Wander uncertainty: 143.53060192117945ns [11:22:43.6536834.239959717][statime::filters::kalman][INFO] wander score: 10 [11:22:43.6537120.342254639][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:43.6537573.337554932][statime::filters::kalman][INFO] Estimated offset 1051794.0000252528ns+-707106.7355935512ns, freq 0+-100, delay 2843.9999747473457+-707106.7355935512 [11:22:43.6527521.61026001][statime::filters::kalman][INFO] Stepped clock by -0.0010517940000252528s [11:22:43.6990458.965301514][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:43.7010500.431060791][statime::port::state::slave][DEBUG] Received DelayResp [11:22:43.7010765.075683594][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354563699107307 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -504298 }) } [11:22:43.7011413.57421875][statime::filters::kalman][INFO] Wander uncertainty: 104411321.73208007ns [11:22:43.7011547.088623047][statime::filters::kalman][INFO] wander score: 0 [11:22:43.7012038.230895996][statime::filters::kalman][INFO] Estimated offset -0.4676892412376123ns+-1889800.4182916149ns, freq 0.0002256988083236677+-99.99981824191545, delay 0.5714751158677488+-999997.8061045122 [11:22:43.7012603.282928467][statime::filters::kalman][INFO] Steered frequency by -0.000008145812295138471ppm (target: 0.00023384462061880616ppm) [11:22:43.9037799.835205078][statime][DEBUG] Interclock measurement: 1706354563903756475 1706354563903624902 1706354563903762218 [11:22:43.9038522.243499756][statime::filters::kalman][INFO] New entry 5743.000000000003 [11:22:43.9038710.594177246][statime::filters::kalman][INFO] New uncertainty estimate: 130.53901128682318ns [11:22:43.9039096.83227539][statime::filters::kalman][INFO] Wander uncertainty: 1415104.9730844065ns [11:22:43.9039242.267608643][statime::filters::kalman][INFO] Wander update predict: 261986194844732650000ns, actual: 137316ns [11:22:43.9039478.302001953][statime::filters::kalman][INFO] p: 1 [11:22:43.9039599.895477295][statime::filters::kalman][INFO] Wander update [11:22:43.9039778.709411621][statime::filters::kalman][INFO] Wander uncertainty: 133.26119511658297ns [11:22:43.9039921.760559082][statime::filters::kalman][INFO] wander score: 11 [11:22:43.9040617.942810059][statime::filters::kalman][INFO] Estimated offset 134442.6878735235ns+-92.30439812501243ns, freq 534.6678618448527+-0.7421271317291173, delay 2873.312125948539+-92.30439733871582 [11:22:43.9041144.847869873][statime::filters::kalman][INFO] Steered frequency by -1043999497886810100ppm (target: -67.22134393676176ppm) [11:22:43.9344015.121459961][statime][ERROR] Missing recv timestamp [11:22:43.9344630.241394043][statime::port::state::slave][DEBUG] Received FollowUp 1049 [11:22:44.1559653.2821655273][statime][DEBUG] Interclock measurement: 1706354564155942442 1706354564155694581 1706354564155948611 [11:22:44.1560425.7583618164][statime::filters::kalman][INFO] New entry 6168.999999999988 [11:22:44.1560635.5667114258][statime::filters::kalman][INFO] New uncertainty estimate: 141.1363373685383ns [11:22:44.1561028.9573669434][statime::filters::kalman][INFO] Wander uncertainty: 1415109.7496832716ns [11:22:44.1561195.8503723145][statime::filters::kalman][INFO] Wander update predict: 262944923314228230000ns, actual: 254029.99999999997ns [11:22:44.1561329.3647766113][statime::filters::kalman][INFO] p: 1 [11:22:44.1561579.704284668][statime::filters::kalman][INFO] Wander update [11:22:44.1561756.1340332031][statime::filters::kalman][INFO] Wander uncertainty: 130.7051357855701ns [11:22:44.1561906.337738037][statime::filters::kalman][INFO] wander score: 12 [11:22:44.1562168.5981750488][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:44.1562592.9832458496][statime::filters::kalman][INFO] Estimated offset 250945.5000307208ns+-707106.7359755515ns, freq 0+-100, delay 3084.4999692791935+-707106.7359755515 [11:22:44.1563146.1143493652][statime::filters::kalman][INFO] Steered frequency by -2087998995773620200ppm (target: -125.4727500153604ppm) [11:22:44.4082386.4936828613][statime][DEBUG] Interclock measurement: 1706354564408213981 1706354564407861640 1706354564408219612 [11:22:44.4083254.337310791][statime::filters::kalman][INFO] New entry 5631.000000000028 [11:22:44.4083461.7614746094][statime::filters::kalman][INFO] New uncertainty estimate: 138.93140567873814ns [11:22:44.4083905.2200317383][statime::filters::kalman][INFO] Wander uncertainty: 396.5640946509305ns [11:22:44.4084131.7176818848][statime::filters::kalman][INFO] Wander uncertainty: 475.0245059607285ns [11:22:44.4084291.458129883][statime::filters::kalman][INFO] wander score: 12 [11:22:44.4084591.865539551][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:44.4085271.3584899902][statime::filters::kalman][INFO] Estimated offset 355156.5000271723ns+-707106.7358663864ns, freq 0+-100, delay 2815.4999728277107+-707106.7358663864 [11:22:44.4085917.4728393555][statime::filters::kalman][INFO] Steered frequency by -4175997991547240400ppm (target: -177.57825001358614ppm) [11:22:44.4801800.25100708][statime::ptp_instance][DEBUG] Recommended state port 0: Some(S1(AnnounceMessage { header: Header { sdo_id: SdoId(0), version: PtpVersion { major: 2, minor: 1 }, domain_number: 0, alternate_master_flag: false, two_step_flag: false, unicast_flag: false, ptp_profile_specific_1: false, ptp_profile_specific_2: false, leap61: false, leap59: false, current_utc_offset_valid: false, ptp_timescale: true, time_tracable: false, frequency_tracable: false, synchronization_uncertain: false, correction_field: TimeInterval(0), source_port_identity: PortIdentity { clock_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), port_number: 0 }, sequence_id: 525, log_message_interval: 0 }, origin_timestamp: WireTimestamp { seconds: 0, nanos: 0 }, current_utc_offset: 0, grandmaster_priority_1: 100, grandmaster_clock_quality: ClockQuality { clock_class: 248, clock_accuracy: Unknown, offset_scaled_log_variance: 26880 }, grandmaster_priority_2: 128, grandmaster_identity: ClockIdentity([248, 228, 59, 166, 102, 95, 0, 0]), steps_removed: 0, time_source: InternalOscillator })) [11:22:44.6598136.425018311][statime][DEBUG] Interclock measurement: 1706354564659787334 1706354564659331438 1706354564659792947 [11:22:44.6599109.172821045][statime::filters::kalman][INFO] New entry 5612.999999999961 [11:22:44.6599335.670471191][statime::filters::kalman][INFO] New uncertainty estimate: 139.21555685396862ns [11:22:44.6599853.038787842][statime::filters::kalman][INFO] Wander uncertainty: 576.2566332867854ns [11:22:44.6600065.231323242][statime::filters::kalman][INFO] Wander uncertainty: 659.2123270166775ns [11:22:44.6600210.666656494][statime::filters::kalman][INFO] wander score: 12 [11:22:44.6600489.616394043][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:44.6601927.280426025][statime::filters::kalman][INFO] Estimated offset 458702.50002719637ns+-707106.7358803583ns, freq 0+-100, delay 2806.499972803629+-707106.7358803583 [11:22:44.6603279.113769531][statime::filters::kalman][INFO] Steered frequency by -8351995983094481000ppm (target: -200ppm) [11:22:44.6995918.750762939][statime::port::state::slave][DEBUG] Starting new delay measurement [11:22:44.7015895.843505859][statime::port::state::slave][DEBUG] Received DelayResp [11:22:44.7016477.584838867][statime::port::state::slave][INFO] Measurement: Measurement { event_time: Time { inner: 1706354564699223701 }, offset: None, delay: None, raw_sync_offset: None, raw_delay_offset: Some(Duration { inner: -392981 }) } [11:22:44.7017824.649810791][statime::filters::kalman][INFO] Wander uncertainty: 104511324.5540909ns [11:22:44.7018306.255340576][statime::filters::kalman][INFO] wander score: 0 [11:22:44.7019293.308258057][statime::filters::kalman][INFO] Estimated offset -0.6171943099330895ns+-1975370.7080248771ns, freq 0.0002171081277720189+-99.99978246600912, delay 0.6697186090699667+-999997.681108035 [11:22:44.7020463.943481445][statime::filters::kalman][INFO] Steered frequency by -0.00009148902719452586ppm (target: 0.0003085971549665448ppm) [11:22:44.9115331.172943115][statime][DEBUG] Interclock measurement: 1706354564911508613 1706354564910949077 1706354564911514300 [11:22:44.9116642.475128174][statime::filters::kalman][INFO] New entry 5686.999999999988 [11:22:44.9117403.030395508][statime::filters::kalman][INFO] New uncertainty estimate: 135.55087538834857ns [11:22:44.9117887.020111084][statime::filters::kalman][INFO] Wander uncertainty: 759.5467516296607ns [11:22:44.9118511.67678833][statime::filters::kalman][INFO] Wander uncertainty: 844.7037922721564ns [11:22:44.9119119.644165039][statime::filters::kalman][INFO] wander score: 12 [11:22:44.9119937.419891357][statime::filters::kalman][INFO] Measurement too far from state, resetting [11:22:44.9121069.90814209][statime::filters::kalman][INFO] Estimated offset 562379.5000261232ns+-707106.7357023562ns, freq 0+-100, delay 2843.4999738766996+-707106.7357023562 [11:22:44.9122309.684753418][statime::filters::kalman][INFO] Steered frequency by -16703991966188962000ppm (target: -200ppm) [11:22:44.9354009.628295898][statime][ERROR] Missing recv timestamp [11:22:44.9354941.844940186][statime::port::state::slave][DEBUG] Received FollowUp 1050 ```

davidv1992 · 2024-01-31T10:38:45Z

Hmm, since it is a kernel bug, you should perhaps just try configuring statime without hardware timestamping. In that scenario only the system clock will be synchronized, not the PHC but that should usually be sufficient, espescially if you only need +-0.5ms. Software timestamping should also be plenty for that level of precision. This can be most easily enabled by simply removing the hardware-clock line from your configuration.

Not sure what you did with the SoftwareAll experiment, but if you modified the code to pass that timestamping mode to the network layer, now a different clock is used for timestamps vs adjustment and there is a large number of ways that could go sideways.

I am going to close the issue here as there seems to be no underlying bug in statime at the moment.

dsseng · 2024-01-31T14:14:44Z

My suggestion was to sync PHC, but use software timestamps. I don't want to sync the system clock because network clocks are frequently out of sync with the real astronomic time. Some of devices we use reset to 1970 and start counting from the epoch zero each time they reset. I certainly want to only have that time on the PHC I use for clocking audio streams.

Another option could be auto determining that offset and syncing the system clock with an offset. Let me illustrate: System time is 2024-01-20 14:00:00, PTP GM clock is 1970-01-20 14:00:00. When starting (well, if you approve the feature I'll of course put it behind a CLI flag) we determine the offset and start driving the system clock with an offset which could be somehow announced to the time consumers. This way we can sync to a clock not having the correct time without PHC and still have browsers working

teodly · 2024-02-02T07:47:35Z

@dsseng your use case looks similar to mine: #389

A general solution I can think of is to make clock synchronization configurable - add a configuration flag whether we want system TAI clock to be synchronized to the network. It could have these values:

on - synchronization working as it is now
off - clock_task would not be run. Packets' software timestamps would need to be shifted and scaled to account for TAI-NIC difference.
virtual - synchronize a virtual clock, implemented in Statime, phase locked to TAI, essentially emulating a /dev/ptp device for systems that don't have one. Timestamps from packets would need to be shifted and scaled to match that virtual clock.

davidv1992 · 2024-02-02T09:56:41Z

Apologies, I misunderstood at least part of your issue. Software timestamps for PHC clocks are really not a good option, as the kernel doesn't support this, it only does software timestamping with the system clock.

We could fall back to userspace timestamping, but that can be problematic depending on hardware, as taking timestamps from a PHC can take a significant amount of time (~ms is not unheard of) which combined with the user space jitter would pretty much destroy any precision.

I think allowing disabling of the internal synchronization mechanisms could be a useful feature, although that should come with a warning in the documentation that at that point the user is responsible for ensuring everything uses the same clock.

Virtual clocks are a nice idea in theory, but currently just not supported by linux in a fashion suitable for something like statime. Hardware clock virtualization is a thing, but that still has all the problems of hardware clocks and those being quite "far away" in terms of latency. If a similar mechanism were to be introduced for the system clocks that could be interesting, but right now there is just no good way of getting the time from the statime process to user processes. As also said in #389 this problem of course disappears when using statime as a library, since then this can be done internally in the using process.

I'm reopening this to keep the discussion more visible and to keep the allow disabling of the clock_task mechanism visible in the issue tracker.

dsseng · 2024-02-02T15:03:54Z

I see. Because SW is essentially "timestamped by kernel mode driver" we can't (yet) have it synced to arbitrary value.

Maybe with a bit of help from the kernel side (well I asked for some of that to allow me to expose PHCs to unprivileged processes already) we could be able to create kernel-virtualized clocks enabling separate clock for software timestamping and freely adjustable by the owner/creator process. We could propose an UAPI considering new SO_TIMESTAMPING options to select such a custom clock for timestamping and something to create/query/destroy virtual clocks from the userspace. These should behave similar to PHCs and use frequency adjustments over a stable CLOCK_MONOTONIC)RAW or something like this.

off - clock_task would not be run. Packets' software timestamps would need to be shifted and scaled to account for TAI-NIC difference.

This seems hard to implement due to the fact we can't (or can we) influence how kernel timestamps the packet because it uses CLOCK_REALTIME (perhaps) as a timestamp value before sending the socket buffer out to the NIC. Would be happy to be wrong on this one however, as this would open up a possibility for userspace-only vclocks which could be accessible using shared memory or sth like this with high enough precision.

@teowoz well, I'm quite close to what you do since I work on AES67 stack in PipeWire, mainly to interact with Dante and RAVENNA devices. Those use PTPv2 however. Also I'd strongly prefer not to have PTP implementation (requiring cap_net_bind_port) in the PipeWire process. Not sure what privilege model you use

teodly · 2024-02-05T19:31:31Z

Would be happy to be wrong on this one however, as this would open up a possibility for userspace-only vclocks which could be accessible using shared memory or sth like this with high enough precision.

That's what I'm thinking about.

Kernel is timestamping packets using CLOCK_REALTIME.

We can shift and scale the timestamps to make them correspond to our virtual clock.

Virtual clock state could be shared with other processes using SHM. It would consist of at least 2 values as in linear equation: y = ax + b, where: y = timestamp of our virtual clock, x = current CLOCK_TAI, a, b - factors computed by clock synchronization daemon. Or it could be a higher order polynomial for better smoothing. This way, PipeWire side running without elevated privileges, could have read access to our virtual clock. But that's off topic and belongs to #389 more.

Kernel-level virtual clock, exposing /dev/ptp API and making it possible to share a clock between userspace processes, could be probably done by writing a kernel module.

davidv1992 closed this as completed Jan 31, 2024

davidv1992 reopened this Feb 2, 2024

teodly mentioned this issue Aug 13, 2024

statime-linux: PHC-only mode #517

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use software timestamping with PHC and hardware timestamping available #380

Use software timestamping with PHC and hardware timestamping available #380

dsseng commented Jan 27, 2024

dsseng commented Jan 27, 2024

dsseng commented Jan 27, 2024 •

edited

Loading

dsseng commented Jan 27, 2024

davidv1992 commented Jan 31, 2024

dsseng commented Jan 31, 2024

teodly commented Feb 2, 2024

davidv1992 commented Feb 2, 2024

dsseng commented Feb 2, 2024

teodly commented Feb 5, 2024

Use software timestamping with PHC and hardware timestamping available #380

Use software timestamping with PHC and hardware timestamping available #380

Comments

dsseng commented Jan 27, 2024

dsseng commented Jan 27, 2024

dsseng commented Jan 27, 2024 • edited Loading

dsseng commented Jan 27, 2024

davidv1992 commented Jan 31, 2024

dsseng commented Jan 31, 2024

teodly commented Feb 2, 2024

davidv1992 commented Feb 2, 2024

dsseng commented Feb 2, 2024

teodly commented Feb 5, 2024

dsseng commented Jan 27, 2024 •

edited

Loading