Monitors are stopped after `database is locked` error #3130

deluxghost · 2023-05-06T09:13:18Z

⚠️ Please verify that this bug has NOT been raised before.

I checked and didn't find similar issue

🛡️ Security Policy

I agree to have read this project Security Policy

Description

I have updated uptime kuma to the latest version recently. I use push monitors only, they are all created in an old version.

One day my push clients are offline for about 1 hour because my local firewall, but when I check the uptime dashboard, there is no DOWN record at all.

The heartbeat intervals of monitors are 60s/30s an retry is 5/3, they should go down in 5mins normally without any push request.

the chart of affected monitors looks like this:

I stopped the push client for about 10 mins, no request in the period. In chart, there is no data in the period too but it's green all the time.

Editing an affected monitor without actually changing any settings and saving directly will fix this issue for that one monitor. (Mumble in the logs below)

New monitor (test in the logs below) works well

👟 Reproduction steps

updated from an old version with push monitors (I cant remember the actual version, sorry)
stop the push client
wait until the monitor should go down
it's not going down
start the push client
you can see the missing data in chart, but no down event

👀 Expected behavior

push monitors from old version should work as expected (going down without push requests) without re-saving

😓 Actual Behavior

such monitors never going down

🐻 Uptime-Kuma Version

1.21.2

💻 Operating System and Arch

Ubuntu 20.04.5 LTS

🌐 Browser

Chrome 112.0.5615.49

🐋 Docker Version

20.10.18

🟩 NodeJS Version

No response

📝 Relevant log output

