[Bug]: Heartbeat not being updated while user edits files or has terminal activity.

[antofthy]

Is there an existing issue for this?

• I have searched the existing issues

OS/Web Information

• Web Browser: chrome, brave
• Local OS: linux, windows
• Remote OS: docker running debian (for example php:8.0.6-apache docker image)
• Remote Architecture: x86_64
• code-server --version: v4.8.3 also tested against v4.9.1, and v4.7.3
  4.8.3 977b853 with Code 1.72.1

Steps to Reproduce

1. Run code server and login in a web browser
2. Continuously watch the heartbeat file in seperate window, to see when it was last updated (how old it is)
3. Edit file and generally work in a open terminal window. Or just go do other things until heartbeat stops.
4. After this do thins with code-server and VERY few times will get heartbeat to start updating again!

Expected

Heartbeat file $HOME/.local/share/code-server/heartbeat should have its time updated (touched) at least once every minute, while there is ANY activity. And for a long period while the web browser tab has code server open, it does update once a minute.

Actual

After a period of time (could be anywhere from 15 to 45 minutes) the heartbeat stops updating.

At which point it will NOT start again even if user starts to edit existing open files, making changes, saving using ctrl-S, closing open file editing, or perform commands in terminal. Actual changes are being made, and confirmed both in the file system, or even from looking via the code-server terminal, and yet heartbeat does not reflect that the user has performed some action, and as such is NOT idle.

The heartbeat only starts updating again, if a new file is opened, or browser tab (google chrome, or brave) is refreshed, or re-opened. And then only for a VERY short time (up to 5 minutes or so) before it stops again, even though user is active and changes are being made (as above). Sometimes with only a single heartbeat update being seen.

This is BAD as the idle-timeout system we use relies on the heartbeat (see below). It can't use web requests as there no new requests, as actual changes were made though open connections. Be it via terminal or file editing.

Logs

No log output has been seen in any log without verbose turned on.
However with the length of times involved the size of the verbose log is HUGE!
Especially as the 'File Watcher' also watches the file it logs to for the File Watching while verbose!
EG: .local/share/code-server/logs/.../remoteagent.log

Looking at around the time the heartbeat stops 2023-01-13_15:14:54
And removing any line with the pattern File Watcher.*share/code-server
I get the following from remoteagent.log...

[2023-01-13 15:12:39.157] [remoteagent] [trace] [File Watcher (parcel)] [ADDED] /var/www/20230113-1512-01-
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)] [ADDED] /var/www/20230113-1512-01-/var
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)] [ADDED] /var/www/20230113-1512-01-/var/www
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)] [ADDED] /var/www/20230113-1512-01-/var/www/.local
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)] [ADDED] /var/www/20230113-1512-01-/var/www/.local/share
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)]  >> normalized [ADDED] /var/www/20230113-1512-01-
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)]  >> normalized [ADDED] /var/www/20230113-1512-01-/var
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)]  >> normalized [ADDED] /var/www/20230113-1512-01-/var/www
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)]  >> normalized [ADDED] /var/www/20230113-1512-01-/var/www/.local
[2023-01-13 15:12:39.158] [remoteagent] [trace] [File Watcher (parcel)]  >> normalized [ADDED] /var/www/20230113-1512-01-/var/www/.local/share
[2023-01-13 15:15:00.644] [remoteagent] [trace] ExtensionManagementService.refreshReportedCache
[2023-01-13 15:15:00.644] [remoteagent] [trace] ExtensionManagementService.refreshControlCache {"malicious":[],"deprecated":{}}
[2023-01-13 15:16:00.640] [remoteagent] [trace] Started scanning user extensions
[2023-01-13 15:16:00.642] [remoteagent] [trace] Scanned user extensions: 0

I seriously doubt this is of any use.

Screenshot/Video

No response

Are you accessing code-server over HTTPS?

• I am using HTTPS.

Notes

I have recently had complaints from students and staff saying the Heartbeat has become flaky.
The heartbeat is used by our docker system to determine when a user is no longer using the development environment they are running so it can be closed down after an hour of non-use.

I am finding the heartbeat stopped updating, even though files are still being edited or the terminal is being used. The heartbeat does start to work again if a different file is opened for editing, or the whole browser tab is refreshed. But not from actual use with files being edited or the terminal being used. The heart beat file, which normally updates once a minute just stops being updated.

