[Bug]: Multiple Scheduler components running at the same time?

[matthewjhands]

DO NOT REPORT VULNERABILITIES HERE!

• By checking this box I am confirming this issue is NOT a vulnerability.

Is there an existing issue for this?

• I have searched the existing issues

What happened?

Hello!

I think I've identified an issue where it looks like maybe there are multiple scheduler components (?) running at the same time within a long running (> 18 days) primary node? I'm not sure how this is happening, so I thought I would report it in the hopes that you may be able to identify the cause, or tell me what other info would be helpful so that we can figure this out.

The good news is that a restart of the long running primary makes the below symptoms go away. Note that we do run Cronicle as non-root, but I doubt that's related to this issue.

There are at least 4 symptoms:

1. Duplicate listings of jobs in the completed log.

2. "Maximum of 1 job already running for event" errors for a multiplex "Primary Group" job. The Primary was trying to run 3 instances of the scheduled job on itself, which doesn't allow Concurrency (It is a singleton event). Note that we only see this behaviour for scheduled jobs, not when it is manually invoked.
3. Triplicate "Advancing time up to..." log lines, seen in extract at the end of this report.
4. I'm pretty sure this issue caused the primary node to crash yesterday, because it tried to fetch logs for the same job from the same worker 3 times, causing an unhandled exception when scheduler components numbers 2 and 3 couldn't find the now deleted log file.

[1769609632.078][2026-01-28 15:13:52][old_primary.example][2129][Cronicle][debug][5][Job log was fetched successfully][https://a-worker.example:8443/api/app/fetch_delete_job_log?path=%2
Fopt%2Fcronicle%2Flogs%2Fjobs%2Fjmkucjcl140.log&auth=1c3cb0xxxxxxxxxxxxxxxxxxxxx]
[1769609632.078][2026-01-28 15:13:52][old_primary.example][2129][Cronicle][debug][5][Job log was fetched successfully][https://a-worker.example:8443/api/app/fetch_delete_job_log?path=%2
Fopt%2Fcronicle%2Flogs%2Fjobs%2Fjmkucjcl140.log&auth=1c3cb0xxxxxxxxxxxxxxxxxxxxx]
[1769609632.084][2026-01-28 15:13:52][old_primary.example][2129][Cronicle][debug][5][Job log was fetched successfully][https://a-worker.example:8443/api/app/fetch_delete_job_log?path=%2
Fopt%2Fcronicle%2Flogs%2Fjobs%2Fjmkucjcl140.log&auth=1c3cb0xxxxxxxxxxxxxxxxxxxxx]
[1769609632.138][2026-01-28 15:13:52][old_primary.example][2129][Cronicle][debug][1][Uncaught Exception: Error: ENOENT: no such file or directory, open 'logs/jobs/jmkucjcl140.log.gz'][Error: ENOENT: no such file or directory, open 'logs/jobs/jmkucjcl140.log.gz']
[1769609632.138][2026-01-28 15:13:52][old_primary.example][2129][Cronicle][debug][1][Emergency Shutdown: Error: ENOENT: no such file or directory, open 'logs/jobs/jmkucjcl140.log.gz'][]

Hopefully the above info will be useful to you identifying a cause, but let me know if you require further info.

Thanks,
Matt

Operating System

RHEL 8

Node.js Version

v18.20.8

Cronicle Version

v0.9.99

Server Setup

Multi-Primary with Workers

Storage Setup

NFS Filesystem

Relevant log output

[1769561700.051][2026-01-28 01:55:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:55:00][]
[1769561700.052][2026-01-28 01:55:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:55:00][]
[1769561700.052][2026-01-28 01:55:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:55:00][]
[1769561760.003][2026-01-28 01:56:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:56:00][]
[1769561760.003][2026-01-28 01:56:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:56:00][]
[1769561760.004][2026-01-28 01:56:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:56:00][]
[1769561820.086][2026-01-28 01:57:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:57:00][]
[1769561820.087][2026-01-28 01:57:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:57:00][]
[1769561820.087][2026-01-28 01:57:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:57:00][]
[1769561880.087][2026-01-28 01:58:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:58:00][]
[1769561880.087][2026-01-28 01:58:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:58:00][]
[1769561880.087][2026-01-28 01:58:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:58:00][]
[1769561940.072][2026-01-28 01:59:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:59:00][]
[1769561940.073][2026-01-28 01:59:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:59:00][]
[1769561940.073][2026-01-28 01:59:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 01:59:00][]
[1769562000.023][2026-01-28 02:00:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 02:00:00][]
[1769562000.023][2026-01-28 02:00:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 02:00:00][]
[1769562000.023][2026-01-28 02:00:00][old_primary.example][2129][Cronicle][debug][4][Scheduler Minute Tick: Advancing time up to: 2026/01/28 02:00:00][]

