heartbeat file modify date keeps getting updated

[OliverwengFiltered]

• Web Browser: Chrome latest, mac os latest.
• Local OS: mac os latest
• Remote OS: Google VM Compute Engine
• Remote Architecture: Ubuntu 20
• code-server --version: 3.5.0

the heartbeat file modify date seems acting a bit weird.

if you open the code server and then close the code server in a relatively short time window, and then ssh into the vm machine to check out the heartbeat file modify date, you will start noticing that the heartbeat file modify date keeps getting updated every minute, but there is no active browser connection to code server.

wondering if anyone where had this issue ?

[code-asher]

If you run code-server with --log trace it will report how many connections it thinks are still connected. Could you do that and verify that it reports > 0 when no browser windows are open?

I'll try to replicate as well as soon as I can.

[OliverwengFiltered]

my service starts with systemctl start code-server@$USER,

I modified the code-server.service file to include --log trace located at /usr/lib/systemd/system/user/

and restarted the systemctl , it seems still don't see any relevant log shows up when I do journalctl -u code-server

I do see some extension logs located at .../.local/share/code-server/logs/...

[OliverwengFiltered]

Hi @code-asher

I'm wondering if you can reproduce the same issue ?

[code-asher]

Odd, there should definitely be stdout. We also log stdout to ~/.local/share/code-server/coder-logs so you could check that.

I ran 3.5.0 but wasn't able to replicate the issue (Firefox & Chrome running locally on Linux):

# < connected here
[2020-09-28T22:18:24.774Z] trace 2 active connections
[2020-09-28T22:18:24.775Z] trace heartbeat
[server] received ping {"proxies":3}
[server] received ping {"proxies":3}
[2020-09-28T22:19:24.780Z] trace 2 active connections
[2020-09-28T22:19:24.780Z] trace heartbeat
[server] received ping {"proxies":3}
# < disconnected here
[server] disconnected from client {"proxies":3}
[2020-09-28T22:20:24.785Z] trace 0 active connections
# < notice no "trace heartbeat" line

I also double-checked the heartbeat file and the timestamp was at 22:19 which matches with the last heartbeat log.

[OliverwengFiltered]

Hi @code-asher
it's kinda sporadic.
but the issue still exists for sure.
when all browsers closed, it seems still one active connection, and then I open one session it says 2 active connections.
and then I close the browser again, it turn back to 0.
PFA

Thanks,
any ideas in terms of what's going on ?

[OliverwengFiltered]

reproduced again.

PFA for the image to get some more insights.

Thanks

[code-asher]

Ah, there will be two connections per page since VS Code makes two websocket connections. So with that in mind it looks like things are working as expected, at least as far as these logs go.

[OliverwengFiltered]

Hi @code-asher
so I see what you meant, and after a few times retry, I reproduced again. and this logs seems a bit different from previous ones.
what happened was, when I created a new instance and opened vscode it asks me to reload window because it tries to reconnect. and then I did click reload window and then everything back to normal, after a few minutes, I turned off browser tab, and never opened the vscode link again.

PFA for the log.

Thanks
-Oliver

[code-asher]

Ah yeah it definitely looks like some connection isn't closing. I tried to replicate on 3.5.0 but I'm not having much luck. Here's what I did based on your comment, do these look like the right steps? 1. Start code-server 2. Open code-server in the browser 3. Restart code-server 4. Click "reconnect now" or wait for VS Code to reconnect, it will fail 5. Click "reload window" 6. Once VS Code has connected, close the VS Code tab Once I do these steps I get this for the next heartbeat: ``` [2020-10-16T15:48:13.213Z] trace 0 active connections ``` I tried it a few times but no luck yet. It's also interesting that you get four connections at one point! Very strange. Do you know if this happens if you close your browser entirely?

[OliverwengFiltered]

Hi @code-asher

so I just closed the whole browser chrome entirely, and after that, when I check the log, it's still updating every minute.