Heartbeat is VITAL for the determination of the automatic shutdown of docker instances, as code-server holds web connections open, rather than making new requests (as jupyter notebook does). The Idle checker checks...
1/ user started or checked the status of docker instance from a control panel
2/ there has been any web request logged by the docker ingress service for that user on the code-server port (8443) or on other ports user may used in their docker environment (apache ports).
3/ the code-server heartbeat file was last updated.

System is basically as originally described in
#792 (comment)
Only with the addition of web request checks being added, as per...
#1274 (comment)
to the 'idle timeout' check script that runs every ten minutes (it looks back and records in another timestamp file) and user web requests for specific ports in the last 15 minutes of ingress logs.

The heartbeat may be related to the refactor of the heartbeat in...
#5544

[jsjoeio]

Hmmm.... any ideas @code-asher? I could have sworn it was implemented upstream which is why we removed it.

[jsjoeio]

@antofthy does this happen with the latest version?

My thinking for how you can help us troubleshoot:

1. ideally reproduce as easy as possible
2. better? reproduce in a unit test
3. then we can look into a fix

[antofthy]

The tricky part is using something to monitor the heartbeat file. I have a small shell script to return the age of the file (appear of our idle test), and then start beeping me when the file gets more than 2 minute old so I know when heartbeat has stopped working.

In a docker set up with a mounted home you can watch the heartbeat file outside the running docker instance (just as our idle timer is doing). Or on a separate docker connection to the docker instance.

Now what do you mean by 'unit test'. I download code-server from the git version releases.

I will create a new docker image with the latest version.

[antofthy]

Yes it still does it in the release of 4.9.1
https://github.com/coder/code-server/tree/v4.9.1

[antofthy]

I have now uploaded a screen shot with a monitor shell script in the code-server terminal, that shows heart beat had stopped, even though I am obviously active in code-server terminal.

Here is a copy of the script..

while true; do
  printf -v now '%(%s)T' -1
  idle=$((now - $(stat --printf "%Y\n" ~/.local/share/code-server/heartbeat) ))
  printf -v human "%5d:%02d" $((idle/60)) $((idle%60))
  if (( idle > 65 ))
  then echo -n "$human" $'\e[7m***** STOPPED *****\e[0m\r'
  else echo -n "$human" $' Heartbeat Running \r'
  fi
  sleep 1
done

At this point I can do anything in terminal or in a editor panel and heartbeat does NOT restrart.
until either the browser tab is refreshed, or I specifically open another file for editing. And even then the heartbeat does not run for very long, before it stops again.

I do not know how long it has been like this. Or if the refactoring caused the problem, only that it was recently reported that user docker instances shutdown expectantly (idle timeout) even though users were editing files (an hour after heartbeat updates stopped and failed to update).

I myself did not get involved until after it was reported, and did not believe it until I ran monitors that show this happening.

[antofthy]

Had a lucky break in that I ran a variation of the script, and had the heartbeat stop not long after running it...

You can see the heartbeat updated at 14:40:20 but then did not update again. It did not update even after more terminal, or file editing as mentioned, so the web connection to code-server was still open.

[antofthy]

If you name a version I can download to test the situation on that version.

[jsjoeio]

Oh I meant so we could add a test here somewhere: https://github.com/coder/code-server/tree/main/test/unit

Thanks for all the notes!

@code-asher any ideas on what we should do to fix this?

[antofthy]

Except I don't use the GIT code, I used the release code, as part of a larger "Student Software Development Environment".
This environment has been used code-server from version 1

Maybe restoring the old code may help.. I am not certain. Do you know what version the code was switched to using VS code? I can test against a version before it was changed to confirm. I am not surprised it was not discovered as it can take a long time for heartbeat to stop.

Really it is obvious to me that the communications link to the browser is still open an active, as terminal can do things, and file changes are being saved. It's just that code-server heartbeat code is not recognising that the communications with browser is still open and active.

[code-asher]

@jsjoeio My thinking is either the Node code we call to get active connections is somehow wrong:

code-server/src/node/routes/index.ts

Lines 35 to 42 in 134e9b4

	return new Promise((resolve, reject) => {
	app.server.getConnections((error, count) => {
	if (error) {
	return reject(error)
	}
	logger.debug(plural(count, `${count} active connection`))
	resolve(count > 0)
	})

Or the heartbeat code itself is buggy. Maybe we can start with some debug logging that tells us when the heartbeat is running, when it schedules itself to run, and when it stops and why it thinks it should stop ("stopping heartbeat because server reports there are no connections" for example).

[jsjoeio]

Great ideas! Okay I'll add it to the next milestone.