Code of Conduct

• I agree to follow this project's Code of Conduct

[jhuckaby]

Hmmm... this is quite a mystery...

Are you running a vanilla version of Cronicle, or a fork? I ask because what you are seeing in the logs should NEVER happen, under any circumstances whatsoever.

I cannot fathom how this could possibly occur. It's a truly bizarre one.

I will fix the crasher bug of course, but the triplicate scheduler tick log messages, all from the same PID, is practically "impossible". I'm really struggling to come up with ideas there, and I've certainly never seen such a thing before.

Ah, you do have a multi-master cluster... okay... it sounds like you have a situation where one of your servers is becoming primary multiple times... that COULD possibly explain some of this...

Can you please check your Cronicle.log log file (and archives) for matches to this string:

We are becoming the master server

So...

# current log
grep "We are becoming the master server" /opt/cronicle/logs/Cronicle.log

# log archives
gzip -cd /opt/cronicle/logs/archives/*/*/*/Cronicle.log.gz | grep "We are becoming the master server"

Please let me know, and paste the results here if you can. Or you can email them to me at jhuckaby AT pixlcore DOT com.

I'm curious if you see multiple entries matching this on the same PID.

Thanks!

[jhuckaby]

Oh, can I have your crash.log too? I'd love to see a stack trace of where that crasher is occurring. Thanks so much for your help!

[mikeTWC1984]

I've seen this behavior on my fork (cronicle-edge). It started after I did sync up some changes from 0.9.9X versions. I'm not sure what exactly was causing it, but the only somewhat related thing was this:
9f99565
After rolling it back, I've never seen this problem. However, later I tried go back to "broken" version to do thorough debugging , and couldn't reproduce it either. So master node restart might help also.
Btw, I always use single master node, so likely not related to multi-master mode.

[jhuckaby]

Thanks @mikeTWC1984 -- that's good information.

How odd -- you're seeing this with a SINGLE master server? Wow 😳. Okay, maybe I'm barking up the wrong tree here.

Hmmm, that commit of mine is so... benign? All I'm doing is adding crash protection around closing a filehandle that may have gone bad. I cannot fathom how that could cause the scheduler to go berserk.