I guess to reproduce, you have to have a new VM instance and then put the link in a iframe to open it when VM instance code server is ready.

I noticed that for any code server vscode that had this issue and then If I open the vscode again, it will most likely update the connections to its correct amount and then if you close the browser tab, the connection will back to 0.

[code-asher]

Hmm that's very interesting. I'll try an iframe and maybe I can spin up some VMs to test as well. I think what I'll do in the meantime is add some more detailed logging which will hopefully help figure out what connection isn't getting closed.

[OliverwengFiltered]

@code-asher
sounds good, also, I can give you access to the VM machine which has the 1 active connection issue if you give me your public key if that helps. my email is [email protected].

Thanks

[nhooyr]

Hi @OliverwengFiltered, can you try to reproduce this on v3.7.1?

We've made major changes to the HTTP layer so it may be fixed.

[OliverwengFiltered]

Hi @nhooyr ,
will try and update you.

[OliverwengFiltered]

Hi @nhooyr

Curious, do you happen to know about when this one will be resolved ?

#2274

I can't upgrade to v3.7.1 for my users because of the above issue.

[code-asher]

I'm going to tackle #2274 after the update to VS Code 1.51.1 which I'm hoping to finish this week.

[OliverwengFiltered]

just switched to 3.7.3, so far so good, not seeing this issue anymore on v 3.7.3
I think it can be closed. will re-open if this issue shows up again.
@code-asher @nhooyr
great work, folks.

[nhooyr]

That's awesome to hear!! 🎊

[OliverwengFiltered]

Hi @nhooyr @code-asher

unfortunately, it happens on v3.7.3 too, I didn't have the enough data to draw a conclusion back then.

but all our system has upgraded to v3.7.3 a week ago, and we still see this happens occasionally. Exactly same logging "trace 1 active connection" .

Thanks
-Oliver

[nhooyr]

