2.4 crashing on macOS with time moving forward?
After last week's struggle with the new version and my conf file, I got everything working. Now however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning, which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning: Time moved forward 48.803640 seconds Feb 07 16:30:27 master: Warning: Time moved forward by 694.039203 seconds - adjusting timeouts. Feb 07 16:52:47 imap(61246): Warning: Time moved forward 293.443011 seconds Feb 07 16:52:47 master: Warning: Time moved forward by 1279.423507 seconds - adjusting timeouts. Feb 07 17:25:39 imap(61286): Warning: Time moved forward 1942.575589 seconds Feb 07 17:25:39 imap(61288): Warning: Time moved forward 172.563346 seconds Feb 07 17:25:39 master: Warning: Time moved forward by 1912.666999 seconds - adjusting timeouts. Feb 07 17:49:32 imap(61286): Warning: Time moved forward 1402.761862 seconds Feb 07 17:51:13 master: Warning: Time moved forward by 1473.582569 seconds - adjusting timeouts. Feb 07 17:51:13 imap(61286): Warning: Time moved forward 70.823888 seconds Feb 07 17:53:07 master: Warning: Time moved forward by 53.843767 seconds - adjusting timeouts. Feb 07 18:44:22 imap(61286): Warning: Time moved forward 1386.259444 seconds Feb 07 19:11:41 master: Warning: Time moved forward by 615.609964 seconds - adjusting timeouts.
Note the very large jump dovecot claims is happening in all of these, up to half an hour, with a minimum of 48 seconds in this bunch. You can see that it even does a pair of these in rapid succession, like at 17:25:39 above, and will do >10 within the space of an hour.
These seem eventually to be followed by a crash ("eventually" because I'm running this on my laptop which isn't always open and running). The crash log entries all start with something like this:
Feb 07 16:17:53 imap(58315): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning: Killed with signal 15 (by pid=1 uid=0 code=unknown 0)
Feb 07 16:17:53 imap(58317): Fatal: master: service(imap): child 58317 killed with signal 6 (core dumps disabled - https://dovecot.org/bugreport.html#coredumps)
One more detail, I usually do sudo brew services start dovecot to run dovecot and this results in the crashes. When I was testing this on Saturday, I started it with sudo dovecot -F instead, so that I would see problems in the terminal. It went all day without crashing and I finally stopped and restarted it with the brew method. That's not a rigorous test, but it is suggestive.
Happy to provide more info, but I'm hoping this is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew macOS 13.6.9
J
Further info: this whole "time moved forward" thing had a long discussion and eventual fix in 2.3:
https://forums.freebsd.org/threads/dovecot-time-moved-forwards.82886/page-2
For the record, how my clock compares with a standard:
sntp time.euro.apple.com +0.109836 +/- 0.031550 time.euro.apple.com 17.253.14.251
So, first there seems to be a bug in this somewhere since dovecot is clearly getting wrong time info. Then this also seems related to dovecot eventually crashing on me.
J
On Feb 10, 2025, at 11:15, John Muccigrosso <muccigrosso@icloud.com> wrote:
After last week's struggle with the new version and my conf file, I got everything working. Now however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning, which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning: Time moved forward 48.803640 seconds Feb 07 16:30:27 master: Warning: Time moved forward by 694.039203 seconds - adjusting timeouts. Feb 07 16:52:47 imap(61246): Warning: Time moved forward 293.443011 seconds Feb 07 16:52:47 master: Warning: Time moved forward by 1279.423507 seconds - adjusting timeouts. Feb 07 17:25:39 imap(61286): Warning: Time moved forward 1942.575589 seconds Feb 07 17:25:39 imap(61288): Warning: Time moved forward 172.563346 seconds Feb 07 17:25:39 master: Warning: Time moved forward by 1912.666999 seconds - adjusting timeouts. Feb 07 17:49:32 imap(61286): Warning: Time moved forward 1402.761862 seconds Feb 07 17:51:13 master: Warning: Time moved forward by 1473.582569 seconds - adjusting timeouts. Feb 07 17:51:13 imap(61286): Warning: Time moved forward 70.823888 seconds Feb 07 17:53:07 master: Warning: Time moved forward by 53.843767 seconds - adjusting timeouts. Feb 07 18:44:22 imap(61286): Warning: Time moved forward 1386.259444 seconds Feb 07 19:11:41 master: Warning: Time moved forward by 615.609964 seconds - adjusting timeouts.
Note the very large jump dovecot claims is happening in all of these, up to half an hour, with a minimum of 48 seconds in this bunch. You can see that it even does a pair of these in rapid succession, like at 17:25:39 above, and will do >10 within the space of an hour.
These seem eventually to be followed by a crash ("eventually" because I'm running this on my laptop which isn't always open and running). The crash log entries all start with something like this:
Feb 07 16:17:53 imap(58315): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning: Killed with signal 15 (by pid=1 uid=0 code=unknown 0)
Feb 07 16:17:53 imap(58317): Fatal: master: service(imap): child 58317 killed with signal 6 (core dumps disabled - https://dovecot.org/bugreport.html#coredumps)
One more detail, I usually do
sudo brew services start dovecotto run dovecot and this results in the crashes. When I was testing this on Saturday, I started it withsudo dovecot -Finstead, so that I would see problems in the terminal. It went all day without crashing and I finally stopped and restarted it with the brew method. That's not a rigorous test, but it is suggestive.Happy to provide more info, but I'm hoping this is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew macOS 13.6.9
J
As this continues to happen and the list seems uninterested, how exactly should I report this bug?
Thanks.
J
On Feb 11, 2025, at 12:18, J wrote:
Further info: this whole "time moved forward" thing had a long discussion and eventual fix in 2.3:
https://forums.freebsd.org/threads/dovecot-time-moved-forwards.82886/page-2
For the record, how my clock compares with a standard:
sntp time.euro.apple.com +0.109836 +/- 0.031550 time.euro.apple.com 17.253.14.251
So, first there seems to be a bug in this somewhere since dovecot is clearly getting wrong time info. Then this also seems related to dovecot eventually crashing on me.
J
On Feb 10, 2025, at 11:15, J wrote:
After last week's struggle with the new version and my conf file, I got everything working. Now however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning, which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning: Time moved forward 48.803640 seconds Feb 07 16:30:27 master: Warning: Time moved forward by 694.039203 seconds - adjusting timeouts. Feb 07 16:52:47 imap(61246): Warning: Time moved forward 293.443011 seconds Feb 07 16:52:47 master: Warning: Time moved forward by 1279.423507 seconds - adjusting timeouts. Feb 07 17:25:39 imap(61286): Warning: Time moved forward 1942.575589 seconds Feb 07 17:25:39 imap(61288): Warning: Time moved forward 172.563346 seconds Feb 07 17:25:39 master: Warning: Time moved forward by 1912.666999 seconds - adjusting timeouts. Feb 07 17:49:32 imap(61286): Warning: Time moved forward 1402.761862 seconds Feb 07 17:51:13 master: Warning: Time moved forward by 1473.582569 seconds - adjusting timeouts. Feb 07 17:51:13 imap(61286): Warning: Time moved forward 70.823888 seconds Feb 07 17:53:07 master: Warning: Time moved forward by 53.843767 seconds - adjusting timeouts. Feb 07 18:44:22 imap(61286): Warning: Time moved forward 1386.259444 seconds Feb 07 19:11:41 master: Warning: Time moved forward by 615.609964 seconds - adjusting timeouts.
Note the very large jump dovecot claims is happening in all of these, up to half an hour, with a minimum of 48 seconds in this bunch. You can see that it even does a pair of these in rapid succession, like at 17:25:39 above, and will do >10 within the space of an hour.
These seem eventually to be followed by a crash ("eventually" because I'm running this on my laptop which isn't always open and running). The crash log entries all start with something like this:
Feb 07 16:17:53 imap(58315): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning: Killed with signal 15 (by pid=1 uid=0 code=unknown 0)
Feb 07 16:17:53 imap(58317): Fatal: master: service(imap): child 58317 killed with signal 6 (core dumps disabled - https://dovecot.org/bugreport.html#coredumps)
One more detail, I usually do
sudo brew services start dovecotto run dovecot and this results in the crashes. When I was testing this on Saturday, I started it withsudo dovecot -Finstead, so that I would see problems in the terminal. It went all day without crashing and I finally stopped and restarted it with the brew method. That's not a rigorous test, but it is suggestive.Happy to provide more info, but I'm hoping this is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew macOS 13.6.9
J
Does this occur when resuming from suspend/hibernate? Also, we do read this
list, it just sometimes takes time to react.
Aki
On 15/02/2025 11:13 EET John Muccigrosso via dovecot
<dovecot@dovecot.org> wrote:
As this continues to happen and the list seems uninterested, how
exactly should I report this bug?
Thanks.
J
On Feb 11, 2025, at 12:18, J wrote:
Further info: this whole "time moved forward" thing had a
long discussion and eventual fix in 2.3:
https://forums.freebsd.org/threads/dovecot-time-moved-
forwards.82886/page-2
For the record, how my clock compares with a standard:
sntp time.euro.apple.com
+0.109836 +/- 0.031550 time.euro.apple.com
17.253.14.251
So, first there seems to be a bug in this somewhere since
dovecot is clearly getting wrong time info. Then this also
seems related to dovecot eventually crashing on me.
J
On Feb 10, 2025, at 11:15, J wrote:
After last week's struggle with the new version
and my conf file, I got everything working. Now
however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning,
which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning:
Time moved forward 48.803640 seconds
Feb 07 16:30:27 master: Warning: Time
moved forward by 694.039203 seconds -
adjusting timeouts.
Feb 07 16:52:47 imap(61246): Warning:
Time moved forward 293.443011 seconds
Feb 07 16:52:47 master: Warning: Time
moved forward by 1279.423507 seconds -
adjusting timeouts.
Feb 07 17:25:39 imap(61286): Warning:
Time moved forward 1942.575589 seconds
Feb 07 17:25:39 imap(61288): Warning:
Time moved forward 172.563346 seconds
Feb 07 17:25:39 master: Warning: Time
moved forward by 1912.666999 seconds -
adjusting timeouts.
Feb 07 17:49:32 imap(61286): Warning:
Time moved forward 1402.761862 seconds
Feb 07 17:51:13 master: Warning: Time
moved forward by 1473.582569 seconds -
adjusting timeouts.
Feb 07 17:51:13 imap(61286): Warning:
Time moved forward 70.823888 seconds
Feb 07 17:53:07 master: Warning: Time
moved forward by 53.843767 seconds -
adjusting timeouts.
Feb 07 18:44:22 imap(61286): Warning:
Time moved forward 1386.259444 seconds
Feb 07 19:11:41 master: Warning: Time
moved forward by 615.609964 seconds -
adjusting timeouts.
Note the very large jump dovecot claims is
happening in all of these, up to half an hour,
with a minimum of 48 seconds in this bunch. You
can see that it even does a pair of these in
rapid succession, like at 17:25:39 above, and
will do >10 within the space of an hour.
These seem eventually to be followed by a crash
("eventually" because I'm running this on my
laptop which isn't always open and running). The
crash log entries all start with something like
this:
Feb 07 16:17:53 imap(58315): Panic:
file ./time-util.h: line 40
(timeval_add_usecs): assertion failed:
(usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning:
Killed with signal 15 (by pid=1 uid=0
code=unknown 0)
Feb 07 16:17:53 imap(58317): Fatal:
master: service(imap): child 58317
killed with signal 6 (core dumps
disabled - https://dovecot.org/
bugreport.html#coredumps)
One more detail, I usually do sudo brew services start dovecot to run dovecot and this results in
the crashes. When I was testing this on Saturday,
I started it with sudo dovecot -F instead, so
that I would see problems in the terminal. It
went all day without crashing and I finally
stopped and restarted it with the brew method.
That's not a rigorous test, but it is suggestive.
Happy to provide more info, but I'm hoping this
is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew
macOS 13.6.9
J
_______________________________________________
dovecot mailing list -- dovecot@dovecot.org
To unsubscribe send an email to dovecot-leave@dovecot.org
Thanks.
It happens in various scenarios, including when I'm actively working on the computer (or it's at least not sleeping). It also happens overnight when the computer should be sleeping. It doesn't seem to happen on resuming.
For example, here's this morning's (or late last night's) when the laptop was closed and sleeping:
Feb 14 22:58:02 master: Warning: Time moved forward by 282.937462 seconds - adjusting timeouts. Feb 15 00:05:28 master: Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0) Feb 15 00:05:28 master: Error: Raw backtrace: 0 libdovecot.0.dylib 0x00000001009bb120 backtrace_append + 72 -> 1 libdovecot.0.dylib 0x00000001009bb264 backtrace_get + 44 -> 2 libdovecot.0.dylib 0x00000001009c9d54 default_fatal_finish + 72 -> 3 libdovecot.0.dylib 0x00000001009c87c4 default_error_handler + 0 -> 4 libdovecot.0.dylib 0x00000001009c8790 fatal_handler_real + 0 -> 5 dovecot 0x00000001006df538 master_fatal_callback + 248 -> 6 libdovecot.0.dylib 0x00000001009c8940 i_fatal + 0 -> 7 libdovecot.0.dylib 0x00000001009e2724 ioloop_iolist_add + 0 -> 8 libdovecot.0.dylib 0x00000001009e0a3c io_loop_handle_timeouts + 640 -> 9 libdovecot.0.dylib 0x00000001009e3438 io_loop_handler_run_internal + 392 -> 10 libdovecot.0.dylib 0x00000001009e1130 io_loop_handler_run + 224 -> 11 libdovecot.0.dylib 0x00000001009e1000 io_loop_run + 92 -> 12 libdovecot.0.dylib 0x000000010093a22c master_service_run + 28 -> 13 dovecot 0x00000001006dee28 main + 2952 -> 14 dyld 0x00000001a4747fd8 start + 2412 Feb 15 00:05:28 log(73755): Warning: Killed with signal 15 (by pid=1 uid=0 code=unknown 0)
Crash log below.
J
On Feb 15, 2025, at 10:32, Aki Tuomi <aki.tuomi@open-xchange.com> wrote:
Does this occur when resuming from suspend/hibernate? Also, we do read this list, it just sometimes takes time to react.
Aki
On 15/02/2025 11:13 EET J via dovecot <dovecot@dovecot.org <mailto:dovecot@dovecot.org>> wrote:
As this continues to happen and the list seems uninterested, how exactly should I report this bug?
Thanks.
J
On Feb 11, 2025, at 12:18, J wrote:
Further info: this whole "time moved forward" thing had a long discussion and eventual fix in 2.3:
https://forums.freebsd.org/threads/dovecot-time-moved-forwards.82886/page-2
For the record, how my clock compares with a standard:
sntp time.euro.apple.com +0.109836 +/- 0.031550 time.euro.apple.com 17.253.14.251 So, first there seems to be a bug in this somewhere since dovecot is clearly getting wrong time info. Then this also seems related to dovecot eventually crashing on me.
J
On Feb 10, 2025, at 11:15, J wrote:
After last week's struggle with the new version and my conf file, I got everything working. Now however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning, which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning: Time moved forward 48.803640 seconds Feb 07 16:30:27 master: Warning: Time moved forward by 694.039203 seconds - adjusting timeouts. Feb 07 16:52:47 imap(61246): Warning: Time moved forward 293.443011 seconds Feb 07 16:52:47 master: Warning: Time moved forward by 1279.423507 seconds - adjusting timeouts. Feb 07 17:25:39 imap(61286): Warning: Time moved forward 1942.575589 seconds Feb 07 17:25:39 imap(61288): Warning: Time moved forward 172.563346 seconds Feb 07 17:25:39 master: Warning: Time moved forward by 1912.666999 seconds - adjusting timeouts. Feb 07 17:49:32 imap(61286): Warning: Time moved forward 1402.761862 seconds Feb 07 17:51:13 master: Warning: Time moved forward by 1473.582569 seconds - adjusting timeouts. Feb 07 17:51:13 imap(61286): Warning: Time moved forward 70.823888 seconds Feb 07 17:53:07 master: Warning: Time moved forward by 53.843767 seconds - adjusting timeouts. Feb 07 18:44:22 imap(61286): Warning: Time moved forward 1386.259444 seconds Feb 07 19:11:41 master: Warning: Time moved forward by 615.609964 seconds - adjusting timeouts. Note the very large jump dovecot claims is happening in all of these, up to half an hour, with a minimum of 48 seconds in this bunch. You can see that it even does a pair of these in rapid succession, like at 17:25:39 above, and will do >10 within the space of an hour.
These seem eventually to be followed by a crash ("eventually" because I'm running this on my laptop which isn't always open and running). The crash log entries all start with something like this:
Feb 07 16:17:53 imap(58315): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning: Killed with signal 15 (by pid=1 uid=0 code=unknown 0) Feb 07 16:17:53 imap(58317): Fatal: master: service(imap): child 58317 killed with signal 6 (core dumps disabled - https://dovecot.org/bugreport.html#coredumps)
One more detail, I usually do
sudo brew services start dovecotto run dovecot and this results in the crashes. When I was testing this on Saturday, I started it withsudo dovecot -Finstead, so that I would see problems in the terminal. It went all day without crashing and I finally stopped and restarted it with the brew method. That's not a rigorous test, but it is suggestive.Happy to provide more info, but I'm hoping this is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew macOS 13.6.9
J
dovecot mailing list -- dovecot@dovecot.org <mailto:dovecot@dovecot.org> To unsubscribe send an email to dovecot-leave@dovecot.org <mailto:dovecot-leave@dovecot.org>
Translated Report (Full Report Below)
Process: dovecot [73750] Path: /opt/homebrew/*/dovecot Identifier: dovecot Version: ??? Code Type: ARM-64 (Native) Parent Process: launchd [1] User ID: 0
Date/Time: 2025-02-15 00:05:28.3917 +0100 OS Version: macOS 13.6.9 (22G830) Report Version: 12 Anonymous UUID: 29B23C20-57B1-887B-2EE7-7DCE47D4DF79
Sleep/Wake UUID: 5FB9AF1F-E715-4B9E-B04D-DBDF5D0CF7A3
Time Awake Since Boot: 430000 seconds Time Since Wake: 16 seconds
System Integrity Protection: enabled
Crashed Thread: 0 Dispatch queue: com.apple.main-thread
Exception Type: EXC_CRASH (SIGABRT) Exception Codes: 0x0000000000000000, 0x0000000000000000
Termination Reason: Namespace SIGNAL, Code 6 Abort trap: 6 Terminating Process: dovecot [73750]
Application Specific Information: abort() called
Thread 0 Crashed:: Dispatch queue: com.apple.main-thread 0 libsystem_kernel.dylib 0x1a4a68704 __pthread_kill + 8 1 libsystem_pthread.dylib 0x1a4a9fc28 pthread_kill + 288 2 libsystem_c.dylib 0x1a49adae8 abort + 180 3 libdovecot.0.dylib 0x1009c9db4 default_fatal_finish + 168 4 libdovecot.0.dylib 0x1009c87c4 fatal_handler_real + 52 5 libdovecot.0.dylib 0x1009c8790 default_fatal_handler + 40 6 dovecot 0x1006df538 master_fatal_callback + 248 7 libdovecot.0.dylib 0x1009c8940 i_panic + 80 8 libdovecot.0.dylib 0x1009e2724 io_loops_timeouts_update + 396 9 libdovecot.0.dylib 0x1009e0a3c io_loop_handle_timeouts + 640 10 libdovecot.0.dylib 0x1009e3438 io_loop_handler_run_internal + 392 11 libdovecot.0.dylib 0x1009e1130 io_loop_handler_run + 224 12 libdovecot.0.dylib 0x1009e1000 io_loop_run + 92 13 libdovecot.0.dylib 0x10093a22c master_service_run + 28 14 dovecot 0x1006dee28 main + 2952 15 dyld 0x1a4747fd8 start + 2412
Thread 0 crashed with ARM Thread State (64-bit): x0: 0x0000000000000000 x1: 0x0000000000000000 x2: 0x0000000000000000 x3: 0x0000000000000000 x4: 0xfffffffffffff23a x5: 0x000000000000000a x6: 0x0000000000000020 x7: 0x0000000000000b00 x8: 0x5c36c162b2174aa8 x9: 0x5c36c160b208aba8 x10: 0x00000000000069d8 x11: 0x0000000000000003 x12: 0x00000000000004ed x13: 0x00000b0100000bc0 x14: 0x00000c0100000c80 x15: 0x0000000000000054 x16: 0x0000000000000148 x17: 0x0000000204d5ec60 x18: 0x0000000000000000 x19: 0x0000000000000006 x20: 0x00000002001fe100 x21: 0x0000000000000103 x22: 0x00000002001fe1e0 x23: 0x00000000000f423f x24: 0x0000000012656a5e x25: 0x0000000000000134 x26: 0x000000000009b55e x27: 0x0000000000000f92 x28: 0x0000000000050d22 fp: 0x000000016f723160 lr: 0x00000001a4a9fc28 sp: 0x000000016f723140 pc: 0x00000001a4a68704 cpsr: 0x40001000 far: 0x0000000000000000 esr: 0x56000080 Address size fault
Binary Images: 0x1006dc000 - 0x1006ebfff dovecot (*) <89fbcf7d-4107-30e9-81dd-37e7d3a2480e> /opt/homebrew/*/dovecot 0x1008fc000 - 0x100a53fff libdovecot.0.dylib (*) <6e9c4759-86b7-3ad4-9d8f-f0a98f795cb8> /opt/homebrew/*/libdovecot.0.dylib 0x1a4a5f000 - 0x1a4a98ff7 libsystem_kernel.dylib (*) <826ec6d5-d1b5-3c71-8b4a-f52782b01a7f> /usr/lib/system/libsystem_kernel.dylib 0x1a4a99000 - 0x1a4aa5fff libsystem_pthread.dylib (*) <7acb080f-eabe-3a59-8d9f-7459f33bb263> /usr/lib/system/libsystem_pthread.dylib 0x1a4937000 - 0x1a49b5ff7 libsystem_c.dylib (*) <840fe68c-8175-347b-bfb1-3b6bce431935> /usr/lib/system/libsystem_c.dylib 0x1a4742000 - 0x1a47d0d13 dyld (*) <79b0cd10-fb62-30ef-9aeb-87e4a596b006> /usr/lib/dyld
External Modification Summary: Calls made by other processes targeting this process: task_for_pid: 0 thread_create: 0 thread_set_state: 0 Calls made by this process: task_for_pid: 0 thread_create: 0 thread_set_state: 0 Calls made by all processes on this machine: task_for_pid: 0 thread_create: 0 thread_set_state: 0
VM Region Summary: ReadOnly portion of Libraries: Total=811.3M resident=0K(0%) swapped_out_or_unallocated=811.3M(100%) Writable regions: Total=974.6M written=0K(0%) resident=0K(0%) swapped_out=0K(0%) unallocated=974.6M(100%)
VIRTUAL REGION REGION TYPE SIZE COUNT (non-coalesced) =========== ======= ======= Activity Tracing 256K 1 Kernel Alloc Once 32K 1 MALLOC 222.2M 26 MALLOC guard page 96K 5 MALLOC_MEDIUM (reserved) 360.0M 3 reserved VM address space (unallocated) MALLOC_NANO (reserved) 384.0M 1 reserved VM address space (unallocated) STACK GUARD 56.0M 1 Stack 8176K 1 __AUTH 46K 11 __AUTH_CONST 77K 40 __DATA 209K 40 __DATA_CONST 231K 43 __DATA_DIRTY 78K 22 __LINKEDIT 803.8M 3 __OBJC_RO 66.4M 1 __OBJC_RW 2012K 1 __TEXT 7692K 45 dyld private memory 272K 2 mapped file 64K 1 shared memory 32K 2 =========== ======= ======= TOTAL 1.9G 250 TOTAL, minus reserved VM space 1.1G 250
Full Report
{"app_name":"dovecot","timestamp":"2025-02-15 00:05:29.00 +0100","app_version":"","slice_uuid":"89fbcf7d-4107-30e9-81dd-37e7d3a2480e","build_version":"","platform":1,"share_with_app_devs":0,"is_first_party":1,"bug_type":"309","os_version":"macOS 13.6.9 (22G830)","roots_installed":0,"incident_id":"A5A9524D-3FAE-4C97-A7F3-83D9B0B920AA","name":"dovecot"} { "uptime" : 430000, "procRole" : "Unspecified", "version" : 2, "userID" : 0, "deployVersion" : 210, "modelCode" : "Mac14,7", "coalitionID" : 42789, "osVersion" : { "train" : "macOS 13.6.9", "build" : "22G830", "releaseType" : "User" }, "captureTime" : "2025-02-15 00:05:28.3917 +0100", "incident" : "A5A9524D-3FAE-4C97-A7F3-83D9B0B920AA", "pid" : 73750, "translated" : false, "cpuType" : "ARM-64", "roots_installed" : 0, "bug_type" : "309", "procLaunch" : "2025-02-14 09:08:53.4251 +0100", "procStartAbsTime" : 9728718032712, "procExitAbsTime" : 10422691932867, "procName" : "dovecot", "procPath" : "\/opt\/homebrew\/*\/dovecot", "parentProc" : "launchd", "parentPid" : 1, "coalitionName" : "homebrew.mxcl.dovecot", "crashReporterKey" : "29B23C20-57B1-887B-2EE7-7DCE47D4DF79", "codeSigningID" : "dovecot-5555494489fbcf7d410730e981dd37e7d3a2480e", "codeSigningTeamID" : "", "codeSigningFlags" : 570425857, "codeSigningValidationCategory" : 10, "codeSigningTrustLevel" : 0, "wakeTime" : 16, "sleepWakeUUID" : "5FB9AF1F-E715-4B9E-B04D-DBDF5D0CF7A3", "sip" : "enabled", "exception" : {"codes":"0x0000000000000000, 0x0000000000000000","rawCodes":[0,0],"type":"EXC_CRASH","signal":"SIGABRT"}, "termination" : {"flags":0,"code":6,"namespace":"SIGNAL","indicator":"Abort trap: 6","byProc":"dovecot","byPid":73750}, "asi" : {"libsystem_c.dylib":["abort() called"]}, "extMods" : {"caller":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"system":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"targeted":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"warnings":0}, "faultingThread" : 0, "threads" : [{"triggered":true,"id":5990211,"threadState":{"x":[{"value":0},{"value":0},{"value":0},{"value":0},{"value":18446744073709548090},{"value":10},{"value":32},{"value":2816},{"value":6644710929870572200},{"value":6644710921279679400},{"value":27096},{"value":3},{"value":1261},{"value":12098922875840},{"value":13198434503808},{"value":84},{"value":328},{"value":8671063136},{"value":0},{"value":6},{"value":8592023808,"symbolLocation":0,"symbol":"_main_thread"},{"value":259},{"value":8592024032,"symbolLocation":224,"symbol":"_main_thread"},{"value":999999},{"value":308636254},{"value":308},{"value":636254},{"value":3986},{"value":331042}],"flavor":"ARM_THREAD_STATE64","lr":{"value":7057570856},"cpsr":{"value":1073745920},"fp":{"value":6164722016},"sp":{"value":6164721984},"esr":{"value":1442840704,"description":" Address size fault"},"pc":{"value":7057344260,"matchesCrashFrame":1},"far":{"value":0}},"queue":"com.apple.main-thread","frames":[{"imageOffset":38660,"symbol":"__pthread_kill","symbolLocation":8,"imageIndex":2},{"imageOffset":27688,"symbol":"pthread_kill","symbolLocation":288,"imageIndex":3},{"imageOffset":486120,"symbol":"abort","symbolLocation":180,"imageIndex":4},{"imageOffset":843188,"symbol":"default_fatal_finish","symbolLocation":168,"imageIndex":1},{"imageOffset":837572,"symbol":"fatal_handler_real","symbolLocation":52,"imageIndex":1},{"imageOffset":837520,"symbol":"default_fatal_handler","symbolLocation":40,"imageIndex":1},{"imageOffset":13624,"symbol":"master_fatal_callback","symbolLocation":248,"imageIndex":0},{"imageOffset":837952,"symbol":"i_panic","symbolLocation":80,"imageIndex":1},{"imageOffset":943908,"symbol":"io_loops_timeouts_update","symbolLocation":396,"imageIndex":1},{"imageOffset":936508,"symbol":"io_loop_handle_timeouts","symbolLocation":640,"imageIndex":1},{"imageOffset":947256,"symbol":"io_loop_handler_run_internal","symbolLocation":392,"imageIndex":1},{"imageOffset":938288,"symbol":"io_loop_handler_run","symbolLocation":224,"imageIndex":1},{"imageOffset":937984,"symbol":"io_loop_run","symbolLocation":92,"imageIndex":1},{"imageOffset":254508,"symbol":"master_service_run","symbolLocation":28,"imageIndex":1},{"imageOffset":11816,"symbol":"main","symbolLocation":2952,"imageIndex":0},{"imageOffset":24536,"symbol":"start","symbolLocation":2412,"imageIndex":5}]}], "usedImages" : [ { "source" : "P", "arch" : "arm64", "base" : 4302159872, "size" : 65536, "uuid" : "89fbcf7d-4107-30e9-81dd-37e7d3a2480e", "path" : "\/opt\/homebrew\/*\/dovecot", "name" : "dovecot" }, { "source" : "P", "arch" : "arm64", "base" : 4304388096, "size" : 1409024, "uuid" : "6e9c4759-86b7-3ad4-9d8f-f0a98f795cb8", "path" : "\/opt\/homebrew\/*\/libdovecot.0.dylib", "name" : "libdovecot.0.dylib" }, { "source" : "P", "arch" : "arm64e", "base" : 7057305600, "size" : 237560, "uuid" : "826ec6d5-d1b5-3c71-8b4a-f52782b01a7f", "path" : "\/usr\/lib\/system\/libsystem_kernel.dylib", "name" : "libsystem_kernel.dylib" }, { "source" : "P", "arch" : "arm64e", "base" : 7057543168, "size" : 53248, "uuid" : "7acb080f-eabe-3a59-8d9f-7459f33bb263", "path" : "\/usr\/lib\/system\/libsystem_pthread.dylib", "name" : "libsystem_pthread.dylib" }, { "source" : "P", "arch" : "arm64e", "base" : 7056093184, "size" : 520184, "uuid" : "840fe68c-8175-347b-bfb1-3b6bce431935", "path" : "\/usr\/lib\/system\/libsystem_c.dylib", "name" : "libsystem_c.dylib" }, { "source" : "P", "arch" : "arm64e", "base" : 7054041088, "size" : 584980, "uuid" : "79b0cd10-fb62-30ef-9aeb-87e4a596b006", "path" : "\/usr\/lib\/dyld", "name" : "dyld" } ], "sharedCache" : { "base" : 7053377536, "size" : 3586080768, "uuid" : "5b429225-625d-316a-b915-35ab8cd166f8" }, "vmSummary" : "ReadOnly portion of Libraries: Total=811.3M resident=0K(0%) swapped_out_or_unallocated=811.3M(100%)\nWritable regions: Total=974.6M written=0K(0%) resident=0K(0%) swapped_out=0K(0%) unallocated=974.6M(100%)\n\n VIRTUAL REGION \nREGION TYPE SIZE COUNT (non-coalesced) \n=========== ======= ======= \nActivity Tracing 256K 1 \nKernel Alloc Once 32K 1 \nMALLOC 222.2M 26 \nMALLOC guard page 96K 5 \nMALLOC_MEDIUM (reserved) 360.0M 3 reserved VM address space (unallocated)\nMALLOC_NANO (reserved) 384.0M 1 reserved VM address space (unallocated)\nSTACK GUARD 56.0M 1 \nStack 8176K 1 \n__AUTH 46K 11 \n__AUTH_CONST 77K 40 \n__DATA 209K 40 \n__DATA_CONST 231K 43 \n__DATA_DIRTY 78K 22 \n__LINKEDIT 803.8M 3 \n__OBJC_RO 66.4M 1 \n__OBJC_RW 2012K 1 \n__TEXT 7692K 45 \ndyld private memory 272K 2 \nmapped file 64K 1 \nshared memory 32K 2 \n=========== ======= ======= \nTOTAL 1.9G 250 \nTOTAL, minus reserved VM space 1.1G 250 \n", "legacyInfo" : { "threadTriggered" : { "queue" : "com.apple.main-thread" } }, "logWritingSignature" : "cc4bcac5503d3f2204421c18e49285cbf1ca4c0b" }
Wondering if there's anyone who can help with this, which is still happening. Yesterday's crash in the logs:
Feb 26 15:55:07 imap(82011): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0)
Thanks.
J
On Feb 15, 2025, at 11:18, John Muccigrosso <muccigrosso@icloud.com>
wrote:
Thanks.
It happens in various scenarios, including when I'm actively working on the computer (or it's at least not sleeping). It also happens overnight when the computer should be sleeping. It doesn't seem to happen on resuming.
For example, here's this morning's (or late last night's) when the laptop was closed and sleeping:
Feb 14 22:58:02 master: Warning: Time moved forward by 282.937462
seconds - adjusting timeouts.
Feb 15 00:05:28 master: Panic: file ./time-util.h: line 40
(timeval_add_usecs): assertion failed: (usecs >= 0)
Feb 15 00:05:28 master: Error: Raw backtrace: 0 libdovecot.0.dylib
0x00000001009bb120 backtrace_append + 72 -> 1
libdovecot.0.dylib 0x00000001009bb264 backtrace_get
+ 44 -> 2 libdovecot.0.dylib 0x00000001009c9d54
default_fatal_finish + 72 -> 3 libdovecot.0.dylib
0x00000001009c87c4 default_error_handler + 0 -> 4
libdovecot.0.dylib 0x00000001009c8790
fatal_handler_real + 0 -> 5 dovecot
0x00000001006df538 master_fatal_callback + 248 -> 6
libdovecot.0.dylib 0x00000001009c8940 i_fatal + 0 -
> 7 libdovecot.0.dylib 0x00000001009e2724
ioloop_iolist_add + 0 -> 8 libdovecot.0.dylib
0x00000001009e0a3c io_loop_handle_timeouts + 640 -> 9
libdovecot.0.dylib 0x00000001009e3438
io_loop_handler_run_internal + 392 -> 10 libdovecot.0.dylib
0x00000001009e1130 io_loop_handler_run + 224 -> 11
libdovecot.0.dylib 0x00000001009e1000 io_loop_run +
92 -> 12 libdovecot.0.dylib 0x000000010093a22c
master_service_run + 28 -> 13 dovecot
0x00000001006dee28 main + 2952 -> 14 dyld
0x00000001a4747fd8 start + 2412
Feb 15 00:05:28 log(73755): Warning: Killed with signal 15 (by pid=1
uid=0 code=unknown 0)Crash log below.
J
On Feb 15, 2025, at 10:32, Aki Tuomi <aki.tuomi@open-xchange.com>
wrote:Does this occur when resuming from suspend/hibernate? Also, we do read this
list, it just sometimes takes time to react.
Aki
On 15/02/2025 11:13 EET J via dovecot <dovecot@dovecot.org> wrote:
As this continues to happen and the list seems uninterested, how
exactly should I report this bug?
Thanks.
J
On Feb 11, 2025, at 12:18, J wrote:
Further info: this whole "time moved forward" thing had a
long discussion and eventual fix in 2.3:
https://forums.freebsd.org/threads/dovecot-time-moved-
forwards.82886/page-2
For the record, how my clock compares with a standard:
sntp time.euro.apple.com
+0.109836 +/- 0.031550 time.euro.apple.com
17.253.14.251
So, first there seems to be a bug in this somewhere since
dovecot is clearly getting wrong time info. Then this also
seems related to dovecot eventually crashing on me.
J
On Feb 10, 2025, at 11:15, J wrote:
After last week's struggle with the new version
and my conf file, I got everything working. Now
however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning,
which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning:
Time moved forward 48.803640 seconds
Feb 07 16:30:27 master: Warning: Time
moved forward by 694.039203 seconds -
adjusting timeouts.
Feb 07 16:52:47 imap(61246): Warning:
Time moved forward 293.443011 seconds
Feb 07 16:52:47 master: Warning: Time
moved forward by 1279.423507 seconds -
adjusting timeouts.
Feb 07 17:25:39 imap(61286): Warning:
Time moved forward 1942.575589 seconds
Feb 07 17:25:39 imap(61288): Warning:
Time moved forward 172.563346 seconds
Feb 07 17:25:39 master: Warning: Time
moved forward by 1912.666999 seconds -
adjusting timeouts.
Feb 07 17:49:32 imap(61286): Warning:
Time moved forward 1402.761862 seconds
Feb 07 17:51:13 master: Warning: Time
moved forward by 1473.582569 seconds -
adjusting timeouts.
Feb 07 17:51:13 imap(61286): Warning:
Time moved forward 70.823888 seconds
Feb 07 17:53:07 master: Warning: Time
moved forward by 53.843767 seconds -
adjusting timeouts.
Feb 07 18:44:22 imap(61286): Warning:
Time moved forward 1386.259444 seconds
Feb 07 19:11:41 master: Warning: Time
moved forward by 615.609964 seconds -
adjusting timeouts.
Note the very large jump dovecot claims is
happening in all of these, up to half an hour,
with a minimum of 48 seconds in this bunch. You
can see that it even does a pair of these in
rapid succession, like at 17:25:39 above, and
will do >10 within the space of an hour.
These seem eventually to be followed by a crash
("eventually" because I'm running this on my
laptop which isn't always open and running). The
crash log entries all start with something like
this:
Feb 07 16:17:53 imap(58315): Panic:
file ./time-util.h: line 40
(timeval_add_usecs): assertion failed:
(usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning:
Killed with signal 15 (by pid=1 uid=0
code=unknown 0)
Feb 07 16:17:53 imap(58317): Fatal:
master: service(imap): child 58317
killed with signal 6 (core dumps
disabled - https://dovecot.org/
bugreport.html#coredumps)
One more detail, I usually do sudo brew services start dovecot to run dovecot and this results in
the crashes. When I was testing this on Saturday,
I started it with sudo dovecot -F instead, so
that I would see problems in the terminal. It
went all day without crashing and I finally
stopped and restarted it with the brew method.
That's not a rigorous test, but it is suggestive.
Happy to provide more info, but I'm hoping this
is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew
macOS 13.6.9
J
Are you sure the real time on your Laptop is not drifting (and eventually gets corrected by time.euro.apple.com just to drift again)?
Depending on the type of laptop maybe the build-in RTC doesn't keep the time as it should caused i.e. by a depleted CMOS battery (note: No CMOS battery in portables though).
I would do a SMC reset on that laptop. If this doesn't help consider a NVRAM (or PRAM) reset.
Tamsy
John Muccigrosso via dovecot wrote on 02.03.2025 14:21: Wondering if there's anyone who can help with this, which is still happening. Yesterday's crash in the logs:
Feb 26 15:55:07 imap(82011): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0)
Thanks.
J
On Feb 15, 2025, at 11:18, John Muccigrosso <muccigrosso@icloud.com>-------- Original Message -------- From: John Muccigrosso via dovecot <dovecot@dovecot.org> Sent: Sunday, March 2, 2025 at 2:21 PM UTC+7 To: dovecot@dovecot.org Cc: Aki Tuomi <aki.tuomi@open-xchange.com> Subject: RE: 2.4 crashing on macOS with time moving forward?
Thanks.
It happens in various scenarios, including when I'm actively working on the computer (or it's at least not sleeping). It also happens overnight when the computer should be sleeping. It doesn't seem to happen on resuming.
For example, here's this morning's (or late last night's) when the laptop was closed and sleeping:
Feb 14 22:58:02 master: Warning: Time moved forward by 282.937462
seconds - adjusting timeouts.
Feb 15 00:05:28 master: Panic: file ./time-util.h: line 40
(timeval_add_usecs): assertion failed: (usecs >= 0)
Feb 15 00:05:28 master: Error: Raw backtrace: 0 libdovecot.0.dylib
0x00000001009bb120 backtrace_append + 72 -> 1
libdovecot.0.dylib 0x00000001009bb264 backtrace_get
+ 44 -> 2 libdovecot.0.dylib 0x00000001009c9d54
default_fatal_finish + 72 -> 3 libdovecot.0.dylib
0x00000001009c87c4 default_error_handler + 0 -> 4
libdovecot.0.dylib 0x00000001009c8790
fatal_handler_real + 0 -> 5 dovecot
0x00000001006df538 master_fatal_callback + 248 -> 6
libdovecot.0.dylib 0x00000001009c8940 i_fatal + 0 -
> 7 libdovecot.0.dylib 0x00000001009e2724
ioloop_iolist_add + 0 -> 8 libdovecot.0.dylib
0x00000001009e0a3c io_loop_handle_timeouts + 640 -> 9
libdovecot.0.dylib 0x00000001009e3438
io_loop_handler_run_internal + 392 -> 10 libdovecot.0.dylib
0x00000001009e1130 io_loop_handler_run + 224 -> 11
libdovecot.0.dylib 0x00000001009e1000 io_loop_run +
92 -> 12 libdovecot.0.dylib 0x000000010093a22c
master_service_run + 28 -> 13 dovecot
0x00000001006dee28 main + 2952 -> 14 dyld
0x00000001a4747fd8 start + 2412
Feb 15 00:05:28 log(73755): Warning: Killed with signal 15 (by pid=1
uid=0 code=unknown 0)Crash log below.
J
On Feb 15, 2025, at 10:32, Aki Tuomi <aki.tuomi@open-xchange.com>
wrote:Does this occur when resuming from suspend/hibernate? Also, we do read this list, it just sometimes takes time to react.
Aki On 15/02/2025 11:13 EET J via dovecot <dovecot@dovecot.org> wrote:
As this continues to happen and the list seems uninterested, how
exactly should I report this bug?
Thanks.
J
On Feb 11, 2025, at 12:18, J wrote:
Further info: this whole "time moved forward" thing had a
long discussion and eventual fix in 2.3:
https://forums.freebsd.org/threads/dovecot-time-moved-
forwards.82886/page-2
For the record, how my clock compares with a standard:
sntp time.euro.apple.com
+0.109836 +/- 0.031550 time.euro.apple.com
17.253.14.251
So, first there seems to be a bug in this somewhere since
dovecot is clearly getting wrong time info. Then this also
seems related to dovecot eventually crashing on me.
J
On Feb 10, 2025, at 11:15, J wrote:
After last week's struggle with the new version
and my conf file, I got everything working. Now
however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning,
which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning:
Time moved forward 48.803640 seconds
Feb 07 16:30:27 master: Warning: Time
moved forward by 694.039203 seconds -
adjusting timeouts.
Feb 07 16:52:47 imap(61246): Warning:
Time moved forward 293.443011 seconds
Feb 07 16:52:47 master: Warning: Time
moved forward by 1279.423507 seconds -
adjusting timeouts.
Feb 07 17:25:39 imap(61286): Warning:
Time moved forward 1942.575589 seconds
Feb 07 17:25:39 imap(61288): Warning:
Time moved forward 172.563346 seconds
Feb 07 17:25:39 master: Warning: Time
moved forward by 1912.666999 seconds -
adjusting timeouts.
Feb 07 17:49:32 imap(61286): Warning:
Time moved forward 1402.761862 seconds
Feb 07 17:51:13 master: Warning: Time
moved forward by 1473.582569 seconds -
adjusting timeouts.
Feb 07 17:51:13 imap(61286): Warning:
Time moved forward 70.823888 seconds
Feb 07 17:53:07 master: Warning: Time
moved forward by 53.843767 seconds -
adjusting timeouts.
Feb 07 18:44:22 imap(61286): Warning:
Time moved forward 1386.259444 seconds
Feb 07 19:11:41 master: Warning: Time
moved forward by 615.609964 seconds -
adjusting timeouts.
Note the very large jump dovecot claims is
happening in all of these, up to half an hour,
with a minimum of 48 seconds in this bunch. You
can see that it even does a pair of these in
rapid succession, like at 17:25:39 above, and
will do >10 within the space of an hour.
These seem eventually to be followed by a crash
("eventually" because I'm running this on my
laptop which isn't always open and running). The
crash log entries all start with something like
this:
Feb 07 16:17:53 imap(58315): Panic:
file ./time-util.h: line 40
(timeval_add_usecs): assertion failed:
(usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning:
Killed with signal 15 (by pid=1 uid=0
code=unknown 0)
Feb 07 16:17:53 imap(58317): Fatal:
master: service(imap): child 58317
killed with signal 6 (core dumps
disabled - https://dovecot.org/
bugreport.html#coredumps)
One more detail, I usually do `sudo brew services
start dovecot` to run dovecot and this results in
the crashes. When I was testing this on Saturday,
I started it with `sudo dovecot -F` instead, so
that I would see problems in the terminal. It
went all day without crashing and I finally
stopped and restarted it with the brew method.
That's not a rigorous test, but it is suggestive.
Happy to provide more info, but I'm hoping this
is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew
macOS 13.6.9
Jdovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
These are pretty big drifts, like tens of minutes. Also note that a bunch of corrections get logged within a second of each other. And this is dovecot’s log.
I think I’d notice problems like that with the clock, but what’s the best way for me to check? Is there another log that should track the same thing?
J
Il giorno 2 mar 2025, alle ore 13:39, Tamsy via dovecot <dovecot@dovecot.org> ha scritto:
Are you sure the real time on your Laptop is not drifting (and eventually gets corrected by time.euro.apple.com just to drift again)?
Depending on the type of laptop maybe the build-in RTC doesn't keep the time as it should caused i.e. by a depleted CMOS battery (note: No CMOS battery in portables though).
I would do a SMC reset on that laptop. If this doesn't help consider a NVRAM (or PRAM) reset.
Tamsy
John Muccigrosso via dovecot wrote on 02.03.2025 14:21: Wondering if there's anyone who can help with this, which is still happening. Yesterday's crash in the logs:
Feb 26 15:55:07 imap(82011): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0)
Thanks.
J
On Feb 15, 2025, at 11:18, John Muccigrosso <muccigrosso@icloud.com>-------- Original Message -------- From: John Muccigrosso via dovecot <dovecot@dovecot.org> Sent: Sunday, March 2, 2025 at 2:21 PM UTC+7 To: dovecot@dovecot.org Cc: Aki Tuomi <aki.tuomi@open-xchange.com> Subject: RE: 2.4 crashing on macOS with time moving forward?
Thanks.
It happens in various scenarios, including when I'm actively working on the computer (or it's at least not sleeping). It also happens overnight when the computer should be sleeping. It doesn't seem to happen on resuming.
For example, here's this morning's (or late last night's) when the laptop was closed and sleeping:
Feb 14 22:58:02 master: Warning: Time moved forward by 282.937462 seconds - adjusting timeouts. Feb 15 00:05:28 master: Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0) Feb 15 00:05:28 master: Error: Raw backtrace: 0 libdovecot.0.dylib 0x00000001009bb120 backtrace_append + 72 -> 1 libdovecot.0.dylib 0x00000001009bb264 backtrace_get + 44 -> 2 libdovecot.0.dylib 0x00000001009c9d54 default_fatal_finish + 72 -> 3 libdovecot.0.dylib 0x00000001009c87c4 default_error_handler + 0 -> 4 libdovecot.0.dylib 0x00000001009c8790 fatal_handler_real + 0 -> 5 dovecot 0x00000001006df538 master_fatal_callback + 248 -> 6 libdovecot.0.dylib 0x00000001009c8940 i_fatal + 0 - > 7 libdovecot.0.dylib 0x00000001009e2724 ioloop_iolist_add + 0 -> 8 libdovecot.0.dylib 0x00000001009e0a3c io_loop_handle_timeouts + 640 -> 9 libdovecot.0.dylib 0x00000001009e3438 io_loop_handler_run_internal + 392 -> 10 libdovecot.0.dylib 0x00000001009e1130 io_loop_handler_run + 224 -> 11 libdovecot.0.dylib 0x00000001009e1000 io_loop_run + 92 -> 12 libdovecot.0.dylib 0x000000010093a22c master_service_run + 28 -> 13 dovecot 0x00000001006dee28 main + 2952 -> 14 dyld 0x00000001a4747fd8 start + 2412 Feb 15 00:05:28 log(73755): Warning: Killed with signal 15 (by pid=1 uid=0 code=unknown 0)Crash log below.
J
On Feb 15, 2025, at 10:32, Aki Tuomi <aki.tuomi@open-xchange.com> wrote:Does this occur when resuming from suspend/hibernate? Also, we do read this list, it just sometimes takes time to react.
Aki On 15/02/2025 11:13 EET J via dovecot <dovecot@dovecot.org> wrote:
As this continues to happen and the list seems uninterested, how exactly should I report this bug? Thanks. J On Feb 11, 2025, at 12:18, J wrote: Further info: this whole "time moved forward" thing had a long discussion and eventual fix in 2.3: https://forums.freebsd.org/threads/dovecot-time-moved- forwards.82886/page-2 For the record, how my clock compares with a standard: sntp time.euro.apple.com +0.109836 +/- 0.031550 time.euro.apple.com 17.253.14.251 So, first there seems to be a bug in this somewhere since dovecot is clearly getting wrong time info. Then this also seems related to dovecot eventually crashing on me. J On Feb 10, 2025, at 11:15, J wrote: After last week's struggle with the new version and my conf file, I got everything working. Now however dovecot crashes on me every few hours. The logs show a bunch of this kind of warning, which I find mention of on the internets: Feb 07 15:13:47 imap(58317): Warning: Time moved forward 48.803640 seconds Feb 07 16:30:27 master: Warning: Time moved forward by 694.039203 seconds - adjusting timeouts. Feb 07 16:52:47 imap(61246): Warning: Time moved forward 293.443011 seconds Feb 07 16:52:47 master: Warning: Time moved forward by 1279.423507 seconds - adjusting timeouts. Feb 07 17:25:39 imap(61286): Warning: Time moved forward 1942.575589 seconds Feb 07 17:25:39 imap(61288): Warning: Time moved forward 172.563346 seconds Feb 07 17:25:39 master: Warning: Time moved forward by 1912.666999 seconds - adjusting timeouts. Feb 07 17:49:32 imap(61286): Warning: Time moved forward 1402.761862 seconds Feb 07 17:51:13 master: Warning: Time moved forward by 1473.582569 seconds - adjusting timeouts. Feb 07 17:51:13 imap(61286): Warning: Time moved forward 70.823888 seconds Feb 07 17:53:07 master: Warning: Time moved forward by 53.843767 seconds - adjusting timeouts. Feb 07 18:44:22 imap(61286): Warning: Time moved forward 1386.259444 seconds Feb 07 19:11:41 master: Warning: Time moved forward by 615.609964 seconds - adjusting timeouts. Note the very large jump dovecot claims is happening in all of these, up to half an hour, with a minimum of 48 seconds in this bunch. You can see that it even does a pair of these in rapid succession, like at 17:25:39 above, and will do >10 within the space of an hour. These seem eventually to be followed by a crash ("eventually" because I'm running this on my laptop which isn't always open and running). The crash log entries all start with something like this: Feb 07 16:17:53 imap(58315): Panic: file ./time-util.h: line 40 (timeval_add_usecs): assertion failed: (usecs >= 0) The reports will end with one of these: Feb 06 17:45:07 log(48089): Warning: Killed with signal 15 (by pid=1 uid=0 code=unknown 0) Feb 07 16:17:53 imap(58317): Fatal: master: service(imap): child 58317 killed with signal 6 (core dumps disabled - https://dovecot.org/ bugreport.html#coredumps) One more detail, I usually do `sudo brew services start dovecot` to run dovecot and this results in the crashes. When I was testing this on Saturday, I started it with `sudo dovecot -F` instead, so that I would see problems in the terminal. It went all day without crashing and I finally stopped and restarted it with the brew method. That's not a rigorous test, but it is suggestive. Happy to provide more info, but I'm hoping this is sufficient to suggest a course of action. dovecot 2.4.0 installed via homebrew macOS 13.6.9 J
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org <OpenPGP_0xDD9B7A9E789E5A4F.asc>
I wonder if this is some power saving feature that pauses dovecot processes? Do
you have power saving enabled?
Aki
On 02/03/2025 16:10 EET John Muccigrosso via dovecot
<dovecot@dovecot.org> wrote:
These are pretty big drifts, like tens of minutes. Also note that a
bunch of corrections get logged within a second of each other. And
this is dovecot’s log.
I think I’d notice problems like that with the clock, but what’s the
best way for me to check? Is there another log that should track the
same thing?
J
Il giorno 2 mar 2025, alle ore 13:39, Tamsy via dovecot
<dovecot@dovecot.org> ha scritto:
Are you sure the real time on your Laptop is not drifting
(and eventually gets corrected by time.euro.apple.com just
to drift again)?
Depending on the type of laptop maybe the build-in RTC
doesn't keep the time as it should caused i.e. by a
depleted CMOS battery (note: No CMOS battery in portables
though).
I would do a SMC reset on that laptop. If this doesn't help
consider a NVRAM (or PRAM) reset.
Tamsy
John Muccigrosso via dovecot wrote on 02.03.2025 14:21:
Wondering if there's anyone who can help with this, which
is still happening.
Yesterday's crash in the logs:
>> Feb 26 15:55:07 imap(82011): Panic: file ./time-util.h:
line 40
(timeval_add_usecs): assertion failed: (usecs >= 0)
Thanks.
J
On Feb 15, 2025, at 11:18, John Muccigrosso
<muccigrosso@icloud.com>
-------- Original Message --------
From: John Muccigrosso via dovecot <dovecot@dovecot.org>
Sent: Sunday, March 2, 2025 at 2:21 PM UTC+7
To: dovecot@dovecot.org
Cc: Aki Tuomi <aki.tuomi@open-xchange.com>
Subject: RE: 2.4 crashing on macOS with time moving
forward?
Thanks.
It happens in various scenarios, including when I'm
actively working on the
computer (or it's at least not sleeping). It also happens
overnight when the
computer should be sleeping. It doesn't seem to happen on
resuming.
For example, here's this morning's (or late last night's)
when the laptop was
closed and sleeping:
Feb 14 22:58:02 master: Warning: Time moved forward by
282.937462
seconds - adjusting timeouts.
Feb 15 00:05:28 master: Panic: file ./time-util.h: line 40
(timeval_add_usecs): assertion failed: (usecs >= 0)
Feb 15 00:05:28 master: Error: Raw backtrace: 0
libdovecot.0.dylib
0x00000001009bb120 backtrace_append + 72 -> 1
libdovecot.0.dylib 0x00000001009bb264 backtrace_get
+ 44 -> 2 libdovecot.0.dylib 0x00000001009c9d54
default_fatal_finish + 72 -> 3 libdovecot.0.dylib
0x00000001009c87c4 default_error_handler + 0 -> 4
libdovecot.0.dylib 0x00000001009c8790
fatal_handler_real + 0 -> 5 dovecot
0x00000001006df538 master_fatal_callback + 248 -> 6
libdovecot.0.dylib 0x00000001009c8940 i_fatal + 0 -
> 7 libdovecot.0.dylib 0x00000001009e2724
ioloop_iolist_add + 0 -> 8 libdovecot.0.dylib
0x00000001009e0a3c io_loop_handle_timeouts + 640 -> 9
libdovecot.0.dylib 0x00000001009e3438
io_loop_handler_run_internal + 392 -> 10 libdovecot.0.dylib
0x00000001009e1130 io_loop_handler_run + 224 -> 11
libdovecot.0.dylib 0x00000001009e1000 io_loop_run +
92 -> 12 libdovecot.0.dylib 0x000000010093a22c
master_service_run + 28 -> 13 dovecot
0x00000001006dee28 main + 2952 -> 14 dyld
0x00000001a4747fd8 start + 2412
Feb 15 00:05:28 log(73755): Warning: Killed with signal 15
(by pid=1
uid=0 code=unknown 0)
Crash log below.
J
On Feb 15, 2025, at 10:32, Aki Tuomi <aki.tuomi@open-
xchange.com>
wrote:
Does this occur when resuming from suspend/hibernate? Also,
we do read this
list, it just sometimes takes time to react.
Aki
On 15/02/2025 11:13 EET J via dovecot <dovecot@dovecot.org>
wrote:
As this continues to happen and the list seems
uninterested, how
exactly should I report this bug?
Thanks.
J
On Feb 11, 2025, at 12:18, J wrote:
Further info: this whole "time moved forward" thing had a
long discussion and eventual fix in 2.3:
https://forums.freebsd.org/threads/dovecot-time-moved-
forwards.82886/page-2
For the record, how my clock compares with a standard:
sntp time.euro.apple.com
+0.109836 +/- 0.031550 time.euro.apple.com
17.253.14.251
So, first there seems to be a bug in this somewhere since
dovecot is clearly getting wrong time info. Then this also
seems related to dovecot eventually crashing on me.
J
On Feb 10, 2025, at 11:15, J wrote:
After last week's struggle with the new version
and my conf file, I got everything working. Now
however dovecot crashes on me every few hours.
The logs show a bunch of this kind of warning,
which I find mention of on the internets:
Feb 07 15:13:47 imap(58317): Warning:
Time moved forward 48.803640 seconds
Feb 07 16:30:27 master: Warning: Time
moved forward by 694.039203 seconds -
adjusting timeouts.
Feb 07 16:52:47 imap(61246): Warning:
Time moved forward 293.443011 seconds
Feb 07 16:52:47 master: Warning: Time
moved forward by 1279.423507 seconds -
adjusting timeouts.
Feb 07 17:25:39 imap(61286): Warning:
Time moved forward 1942.575589 seconds
Feb 07 17:25:39 imap(61288): Warning:
Time moved forward 172.563346 seconds
Feb 07 17:25:39 master: Warning: Time
moved forward by 1912.666999 seconds -
adjusting timeouts.
Feb 07 17:49:32 imap(61286): Warning:
Time moved forward 1402.761862 seconds
Feb 07 17:51:13 master: Warning: Time
moved forward by 1473.582569 seconds -
adjusting timeouts.
Feb 07 17:51:13 imap(61286): Warning:
Time moved forward 70.823888 seconds
Feb 07 17:53:07 master: Warning: Time
moved forward by 53.843767 seconds -
adjusting timeouts.
Feb 07 18:44:22 imap(61286): Warning:
Time moved forward 1386.259444 seconds
Feb 07 19:11:41 master: Warning: Time
moved forward by 615.609964 seconds -
adjusting timeouts.
Note the very large jump dovecot claims is
happening in all of these, up to half an hour,
with a minimum of 48 seconds in this bunch. You
can see that it even does a pair of these in
rapid succession, like at 17:25:39 above, and
will do >10 within the space of an hour.
These seem eventually to be followed by a crash
("eventually" because I'm running this on my
laptop which isn't always open and running). The
crash log entries all start with something like
this:
Feb 07 16:17:53 imap(58315): Panic:
file ./time-util.h: line 40
(timeval_add_usecs): assertion failed:
(usecs >= 0)
The reports will end with one of these:
Feb 06 17:45:07 log(48089): Warning:
Killed with signal 15 (by pid=1 uid=0
code=unknown 0)
Feb 07 16:17:53 imap(58317): Fatal:
master: service(imap): child 58317
killed with signal 6 (core dumps
disabled - https://dovecot.org/
bugreport.html#coredumps)
One more detail, I usually do sudo brew services start dovecot to run dovecot and this results in
the crashes. When I was testing this on Saturday,
I started it with sudo dovecot -F instead, so
that I would see problems in the terminal. It
went all day without crashing and I finally
stopped and restarted it with the brew method.
That's not a rigorous test, but it is suggestive.
Happy to provide more info, but I'm hoping this
is sufficient to suggest a course of action.
dovecot 2.4.0 installed via homebrew
macOS 13.6.9
J
_______________________________________________
dovecot mailing list -- dovecot@dovecot.org
To unsubscribe send an email to dovecot-leave@dovecot.org
<OpenPGP_0xDD9B7A9E789E5A4F.asc>
_______________________________________________
dovecot mailing list -- dovecot@dovecot.org
To unsubscribe send an email to dovecot-leave@dovecot.org
participants (3)
-
Aki Tuomi
-
John Muccigrosso
-
Tamsy