Time issue using pycapnp async RPC

[Andreas Stenius]

Hi all!

Very long time since I was last here, so happy to see this project is still active!

Picked it up for a hobby project to get into it a bit again, this time using Python.

I've seen an issue come up quite frequently though, while playing around with a client/server setup modeled after the asyncio example for pycapnp, keep hitting this assert https://github.com/capnproto/capnproto/blob/be7a80b4add706ddaeb41689221146b86c3e0f5f/c%2B%2B/src/kj/timer.c%2B%2B#L113

libc++abi: terminating with uncaught exception of type kj::ExceptionImpl: kj/timer.c++:113: failed: expected newTime >= time; can't advance backwards in time

stack: 10521bb2e 1052131ee 1050f341c 10507382c 105073672 10507337a 1033f42b3 1033ec8b4 1033ecae2 1049c12f3 1049c20eb 1033ea4e5 1034e60ff 10342a701 1033ea833 1034c887f 1033eae9c 1034cbca1 1034c833e 1033eae9c 1034cbca1 1034c833e 1033eae9c 1034cbca1 1034c833e 1033eae9c 1034cbca1 1034c833e 1034ccd13 1033eb01c 1034cbca1

I see this message both on the server and on the client (but with different stack, naturally). Could this be caused if there's a ntp service running on my machine that adjusts the time slightly in the "wrong" direction, perhaps?

Is this a known issue?

Cheers,
Andreas kaos Stenius

[Kenton Varda]

That's very strange! Presumably the timer in use here is the one in UnixEventPort, but it always calls advanceTo() with a time taken from clock_gettime() with CLOCK_MONOTONIC. That value should never decrease regardless of ntp adjustments. Typically CLOCK_MONOTONIC counts time since system boot.

(On Windows, the code is different but should produce the same result: GetTickCount64() and QueryPerformanceCounter() are used to calculate the time. Neither of these should ever go backwards.)

So it seems like something weird is going on with your system?

-Kenton

--
You received this message because you are subscribed to the Google Groups "Cap'n Proto" group.
To unsubscribe from this group and stop receiving emails from it, send an email to capnproto+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/capnproto/8a94e397-9b55-4b54-aad2-8bd4470b2cc5n%40googlegroups.com.

[Andreas Stenius]

Thanks for the reply!

OK, so strange things on my end. Got it, see if I'll be able to investigate it further. (I'm on a Mac fwiw)

Darwin xx 21.5.0 Darwin Kernel Version 21.5.0: Tue Apr 26 21:08:22 PDT 2022; root:xnu-8020.121.3~4/RELEASE_X86_64 x86_64

[Kenton Varda]

Apple's POSIX support can be quite buggy, and apparently CLOCK_MONOTONIC was a late addition, so it's entirely possible there's something wrong with it that we need to work around in userspace.

However, this is the first I've actually heard this problem being reported and I'm sure plenty of people have run KJ event loops on Mac, so there must be a little more to it...

-Kenton