Possible memory leak?

[MasterGroosha]

Describe the bug

I'm running WriteFreely v 0.9.1 on my Scaleway instance with 2GB of RAM. It's a single-user federated instance with SQLite as backend. I'm managing it via systemd with the following service description:

[Unit]
Description=Write Freely Instance
After=syslog.target network.target

[Service]
Type=simple
WorkingDirectory=/home/groosha/writefreely
ExecStart=/home/groosha/writefreely/writefreely >> /var/log/writefreely.log
Restart=always

[Install]
WantedBy=multi-user.target

The only modification I made is replacing one of "letter-avatars" with a custom one to see a proper profile pic on Mastodon.

Symptoms

If I run WriteFreely for a long time (let's say, a month) without even touching it (no users, no new posts, nothing), it consumes almost all free RAM on server, causing other apps to have problems.
For example, my Python scripts which are running as cron jobs and regular processes, raise some exceptions like RuntimeError: can't start new thread or vedis.cpython-35m-x86_64-linux-gnu.so: failed to map segment from shared object. Also running htop shows that writefreely process consumes ~60% of RAM:

(notice that I'm running only one process, but htop shows all threads)

After I restart writefreely with systemctl restart writefreely everything gets back to normal:

(here I enabled "tree" view of processes, showing that I have only 1 process of writefreely and others are most likely threads)

My bad I didn't write down Go internal stats from /admin page, I guess it would help a lot.

Expected behavior

RAM usage should depend on active users or API usage, not increase as the time goes by.

Application configuration

• Single mode or Multi-user mode? Single mode
• Database? SQLite
• Open registration? No
• Federation enabled? Yes
• Operating system? Ubuntu 16.10 (oops!)

Version or last commit: 0.9.1

[MasterGroosha]

I've also noticed that despite ExecStart=/home/groosha/writefreely/writefreely >> /var/log/writefreely.log command in Systemd service description, there's no such file /var/log/writefreely.log 🤔

[thebaer]

Thanks for filing this @MasterGroosha, we definitely want to look into this. For now, if anyone with experience with Go profiling tools wants to help out, that'd be a huge help!

(As for the logging, I'd suggest updating the Systemd service to the current config shown in the Getting Started guide.)

[prologic]

Are we sure its not a goroutine leak? In my experience thats usually more common.

Terminating the process with SIGQUIT ^\ after some runtime amount of time might shed some light.

[prologic]

I've also noticed that despite ExecStart=/home/groosha/writefreely/writefreely >> /var/log/writefreely.log command in Systemd service description, there's no such file /var/log/writefreely.log 🤔

That doesn't look quite correct. ExecStart AFAIK doesn't invoke a shell nor does it log to plain text files. You want to use journalctl to view logs (which are captured and stored in binary form) and requires systemd tooling to view.

[prologic]

I can also confirm this memory leak in my own instance (I don't recall which version specifically) with this Prometheus query:

container_memory_usage_bytes{container_label_com_docker_swarm_service_name="blog_blog"}

[prologic]

@thebaer If you add instrumentation like in https://prometheus.io/docs/guides/go-application/ this will help debug this and monitor instances runtime behaviour more reasily. I'm happy to put up such a PR and documentation for this (more of an ops features than a user-facing one -- but a Admin UI could be developed to pull in some useful data/graphs too).

[MasterGroosha]

I'm preparing for migration, so WriteFreely instance will be stopped. Now it consumes 13.7% memory with the following stats from admin webpage:

WriteFreely v0.9.1
Server Uptime 6 days, 1 hour, 23 minutes, 37 seconds
Current Goroutines 9
Current memory usage 247 MB
Total mem allocated 513 MB
Memory obtained 273 MB
Pointer lookup times 0
Memory allocate times 5057914
Memory free times 2631677
Current heap usage 247 MB
Heap memory obtained 255 MB
Heap memory idle 5.9 MB
Heap memory in use 250 MB
Heap memory released 0 B
Heap objects 2426237
Bootstrap stack usage 576 KB
Stack memory obtained 576 KB
MSpan structures in use 4.5 MB
MSpan structures obtained 255 MB
MCache structures in use 3.4 KB
MCache structures obtained 16 KB
Profiling bucket hash table obtained 1.5 MB
GC metadata obtained 10 MB
Other system allocation obtained 881 KB
Next GC recycle 492 MB
Since last GC 92.8s
Total GC pause 0.9s
Last GC pause 0.000s
GC times 3837

[thebaer]

@prologic That'd be great! Please feel free to submit a PR. At least one user has requested this feature, and I think it'd be a great addition beyond solving this issue.

[thebaer]

We started noticing memory issues on our Write.as instance and, using Go's pprof tool among other things, tracked it down to an old dependency.

If you all wouldn't mind testing out the fix in #251, I'd love to hear whether or not it fixes the issue for you!

[MasterGroosha]

Thank you, @thebaer!
Unfortunately, I'm not well experienced with go/node.js, so I think I'll have a hard time building Writefreely from sources. Would you mind building a Linux amd64 build please so that I can simply deploy it on my server?

[thebaer]

Sure, no problem. Here's the build for this branch: writefreely_0.11.2-88-g8fce34b_linux_amd64.tar.gz

[MasterGroosha]

@thebaer I've just started to deploy the version you've built for me and I've got a strange error.
ERROR: 2020/02/03 14:58:54 app.go:568: migrate: near "(": syntax error

My config:

• Production, behind reverse proxy
• Local port 8085
• SQLite database
• writefreely.db filename
• Single-user blog
• Federation enabled
• Federation usage stats Private
• Instance metadata privacy Public

When this error appeared for the first time, I decided to try again with the same config and it said "Database already initialized". Trying to start Writefreely results in error:
ERROR: 2020/02/03 15:03:46 main.go:119: init keys: open keys/email.aes256: no such file or directory

Upd: my bad, I forgot to run --gen-keys action. Though that "migrate" issue is still valid, I guess.

[thebaer]

Ah, our latest migrations don't work with SQLite -- sorry about that. We should have that fixed in the near future, but it's probably best to avoid this version in production for now if you're using SQLite.

[MasterGroosha]

@thebaer by the way this version seems to be working (at least, I managed to deploy and create a post).
So this is not a breaking bug for me. I'm currently running Writefreely in mostly "idle" mode to see if any memory leaks occur. So far so good.

[thebaer]

Okay awesome. We're seeing the same results on Write.as, so I think we'll merge the fix now. But please report here if anything comes up.