Fuzzing Messages

Sun Dec 1 08:17:46 UTC 2019

On 11/30/19 6:17 AM, ASSI via devel wrote:
> ASSI via devel writes:
>> is… intriguing.  If you follow the code through the function, ts_min in
>> the log should always be ts_prev+sys_fuzz; these two values can't be
>> identical or differ by any other value, ts_min must strictly be greater
>> than ts_prev by sys_fuzz.  I notice that there is always a DNS operation
>> logged at the same time when I get these errors, so I am pretty sure
>> this is related to the DNS thread.

That was the case for me _at startup_, but not after that. (See the
attached logs.)

>>  This would also explain why a server
>> that has many clients would see many more such errors.

Why's that? What DNS lookups is ntpd doing for clients?

> While I have not yet identified the code path that is involved (likely
> something in NTS, I think), you might want to try the following monkey
> patch:
> 
> Let me know if makes a difference on your system.  The error crops up
> too sparingly on mine to really tell if it helps or not.

Attached is what I have right away, filtered for DNS|CLOCK.

-- 
Richard
-------------- next part --------------
2019-12-01T02:04:28.211306-06:00 ntp2 ntpd[29868]: DNS: dns_probe: ntp1.wiktel.com, cast_flags:1, flags:21901
2019-12-01T02:04:28.211433-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000046718 s while waiting for another thread
2019-12-01T02:04:28.219010-06:00 ntp2 ntpd[29868]: DNS: dns_check: processing ntp1.wiktel.com, 1, 21901
2019-12-01T02:04:28.219046-06:00 ntp2 ntpd[29868]: DNS: Server taking: 2600:2600::99
2019-12-01T02:04:28.219078-06:00 ntp2 ntpd[29868]: DNS: Server poking hole in restrictions for: 2600:2600::99
2019-12-01T02:04:28.219110-06:00 ntp2 ntpd[29868]: DNS: dns_take_status: ntp1.wiktel.com=>good, 0
2019-12-01T02:04:29.211262-06:00 ntp2 ntpd[29868]: DNS: dns_probe: time.cloudflare.com:1234, cast_flags:1, flags:21901
2019-12-01T02:04:29.211404-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000027831 s while waiting for another thread
2019-12-01T02:04:29.211444-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000008658 s while waiting for another thread
2019-12-01T02:04:29.303891-06:00 ntp2 ntpd[29868]: DNS: dns_check: processing time.cloudflare.com:1234, 1, 21901
2019-12-01T02:04:29.303925-06:00 ntp2 ntpd[29868]: DNS: Server taking: 2606:4700:f1::123
2019-12-01T02:04:29.304008-06:00 ntp2 ntpd[29868]: DNS: Server poking hole in restrictions for: 2606:4700:f1::123
2019-12-01T02:04:29.304055-06:00 ntp2 ntpd[29868]: DNS: dns_take_status: time.cloudflare.com:1234=>good, 0
2019-12-01T02:04:49.271159-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000015647 s while waiting for another thread
2019-12-01T02:05:10.364817-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000008022 s while waiting for another thread
2019-12-01T02:05:37.990619-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000051095 s while waiting for another thread
2019-12-01T02:06:04.152914-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000000160 s while waiting for another thread
2019-12-01T02:06:04.152954-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000001035 s while waiting for another thread
2019-12-01T02:06:20.372082-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000003552 s while waiting for another thread
2019-12-01T02:06:47.079607-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000001632 s while waiting for another thread
2019-12-01T02:06:52.489707-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000024759 s while waiting for another thread
2019-12-01T02:09:59.817856-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000019769 s while waiting for another thread
2019-12-01T02:10:28.192124-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000007581 s while waiting for another thread
2019-12-01T02:10:28.192234-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000022856 s while waiting for another thread
2019-12-01T02:10:41.854610-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000028176 s while waiting for another thread
2019-12-01T02:10:45.901016-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000048026 s while waiting for another thread
2019-12-01T02:10:45.901134-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000003723 s while waiting for another thread
2019-12-01T02:11:22.081163-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000009447 s while waiting for another thread
2019-12-01T02:11:22.081203-06:00 ntp2 ntpd[29868]: CLOCK: we were blocked for 0.000009033 s while waiting for another thread
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: OpenPGP digital signature
URL: <https://lists.ntpsec.org/pipermail/devel/attachments/20191201/3085dcac/attachment.bin>