Nooo :(

Are you absolutely positive there isn't an active connection? You can check with sudo ss -tpn

[OliverwengFiltered]

here is what I see when do sudo ss -tpn
sshd is my terminal, and the other two are just google default users, which is not connecting to code server port.
@nhooyr @code-asher

[nhooyr]

That's wild!!

What version of node are you using? Did you install via a binary release or the npm package?

Honestly I'm at my wits end, the code isn't very complicated so I'm not sure what's going on.

[OliverwengFiltered]

@nhooyr
I installed it via curl -fOL https://github.com/cdr/code-server/releases/download/v3.7.3/code-server_3.7.3_amd64.deb
I'm using nodejs v10.x (old one), is it relevant ?
I can try upgrade nodejs to latest.

[nhooyr]

Yea so the .deb includes it's own node which is v12 iirc so that shouldn't be the problem.

I'm honestly not really sure how to continue debugging this.

I think we need a way to not only print that there is an active connection but where it's originating from and whether it's a websocket or HTTP @code-asher

That could help narrow things down.

[code-asher]

Definitely agreed, we need a bunch more logging around this to figure it out I think.

[code-asher]

I wonder if it's the same issue here? #2061 In that issue it's only caused by Safari + iPad, so maybe not.

[vikstrous2]

This issue happens to me all the time. I'm using a chromebook to connect. There's a proxy between vs code and the chromebook, but that probably doesn't matter. The logs show:

code-server[17244]: [2021-04-04T15:44:58.008Z] trace heartbeat
code-server[17244]: [2021-04-04T15:45:58.010Z] trace 1 active connection
code-server[17244]: [2021-04-04T15:45:58.010Z] trace heartbeat
code-server[17244]: [2021-04-04T15:46:58.013Z] trace 1 active connection

There are definitely no open connections left when this is happening:

netstat -apunt | grep 8443
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp        0      0 0.0.0.0:8443            0.0.0.0:*               LISTEN      17297/node

The local nodejs version is:

nodejs --version
v10.24.0

Code-server seems to have its own node version though:

/usr/share/code-server/lib/node --version
v12.18.4

This seems to happen very reliably when the chromebook fails asleep, so I suspect that nodejs is struggling with detecting when the connection goes away.

vs code is being started by systemd, in case that's relevant

lsof doesn't show anything interesting:

COMMAND   PID   FD      TYPE             DEVICE SIZE/OFF     NODE NAME
node    17297  cwd       DIR               8,16     4096 15205703 /<redacted>
node    17297  rtd       DIR                8,1     4096        2 /
node    17297  txt       REG                8,1 48646616  1052590 /usr/share/code-server/lib/node
node    17297  mem       REG                8,1    93000   394670 /usr/lib/x86_64-linux-gnu/libresolv-2.28.so
node    17297  mem       REG                8,1    26960   394663 /usr/lib/x86_64-linux-gnu/libnss_dns-2.28.so
node    17297  mem       REG                8,1    55792   394664 /usr/lib/x86_64-linux-gnu/libnss_files-2.28.so
node    17297  mem       REG                8,1  1824496   394655 /usr/lib/x86_64-linux-gnu/libc-2.28.so
node    17297  mem       REG                8,1   146968   394669 /usr/lib/x86_64-linux-gnu/libpthread-2.28.so
node    17297  mem       REG                8,1   100712   394472 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1
node    17297  mem       REG                8,1  1579448   394658 /usr/lib/x86_64-linux-gnu/libm-2.28.so
node    17297  mem       REG                8,1  1570256   394476 /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25
node    17297  mem       REG                8,1    14592   394657 /usr/lib/x86_64-linux-gnu/libdl-2.28.so
node    17297  mem       REG                8,1   165632   394650 /usr/lib/x86_64-linux-gnu/ld-2.28.so
node    17297    0u     unix 0x00000000c1a71d7a      0t0  1908057 type=STREAM
node    17297    1u     unix 0x00000000a3e67943      0t0  1908059 type=STREAM
node    17297    2u     unix 0x000000002be942c7      0t0  1908061 type=STREAM
node    17297    3u  a_inode               0,13        0     7897 [eventpoll]
node    17297    4r     FIFO               0,12      0t0  1912274 pipe
node    17297    5w     FIFO               0,12      0t0  1912274 pipe
node    17297    6r     FIFO               0,12      0t0  1912275 pipe
node    17297    7w     FIFO               0,12      0t0  1912275 pipe
node    17297    8u  a_inode               0,13        0     7897 [eventfd]
node    17297    9u  a_inode               0,13        0     7897 [eventpoll]
node    17297   10r     FIFO               0,12      0t0  1915050 pipe
node    17297   11w     FIFO               0,12      0t0  1915050 pipe
node    17297   12u  a_inode               0,13        0     7897 [eventfd]
node    17297   13u  a_inode               0,13        0     7897 [eventpoll]
node    17297   14r     FIFO               0,12      0t0  1912276 pipe
node    17297   15w     FIFO               0,12      0t0  1912276 pipe
node    17297   16u  a_inode               0,13        0     7897 [eventfd]
node    17297   17r      CHR                1,3      0t0     1028 /dev/null
node    17297   18u     IPv4            1912279      0t0      TCP *:8443 (LISTEN)
node    17297   21u     unix 0x000000000b813b5a      0t0  2523339 type=STREAM

Starting and stopping the vs code client (browser tab) does fix the issue and the code-server logs go back to:

code-server[17244]: [2021-04-04T15:57:58.042Z] trace 0 active connections

After the "fix", lsof and netstat show the same thing as before.

[jsjoeio]

Do you mind opening up a separate issue and filing a bug report with reproduction steps? We can take a closer look and hopefully find a fix.

[vikstrous2]

Ok. I'll try to narrow it down better first and come up with a repro that doesn't involve waiting for a chromebook to fall asleep :)

[vikstrous2]

Sorry, this turned out to be a pretty time consuming exercise. I don't think I'll be able to come up with a better repro easily. I tried disconnecting the network, but that didn't seem to work. I'm not sure exactly what happens at the network level when a chromebooks falls asleep.