uptime-kuma  | 2023-05-06T03:14:01+08:00 [PLUGIN] WARN: Warning: In order to enable plugin feature, you need to use the default data directory: ./data/
uptime-kuma  | 2023-05-06T03:14:01+08:00 [DB] INFO: Data Dir: data/
uptime-kuma  | 2023-05-06T03:14:02+08:00 [DB] INFO: SQLite config:
uptime-kuma  | [ { journal_mode: 'wal' } ]
uptime-kuma  | [ { cache_size: -12000 } ]
uptime-kuma  | 2023-05-06T03:14:02+08:00 [DB] INFO: SQLite Version: 3.41.1
uptime-kuma  | {
uptime-kuma  |   name: 'clear-old-data',
uptime-kuma  |   message: 'Clearing Data older than 180 days...'
uptime-kuma  | }
uptime-kuma  | { name: 'clear-old-data', message: 'done' }
uptime-kuma  | 2023-05-06T14:52:29+08:00 [AUTH] INFO: Login by token. IP=#############
uptime-kuma  | 2023-05-06T14:52:29+08:00 [AUTH] INFO: Username from JWT: #############
uptime-kuma  | 2023-05-06T14:52:29+08:00 [AUTH] INFO: Successfully logged in user #############. IP=#############
uptime-kuma  | 2023-05-06T16:05:55+08:00 [AUTH] INFO: Login by token. IP=#############
uptime-kuma  | 2023-05-06T16:05:55+08:00 [AUTH] INFO: Username from JWT: #############
uptime-kuma  | 2023-05-06T16:05:55+08:00 [AUTH] INFO: Successfully logged in user #############. IP=#############
uptime-kuma  | 2023-05-06T16:07:02+08:00 [MONITOR] INFO: Get Monitor: 12 User ID: 1
uptime-kuma  | 2023-05-06T16:08:30+08:00 [AUTH] INFO: Login by token. IP=#############
uptime-kuma  | 2023-05-06T16:08:30+08:00 [AUTH] INFO: Username from JWT: #############
uptime-kuma  | 2023-05-06T16:08:30+08:00 [AUTH] INFO: Successfully logged in user #############. IP=#############
uptime-kuma  | 2023-05-06T16:08:37+08:00 [MONITOR] INFO: Get Monitor: 12 User ID: 1
uptime-kuma  | 2023-05-06T16:09:18+08:00 [MANAGE] INFO: Resume Monitor: 28 User ID: 1
uptime-kuma  | 2023-05-06T16:09:18+08:00 [MONITOR] INFO: Added Monitor: undefined User ID: 1
uptime-kuma  | 2023-05-06T16:09:27+08:00 [MONITOR] INFO: Get Monitor: 28 User ID: 1
uptime-kuma  | 2023-05-06T16:09:38+08:00 [MONITOR] WARN: Monitor #28 'test': Pending: No heartbeat in the time window | Max retries: 1 | Retry: 1 | Retry Interval: 20 seconds | Type: push
uptime-kuma  | 2023-05-06T16:10:06+08:00 [MONITOR] WARN: Monitor #28 'test': Pending: No heartbeat in the time window | Max retries: 1 | Retry: 1 | Retry Interval: 20 seconds | Type: push
uptime-kuma  | 2023-05-06T16:10:08+08:00 [MONITOR] INFO: Get Monitor: 12 User ID: 1
uptime-kuma  | 2023-05-06T16:10:26+08:00 [MONITOR] WARN: Monitor #28 'test': Failing: No heartbeat in the time window | Interval: 20 seconds | Type: push | Down Count: 0 | Resend Interval: 0
uptime-kuma  | 2023-05-06T16:10:34+08:00 [MANAGE] INFO: Delete Monitor: 28 User ID: 1
uptime-kuma  | 2023-05-06T16:10:38+08:00 [MONITOR] INFO: Get Monitor: 12 User ID: 1
uptime-kuma  | 2023-05-06T16:10:43+08:00 [MANAGE] INFO: Resume Monitor: 12 User ID: 1
uptime-kuma  | 2023-05-06T16:10:43+08:00 [MONITOR] INFO: Get Monitor: 12 User ID: 1
uptime-kuma  | 2023-05-06T16:11:13+08:00 [MONITOR] WARN: Monitor #12 'Mumble': Pending: No heartbeat in the time window | Max retries: 3 | Retry: 1 | Retry Interval: 30 seconds | Type: push
uptime-kuma  | 2023-05-06T16:11:43+08:00 [MONITOR] WARN: Monitor #12 'Mumble': Pending: No heartbeat in the time window | Max retries: 3 | Retry: 2 | Retry Interval: 30 seconds | Type: push
uptime-kuma  | 2023-05-06T16:12:07+08:00 [MONITOR] INFO: Get Monitor: 8 User ID: 1
uptime-kuma  | 2023-05-06T16:12:12+08:00 [MONITOR] INFO: Get Monitor: 26 User ID: 1
uptime-kuma  | 2023-05-06T16:12:13+08:00 [MONITOR] WARN: Monitor #12 'Mumble': Pending: No heartbeat in the time window | Max retries: 3 | Retry: 3 | Retry Interval: 30 seconds | Type: push
uptime-kuma  | 2023-05-06T16:12:24+08:00 [MONITOR] INFO: Get Monitor: 14 User ID: 1
uptime-kuma  | 2023-05-06T16:12:44+08:00 [MONITOR] WARN: Monitor #12 'Mumble': Failing: No heartbeat in the time window | Interval: 30 seconds | Type: push | Down Count: 0 | Resend Interval: 0
uptime-kuma  | 2023-05-06T16:13:16+08:00 [MONITOR] INFO: Get Monitor Beats: 11 User ID: 1
uptime-kuma  | 2023-05-06T16:13:33+08:00 [MONITOR] INFO: Get Monitor Beats: 11 User ID: 1
uptime-kuma  | 2023-05-06T16:14:00+08:00 [AUTH] INFO: Login by token. IP=#############
uptime-kuma  | 2023-05-06T16:14:00+08:00 [AUTH] INFO: Username from JWT: #############
uptime-kuma  | 2023-05-06T16:14:00+08:00 [AUTH] INFO: Successfully logged in user #############. IP=#############
uptime-kuma  | 2023-05-06T16:45:11+08:00 [MONITOR] INFO: Get Monitor Beats: 11 User ID: 1
uptime-kuma  | 2023-05-06T16:45:14+08:00 [MONITOR] INFO: Get Monitor Beats: 11 User ID: 1
uptime-kuma  | 2023-05-06T16:56:42+08:00 [MONITOR] INFO: Get Monitor: 11 User ID: 1

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

chakflying · 2023-05-06T12:57:24Z

Does the issue reappear if you restart the server?

deluxghost · 2023-05-06T13:18:27Z

Does the issue reappear if you restart the server?

I think I restarted the server during the updating process... but yeah, restarting the server seems to fix this issue

deluxghost · 2023-05-14T08:20:16Z

Does the issue reappear if you restart the server?

weird, I think I have already restarted the server, but when I shutted down one of my node yesterday, the issue is still there. All services on the node should go down but not

chakflying · 2023-05-14T09:01:10Z

Unfortunately a lot of the useful logging are hidden unless you run with NODE_ENV=development. Is this the same monitor that you previously "Saved without changing", or is this another one?