I am fairly certain the problem is that setupScheduler() is getting called twice (or in Matthew's case 3 times), and that function is only ever called from becomeMaster(), which makes me think that somehow a server is getting promoted to master multiple times in the same process.

I can add some basic protection against this, but I'd love to know more before blinding making changes. Curious what Matthew's logs show.

Thanks!

[matthewjhands]

Hi @jhuckaby

Thanks - here is the info you requested:

Primary:

logs/archives/2025/04/12/Cronicle-2025-04-12.log.gz:[1744481568.092][2025-04-12 20:12:48][old_primary.example][1689][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/04/13/Cronicle-2025-04-13.log.gz:[1744502473.103][2025-04-13 02:01:13][old_primary.example][1714][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/04/26/Cronicle-2025-04-26.log.gz:[1745691279.03][2025-04-26 20:14:39][old_primary.example][1711][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/04/27/Cronicle-2025-04-27.log.gz:[1745712090.062][2025-04-27 02:01:30][old_primary.example][1680][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/05/11/Cronicle-2025-05-11.log.gz:[1746921690.109][2025-05-11 02:01:30][old_primary.example][1699][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/05/20/Cronicle-2025-05-20.log.gz:[1747743513.038][2025-05-20 14:18:33][old_primary.example][758055][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/05/24/Cronicle-2025-05-24.log.gz:[1748110783.119][2025-05-24 20:19:43][old_primary.example][1699][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/05/25/Cronicle-2025-05-25.log.gz:[1748131303.069][2025-05-25 02:01:43][old_primary.example][1668][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/06/15/Cronicle-2025-06-15.log.gz:[1749945691.086][2025-06-15 02:01:31][old_primary.example][2170][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/06/28/Cronicle-2025-06-28.log.gz:[1751134448.022][2025-06-28 20:14:08][old_primary.example][1693][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/06/29/Cronicle-2025-06-29.log.gz:[1751155292.089][2025-06-29 02:01:32][old_primary.example][1722][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/01/Cronicle-2025-07-01.log.gz:[1751363165.092][2025-07-01 11:46:05][old_primary.example][181506][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/01/Cronicle-2025-07-01.log.gz:[1751367696.043][2025-07-01 13:01:36][old_primary.example][186214][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/01/Cronicle-2025-07-01.log.gz:[1751372315.033][2025-07-01 14:18:35][old_primary.example][190931][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/07/Cronicle-2025-07-07.log.gz:[1751891926.021][2025-07-07 14:38:46][old_primary.example][708014][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/08/Cronicle-2025-07-08.log.gz:[1751982780.075][2025-07-08 15:53:00][old_primary.example][795550][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/13/Cronicle-2025-07-13.log.gz:[1752364880.045][2025-07-13 02:01:20][old_primary.example][1684][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/18/Cronicle-2025-07-18.log.gz:[1752847233.021][2025-07-18 16:00:33][old_primary.example][449251][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/26/Cronicle-2025-07-26.log.gz:[1753553788.073][2025-07-26 20:16:28][old_primary.example][1712][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/27/Cronicle-2025-07-27.log.gz:[1753574503.053][2025-07-27 02:01:43][old_primary.example][1736][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/08/07/Cronicle-2025-08-07.log.gz:[1754579049.049][2025-08-07 17:04:09][old_primary.example][1031197][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/08/10/Cronicle-2025-08-10.log.gz:[1754784172.113][2025-08-10 02:02:52][old_primary.example][2039][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/08/23/Cronicle-2025-08-23.log.gz:[1755973165.057][2025-08-23 20:19:25][old_primary.example][1956][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/08/24/Cronicle-2025-08-24.log.gz:[1755993699.083][2025-08-24 02:01:39][old_primary.example][1927][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/09/14/Cronicle-2025-09-14.log.gz:[1757808102.089][2025-09-14 02:01:42][old_primary.example][1908][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/09/27/Cronicle-2025-09-27.log.gz:[1758996930.111][2025-09-27 20:15:30][old_primary.example][1907][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/09/28/Cronicle-2025-09-28.log.gz:[1759017702.101][2025-09-28 02:01:42][old_primary.example][1903][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/10/25/Cronicle-2025-10-25.log.gz:[1761416450.028][2025-10-25 20:20:50][old_primary.example][1922][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/10/25/Cronicle-2025-10-25.log.gz:[1761422137.049][2025-10-25 21:55:37][old_primary.example][93148][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/10/26/Cronicle-2025-10-26.log.gz:[1761436915.045][2025-10-26 02:01:55][old_primary.example][2029][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/03/Cronicle-2025-11-03.log.gz:[1762176668.084][2025-11-03 14:31:08][old_primary.example][2033][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/03/Cronicle-2025-11-03.log.gz:[1762185548.037][2025-11-03 16:59:08][old_primary.example][21619][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/09/Cronicle-2025-11-09.log.gz:[1762646477.101][2025-11-09 01:01:17][old_primary.example][2007][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763510902.052][2025-11-19 01:08:22][old_primary.example][2007][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763511859.041][2025-11-19 01:24:19][old_primary.example][2002647][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763512387.064][2025-11-19 01:33:07][old_primary.example][2002647][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763513564.1][2025-11-19 01:52:44][old_primary.example][2004223][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763514107.052][2025-11-19 02:01:47][old_primary.example][2004223][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/22/Cronicle-2025-11-22.log.gz:[1763835627.097][2025-11-22 19:20:27][old_primary.example][2332641][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/22/Cronicle-2025-11-22.log.gz:[1763835749.076][2025-11-22 19:22:29][old_primary.example][2026][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/23/Cronicle-2025-11-23.log.gz:[1763856113.035][2025-11-23 01:01:53][old_primary.example][2033][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/12/27/Cronicle-2025-12-27.log.gz:[1766859374.068][2025-12-27 19:16:14][old_primary.example][2052][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/12/28/Cronicle-2025-12-28.log.gz:[1766880113.031][2025-12-28 01:01:53][old_primary.example][2121][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/09/Cronicle-2026-01-09.log.gz:[1767978429.046][2026-01-09 18:07:09][old_primary.example][2181][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/11/Cronicle-2026-01-11.log.gz:[1768089698.073][2026-01-11 01:01:38][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/17/Cronicle-2026-01-17.log.gz:[1768610613.009][2026-01-17 01:43:33][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/26/Cronicle-2026-01-26.log.gz:[1769466186.094][2026-01-26 23:23:06][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/28/Cronicle-2026-01-28.log.gz:[1769609703.017][2026-01-28 15:15:03][old_primary.example][3281077][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/29/Cronicle-2026-01-29.log.gz:[1769696563.032][2026-01-29 15:22:43][old_primary.example][3312861][Cronicle][debug][3][We are becoming the master server][]

Backup (it is the only one):

logs/archives/2025/03/19/Cronicle-2025-03-19.log.gz:[1742401076.346][2025-03-19 17:17:56][backup.example][818281][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/03/19/Cronicle-2025-03-19.log.gz:[1742401799.121][2025-03-19 17:29:59][backup.example][902862][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/01/Cronicle-2025-07-01.log.gz:[1751371879.078][2025-07-01 14:11:19][backup.example][190467][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/07/01/Cronicle-2025-07-01.log.gz:[1751372089.061][2025-07-01 14:14:49][backup.example][190802][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/08/06/Cronicle-2025-08-06.log.gz:[1754468943.116][2025-08-06 10:29:03][backup.example][1862][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/03/Cronicle-2025-11-03.log.gz:[1762176848.085][2025-11-03 14:34:08][backup.example][10528][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763510522.133][2025-11-19 01:02:02][backup.example][2006][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763511787.091][2025-11-19 01:23:07][backup.example][783426][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/19/Cronicle-2025-11-19.log.gz:[1763513492.06][2025-11-19 01:51:32][backup.example][784858][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/11/20/Cronicle-2025-11-20.log.gz:[1763646147.137][2025-11-20 14:42:27][backup.example][993042][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2025/12/14/Cronicle-2025-12-14.log.gz:[1765670498.088][2025-12-14 01:01:38][backup.example][2325][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/17/Cronicle-2026-01-17.log.gz:[1768610463.065][2026-01-17 01:41:03][backup.example][2260][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/26/Cronicle-2026-01-26.log.gz:[1769466046.054][2026-01-26 23:20:46][backup.example][519452][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/28/Cronicle-2026-01-28.log.gz:[1769617543.241][2026-01-28 17:25:43][backup.example][1448852][Cronicle][debug][3][We are becoming the master server][]

Primary (old_primary.example - poor choice of placeholder name but there you go..) Crash logs:

Wed Jan 28 2026 15:13:52 GMT+0100 (Central European Standard Time) - old_primary.example - PID 2129
Error: ENOENT: no such file or directory, open 'logs/jobs/jmkucjcl140.log.gz'

[jhuckaby]

Thank you so much!

BINGO:

logs/archives/2026/01/11/Cronicle-2026-01-11.log.gz:[1768089698.073][2026-01-11 01:01:38][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/17/Cronicle-2026-01-17.log.gz:[1768610613.009][2026-01-17 01:43:33][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]
logs/archives/2026/01/26/Cronicle-2026-01-26.log.gz:[1769466186.094][2026-01-26 23:23:06][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]

Look at that. The server became master 3 times, and all from the same PID (same process).

Well that's a huge smoking gun right there.

I will dig deeper into this right away.

Thanks again.

[jhuckaby]

Okay, I've been studying this for hours, and frankly there is only one possible way this situation could ever occur, and that is with multiple servers with a shared filesystem that is not working properly (or fails on some servers but not others). For e.g. an NFS mount that is not setup properly on all the Cronicle servers, or some kind of 3rd party storage backend where only SOME of the servers have proper read/write access to it.

A Cronicle server should only ever be promoted to master "once". It is never demoted after that happens. UNLESS... another server in the cluster thinks that IT is, in fact, the master, and tells the other servers so. This can only happen with a misconfigured storage system, because all servers should all agree on who is master (it's based on an alphabetical sort of the hostnames).

I suppose one other way it could happen is if two or more servers in the cluster have identical hostnames. That is also a very, VERY bad situation for a cluster system that uses the hostname as the "primary key".

I have released Cronicle v0.9.103 which detects this situation as it occurs, and logs a VERY loud error with full stack trace, then exits.

Honestly, shutting down is much better than allowing it to continue on, because at this point the cluster is "broken", and you have multiple servers who have different ideas on who is the current master. This will highly likely result in data corruption as multiple servers all try to write records at the same time, etc. etc. So shutting down before you get into a duplicate master situation is the best course of action.

The error does include a full stack trace, so if this does happen again, I'd love to see what the call stack looks like.

I would also recommend you run the Storage Repair script right away. I'll bet it finds one or more corrupted records.

Thanks for your help on this! It's quite a weird one, but I have a strong suspicion it is a misbehaving storage backend (NFS in your case), or 2+ servers with identical hostnames.

[matthewjhands]

Thanks @jhuckaby . I've done some staring at the logs - and I think I might be on to something. When a "master" server becomes a "slave", is the Cronicle daemon properly giving up all of it's primary responsibilities? I think the issue is that when the daemon calls goSlave() then shutdownScheduler() (or something with a similar effect) isn't been called. I've attached logs I think illustrates this, when the connection between the two primaries is temporarily lost.

logs sanitised.txt

As an aside - I stopped our Primaries this morning (not the workers - they don't have NFS access anyway), and couldn't find any issues in dryrun mode.

[jhuckaby]

When a "master" server becomes a "slave", is the Cronicle daemon properly giving up all of it's primary responsibilities?

Well, if by "master" you mean the current primary master, then it should actually never be demoted. Once an eligible server is promoted to master primary, it should never become a worker after that point. It will remain master until the moment it is shut down.

I think the issue is that when the daemon calls goSlave() then shutdownScheduler() (or something with a similar effect) isn't been called.

Ah, you see, there is the sticking point. There is no shutdownScheduler(). It doesn't exist -- because a server should never, ever be demoted to a worker. There is no code path that allows a primary master to "downgrade" or "demote" itself to a worker.

That may be our core issue right there. There may be a set of circumstances where your primary master is SOMEHOW getting demoted to a worker server after it was previously promoted to primary -- which should be impossible 😝

So, I think the problem is that you have multiple eligible servers, and they each have a different idea on who should become master primary, so they clash and create a conflict. The only feasible way I can imagine this happening is:

• if two or more servers have the same hostname, or
• your NFS storage system is misconfigured on one or more of the servers.
• A related issue could be that the Cronicle /opt/cronicle/conf/config.json files are not identical, i.e. the storage "base directory" may be different, or some of the settings in there.

Thank you for the logs! Okay, look at this snippet right here:

[1768089698.073][2026-01-11 01:01:38][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]

Then... same PID, same server, 42 minutes later...

[1768610553.186][2026-01-17 01:42:33][old_primary.example][2129][Cronicle][debug][3][We are becoming a slave server][]

Yikes 😳

Okay, so this is a really bad situation. It is one of those things that should NEVER happen. I'm just flummoxed.

Your two servers, old_primary and backup, both seem to know about each other, so they are working off a correct cluster configuration:

[1768089698.073][2026-01-11 01:01:38][old_primary.example][2129][Cronicle][debug][3][We are becoming the master server][]
[1768089698.194][2026-01-11 01:01:38][old_primary.example][2129][Cronicle][debug][5][Adding slave to cluster: backup.example (10.XXX.XXX.162)][]

And:

[1768610463.065][2026-01-17 01:41:03][backup.example][2260][Cronicle][debug][3][We are becoming the master server][]
[1768610463.106][2026-01-17 01:41:03][backup.example][2260][Cronicle][debug][5][Adding slave to cluster: old_primary.example (10.XXX.XXX.35)][]

So I guess that eliminates one of my possible theories. The problem then comes down to this, I believe:

[1768089698.047][2026-01-11 01:01:38][old_primary.example][2129][Cronicle][debug][3][No master ping received within 60 seconds, choosing new master][]

And:

[1768610458.008][2026-01-17 01:40:58][backup.example][2260][Cronicle][debug][3][No master ping received within 60 seconds, choosing new master][]

Basically, the ping system is not working.

This seems to be happening on BOTH of your servers, when they are workers. The ping system just doesn't seem to work. I am struggling really hard to figure out why.

I will add protection against this "demotion from primary to worker" situation, but.... that's only putting a band-aid over a broken arm. We need to solve the core issue here.

Somehow your servers know about each other, but then they do not or cannot send pings to each other. So they both failover and create a conflict. It is very confusing.

What I'd like to try next is have you adjust these, in your config.json files on both of your servers:

"master_ping_freq": 20,
"master_ping_timeout": 60,

Those are the defaults, so it allows for 2 missed pings before it fails over. Let's change these to:

"master_ping_freq": 5,
"master_ping_timeout": 120,

So it will send a ping every 5 seconds, and allow up to 120 seconds before failing over. Maybe your network just has a lot of dropped packets or something?

Can you try a long-running ping from old_primary.example to backup.example? Let it run for 5 minutes, then Ctrl-C and see how many dropped packets.

In the meantime, I'll add protection against the code path that causes a master primary server to suddenly demote itself to a worker.

Thanks for all this info!

[jhuckaby]

Released Cronicle v0.9.105

[mikeTWC1984]

I suppose one other way it could happen is if two or more servers in the cluster have identical hostnames. That is also a very, VERY bad situation for a cluster system that uses the hostname as the "primary key".

Hm, that might explain my situation, when I got same behavior using just a single master node. I run my cluster in kubernetes, it might reschedule running apps between kubernetes nodes, so perhaps it started new instance, while not killing another fully, so there was 2 primary nodes at the same time.

[matthewjhands]

Thanks for this @jhuckaby .

I think code protections against demotion is definitely a good thing - what will happen now to a primary that gets demoted? Will the daemon just restart?

We are operating Cronicle in a large network environment, so it is entirely possible that over a period of many weeks that there will be a few dropped pings here and there as network maintenance/failovers etc are performed.

We will upgrade to the latest release and increase our ping frequency and timeouts, and keep you posted. We're also going to add weekly restarts to our daemons too.

Many thanks again.

[jhuckaby]

Thank you, @matthewjhands for all your help in debugging this one. I don't think it's 100% solved yet, but my latest changes will:

• Detect if a server becomes master twice (i.e. twice in the same process)
• Detect if a master server is asked to be demoted to a backup server by an authenticated master in the same cluster.

Both of these situations are unfortunately quite fatal. This means something has gone terribly wrong in the cluster, and multiple servers all think they are master at the same time. If this is allowed to continue, it will result in data corruption (which is often difficult to repair).

So what I am doing is logging a VERY loud error when either of these situations occur, and shutting down the service on the server where the problem was detected.

(Note: This will not shut down Cronicle on ALL your servers -- just the one where the situation was detected)

I think the key in fixing this for you is increasing your socket ping frequency and ping timeout values, because those pings are really the lifeline (heartbeat) of the system. The multi-master system totally relies on those pings.

If the WebSocket pings aren't making it to the other servers in the cluster (which is what we're seeing in your logs), then we've got a much greater problem to solve.

Did you ever try that CLI ping test between your two master servers to see if you are experiencing packet loss? Run it for multiple minutes then Ctrl-C it. Because it really looks like something terrible is happening here, on a network level.

Anyway, let me know how 5 / 120 goes! I think that may help you, but the thing is, if you have an underlying network issue that is causing packet loss, then that is the root issue we really need to solve.