[code-asher]

I've seen this occasionally as well but I'm not sure what exactly reproduces it. I think we should still try to add some more logging around what connections exactly are open to help figure it out.

[jsjoeio]

No worries at all. Thanks for trying @vikstrous2.

Added to On Deck. We can at least try to reproduce ourselves again and then also add logging like code-asher said.

[futurist]

I've encountered the same issue, after several try, and found below logs possible related:

[2021-07-09T01:38:02.082Z] debug exthost Spawning extension host... {"token":"90da54ec-421f-48ce-a6df-c3a061c031a6"}
[2021-07-09T01:38:02.091Z] debug exthost Waiting for handshake... {"token":"90da54ec-421f-48ce-a6df-c3a061c031a6"}
[2021-07-09T01:38:02.172Z] trace TerminalProviderChannel:call {"command":"$reduceConnectionGraceTime"}
[2021-07-09T01:38:02.562Z] debug exthost Handshake completed {"token":"90da54ec-421f-48ce-a6df-c3a061c031a6"}
[2021-07-09T01:38:02.563Z] debug exthost Sending socket {"token":"90da54ec-421f-48ce-a6df-c3a061c031a6"}
[2021-07-09T01:38:03.925Z] debug management Disconnected {"token":"e334db14-a717-4988-a6c7-14fbcc7cfdbd"}
[2021-07-09T01:38:03.928Z] debug exthost Got disconnected message {"token":"90da54ec-421f-48ce-a6df-c3a061c031a6"}
[2021-07-09T01:38:03.928Z] debug exthost Disconnected {"token":"90da54ec-421f-48ce-a6df-c3a061c031a6"}
[2021-07-09T01:39:00.949Z] debug 1 active connection
[2021-07-09T01:39:00.949Z] trace heartbeat
[2021-07-09T01:40:00.955Z] debug 1 active connection
[2021-07-09T01:40:00.956Z] trace heartbeat
[2021-07-09T01:41:00.961Z] debug 1 active connection
[2021-07-09T01:41:00.961Z] trace heartbeat

Above can be reproduced as below steps:

ENV: macOS15 + Code-Server:3.10.2 + Chrome91

1. Open cdr url in a Browser Tab first
2. Close the Tab, wait for a bit seconds
3. Then press Shift+Cmd+T (Reopen Last Closed Tab)
4. Close the tab quickly when the VSCode editor shown

And the logs will be appended 1 active connection constantly forever, even there's no open Browser Tabs.

Hope it's helperful!

[futurist]

When I patched the output file lib/vscode/out/vs/server/entry.js, place a console.log(1234), before all this._onMessage.fire call (I think the source code contained within lib/vscode/src/vs/base/parts/ipc/common/ipc.net.ts)

• When no open Browser Tabs:
  There's no 1234 output, but only 1 active connection.

• When opened a Browser Tab for code-server:
  There're many 1234 output, together with other normal logs.

Maybe we can add some check for the real onMessage fired? If no message, no heartbeat?

[jsjoeio]

Fantastic notes @futurist 👏

Maybe we can add some check for the real onMessage fired? If no message, no heartbeat?

Maybe you're right. @code-asher is more familiar with the heartbeat file so I'll let him weigh in on it when he is back next week.

[code-asher]

We could change the heartbeat mechanism to use onMessage or something like that but I think that might disguise the problem that there is some connection hanging open. Currently we use `getConnections` on the server (https://nodejs.org/api/net.html#net_server_getconnections_callback) Since this returns >= 1 I think it means there is a connection failing to close and we need to make sure it closes properly somehow.

[ifduyue]

I encountered this problem, too.
Once I've visited code-server and left, no matter what I do (close tab, even close chrome), there will always be 1 active connection.
lsof and ss shows there is no IPv4 connections related to any code-server processes

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no activity occurs in the next 5 days.