I thought about this but there really shouldn't be any database changes that would affect the behavior of the push monitor.

deluxghost · 2023-05-14T09:30:15Z

Ah, so I need to add the variable to my compose file to get more info. I will do more test later

deluxghost · 2023-05-18T08:48:48Z

Looks like it might not be about the version. I have enabled debug logs, and noticed some of the monitors gone after these errors:

^^^ There are more same errors above ^^^


uptime-kuma  | Trace: [Error: insert into `heartbeat` (`down_count`, `duration`, `important`, `monitor_id`, `msg`, `status`, `time`) values (0, 61, false, 8, 'No heartbeat in the time window', 2, '2023-05-17 19:14:33.005') - SQLITE_BUSY: database is locked] {
uptime-kuma  |   errno: 5,
uptime-kuma  |   code: 'SQLITE_BUSY'
uptime-kuma  | }
uptime-kuma  |     at process.<anonymous> (/app/server/server.js:1804:13)
uptime-kuma  |     at process.emit (node:events:513:28)
uptime-kuma  |     at emit (node:internal/process/promises:140:20)
uptime-kuma  |     at processPromiseRejections (node:internal/process/promises:274:27)
uptime-kuma  |     at processTicksAndRejections (node:internal/process/task_queues:97:32)
uptime-kuma  | If you keep encountering errors, please report to https://github.com/louislam/uptime-kuma/issues
uptime-kuma  | Trace: [Error: insert into `heartbeat` (`down_count`, `duration`, `important`, `monitor_id`, `msg`, `status`, `time`) values (0, 62, false, 10, 'No heartbeat in the time window', 2, '2023-05-17 19:14:34.030') - SQLITE_BUSY: database is locked] {
uptime-kuma  |   errno: 5,
uptime-kuma  |   code: 'SQLITE_BUSY'
uptime-kuma  | }
uptime-kuma  |     at process.<anonymous> (/app/server/server.js:1804:13)
uptime-kuma  |     at process.emit (node:events:513:28)
uptime-kuma  |     at emit (node:internal/process/promises:140:20)
uptime-kuma  |     at processPromiseRejections (node:internal/process/promises:274:27)
uptime-kuma  |     at processTicksAndRejections (node:internal/process/task_queues:97:32)
uptime-kuma  | If you keep encountering errors, please report to https://github.com/louislam/uptime-kuma/issues
uptime-kuma  | Trace: [Error: insert into `heartbeat` (`down_count`, `duration`, `important`, `monitor_id`, `msg`, `status`, `time`) values (0, 62, false, 1, 'No heartbeat in the time window', 2, '2023-05-17 19:14:34.033') - SQLITE_BUSY: database is locked] {
uptime-kuma  |   errno: 5,
uptime-kuma  |   code: 'SQLITE_BUSY'
uptime-kuma  | }
uptime-kuma  |     at process.<anonymous> (/app/server/server.js:1804:13)
uptime-kuma  |     at process.emit (node:events:513:28)
uptime-kuma  |     at emit (node:internal/process/promises:140:20)
uptime-kuma  |     at processPromiseRejections (node:internal/process/promises:274:27)
uptime-kuma  |     at processTicksAndRejections (node:internal/process/task_queues:97:32)
uptime-kuma  | If you keep encountering errors, please report to https://github.com/louislam/uptime-kuma/issues
uptime-kuma  | 2023-05-18T03:14:56+08:00 [UPTIMECACHELIST] DEBUG: clearCache: 10
uptime-kuma  | 2023-05-18T03:14:56+08:00 [MONITOR] DEBUG: No clients in the room, no need to send stats
uptime-kuma  | { name: 'clear-old-data', message: 'done' }
uptime-kuma  | 2023-05-18T03:14:56+08:00 [UPTIMECACHELIST] DEBUG: clearCache: 1
uptime-kuma  | 2023-05-18T03:14:56+08:00 [MONITOR] DEBUG: No clients in the room, no need to send stats
uptime-kuma  | 2023-05-18T03:14:56+08:00 [ROUTER] DEBUG: /api/push/ called at 2023-05-18 03:14:56.428

I'm using docker local bind (/local/path:/app/data), my db preserve setting is 180 days, and current db size is about 1400M

I have seen another database is locked error before, but the log messages are different:

uptime-kuma  | Trace: [Error: insert into `heartbeat` (`down_count`, `duration`, `important`, `monitor_id`, `msg`, `status`, `time`) values (0, 61, false, 21, 'No heartbeat in the time window', 0, '2023-05-16 19:14:25.968') - SQLITE_BUSY: database is locked] {
uptime-kuma  |   errno: 5,
uptime-kuma  |   code: 'SQLITE_BUSY'
uptime-kuma  | }
uptime-kuma  |     at Timeout.safeBeat [as _onTimeout] (/app/server/model/monitor.js:811:25)
uptime-kuma  | 2023-05-17T03:14:35+08:00 [MONITOR] INFO: Try to restart the monitor

one of the message mentioned the monitor is restarted, another message didn't

after the batch of errors, I haven't seen the Checking monitor at <date time> of most of the monitors

deluxghost · 2023-05-18T08:55:46Z

The two error handlers:

uptime-kuma/server/server.js

Lines 1802 to 1807 in 9dc02bb

    
           // Catch unexpected errors here 
        
           process.addListener("unhandledRejection", (error, promise) => { 
        
               console.trace(error); 
        
               UptimeKumaServer.errorLog(error, false); 
        
               console.error("If you keep encountering errors, please report to https://github.com/louislam/uptime-kuma/issues"); 
        
           });

uptime-kuma/server/model/monitor.js

Lines 809 to 822 in 9dc02bb

    
           const safeBeat = async () => { 
        
               try { 
        
                   await beat(); 
        
               } catch (e) { 
        
                   console.trace(e); 
        
                   UptimeKumaServer.errorLog(e, false); 
        
                   log.error("monitor", "Please report to https://github.com/louislam/uptime-kuma/issues"); 
        
                   if (! this.isStop) { 
        
                       log.info("monitor", "Try to restart the monitor"); 
        
                       this.heartbeatInterval = setTimeout(safeBeat, this.interval * 1000); 
        
                   } 
        
               } 
        
           };

deluxghost · 2023-05-18T09:02:57Z

I have also encountered the KnexTimeoutError issue, maybe waiting for 2.0 with external db is a better solution

chakflying · 2023-05-18T09:29:18Z

Those errors will show up without setting debug logging. If you haven't seen them before, it maybe because printing the debug logs increased server load too much.

deluxghost · 2023-05-18T09:31:55Z

The log was too long so I didn't find them before starting checking Checking monitor at... logs

chakflying · 2023-05-19T11:02:47Z

Thank you for your investigation. This is a separate issue and a fix is now open in #3174.

deluxghost added the bug Something isn't working label May 6, 2023

deluxghost closed this as completed May 6, 2023

deluxghost reopened this May 14, 2023

deluxghost changed the title ~~Push monitors from old version don't go DOWN state at all~~ Monitors are stopped after database is locked error May 18, 2023

chakflying mentioned this issue May 19, 2023

Fix: Use safeBeat in push monitor #3174

Merged

7 tasks

louislam closed this as completed in #3174 Jul 13, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Monitors are stopped after `database is locked` error #3130

Monitors are stopped after `database is locked` error #3130

deluxghost commented May 6, 2023

chakflying commented May 6, 2023

deluxghost commented May 6, 2023

deluxghost commented May 14, 2023

chakflying commented May 14, 2023

deluxghost commented May 14, 2023

deluxghost commented May 18, 2023

deluxghost commented May 18, 2023

deluxghost commented May 18, 2023

chakflying commented May 18, 2023

deluxghost commented May 18, 2023

chakflying commented May 19, 2023

Monitors are stopped after database is locked error #3130

Monitors are stopped after database is locked error #3130

Comments

deluxghost commented May 6, 2023

⚠️ Please verify that this bug has NOT been raised before.

🛡️ Security Policy

Description

👟 Reproduction steps

👀 Expected behavior

😓 Actual Behavior

🐻 Uptime-Kuma Version

💻 Operating System and Arch

🌐 Browser

🐋 Docker Version

🟩 NodeJS Version

📝 Relevant log output

chakflying commented May 6, 2023

deluxghost commented May 6, 2023

deluxghost commented May 14, 2023

chakflying commented May 14, 2023

deluxghost commented May 14, 2023

deluxghost commented May 18, 2023

deluxghost commented May 18, 2023

deluxghost commented May 18, 2023

chakflying commented May 18, 2023

deluxghost commented May 18, 2023

chakflying commented May 19, 2023

Monitors are stopped after `database is locked` error #3130

Monitors are stopped after `database is locked` error #3130