search

realm / realm-object-server

Tracking of issues related to the Realm Object Server and other general issues not related to the specific SDK's
https://realm.io
293 stars 42 forks source link

NodeJS Error 'ENOBUFS' prevents server from starting #250

Closed dannygrob closed 7 years ago

dannygrob commented 7 years ago

I was trying to restart the object server, but it won't start. systemctl status seems to be reporting that the server is running, but it isn't, see journalctl outout. Also when running manually it outputs this same error (made sure all services where stopped), see error below

I'm running the latest version of Nginx and realm (1.8.2-310)

I have around 600 realms and it was running fine before the restart. From what i've read about ENOBUFS is that spawning too many connections can cause this error:

Error: Error: listen ENOBUFS 127.0.0.1:27080

https://stackoverflow.com/questions/10603860/very-simple-node-js-client-throws-error-enobufs-after-many-http-requests

edit: After renaming my folder so I can test if the server runs without my user realms: it does. It starts normally. Looks like i've reached max connections?

Version of Realm and Tooling

Logs

sudo journalctl -u realm-object-server.service

 read configuration from /etc/realm/configuration.yml.
Error: listen ENOBUFS 127.0.0.1:27080
at Object.exports._errnoException (util.js:1018:11)
at exports._exceptionWithHostPort (util.js:1041:20)
at Server._listen2 (net.js:1245:19)
at listen (net.js:1294:10)
at net.js:1404:9
at _combinedTickCallback (internal/process/next_tick.js:83:11)
at process._tickCallback (internal/process/next_tick.js:104:9)
at Module.runMain (module.js:606:11)
at run (bootstrap_node.js:389:7)
at startup (bootstrap_node.js:149:9)
systemctl status realm-object-server.service Loaded: loaded (/etc/systemd/system/realm-object-server.service; enabled; vendor preset: enabled) Drop-In: /etc/systemd/system/realm-object-server.service.d └─override.conf Active: active (running) since vr 2017-08-11 11:52:11 CEST; 352ms ago Main PID: 12434 (realm-object-se) CGroup: /system.slice/realm-object-server.service └─12434 /usr/lib/realm-object-server-developer/node/bin/node /usr/bin/realm-object-server -c /etc/realm/configuration.yml
cat /var/log/realm-object-server.log [no errors, last entry was my stop: Closing gracefully. Caught signal SIGTERM.]
morten-krogh commented 7 years ago

It looks like there are too many connections as you say.

Can you turn on debug level logging, start the server again, and upload the full log file? Thanks in advance.

dannygrob commented 7 years ago

My log isn't showing anything useful I think, as I don't see anything getting added. Log level is 'all'. My log is 8GB, so here the part cut from when it was running and I did the reboot till the end:


2017-08-11T13:13:01.513Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/auth.realm
2017-08-11T13:13:01.523Z - debug: permissions: Permissions were changed deletions=[], insertions=[], modifications=[1]
2017-08-11T13:13:01.525Z - debug: permissions: Open permission-Realm /__permission
2017-08-11T13:13:01.525Z - debug: permissions: Delete mirrored permission for user '*' and Realm-file '%s'
2017-08-11T13:13:01.531Z - debug: permissions: Open permission-Realm /__permission
2017-08-11T13:13:01.532Z - debug: permissions: Create mirrored permission for user '*' and Realm-file '%s' with %s
2017-08-11T13:13:01.539Z - detail: sync: Sync Connection[5]: Session[3]: Remote changeset integrated, producing server version 8
2017-08-11T13:13:01.539Z - debug: sync: Using already open Realm file: /var/lib/realm/object-server/0/user_data/__auth/__permission.realm
2017-08-11T13:13:01.539Z - trace: sync: Sending: DOWNLOAD(scan_server_version=8, scan_client_version=17, latest_server_version=8, latest_server_session_ident=2489962195618139864, latest_client_version=17, inserted_changeset_count=0, is_body_compressed=0, body_size=0, compressed_body_size=0)
2017-08-11T13:13:01.539Z - detail: sync: Sync Connection[5]: Session[3]: Sending: DOWNLOAD(scan_server_version=8, scan_client_version=17, latest_server_version=8, latest_server_session_ident=2489962195618139864, latest_client_version=17, number of changesets=0, downloadable_bytes=0)
2017-08-11T13:13:01.539Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/auth.realm
2017-08-11T13:13:01.539Z - debug: sync-client: Connection[1]: Session[1]: Progress handler called, downloaded = 109, downloadable = 109, uploaded = 1119, uploadable = 1119, progress version = 1, snapshot version = 29
2017-08-11T13:13:01.539Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__global.realm
2017-08-11T13:13:01.540Z - debug: sync-client: Connection[4]: Session[4]: Progress handler called, downloaded = 0, downloadable = 0, uploaded = 323, uploadable = 331, progress version = 1, snapshot version = 13
2017-08-11T13:13:01.540Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__global.realm
2017-08-11T13:13:01.543Z - detail: sync-client: Connection[4]: Session[4]: Sending: UPLOAD(client_version=13, server_version=4, changeset_size=8, timestamp=82386781526)
2017-08-11T13:13:01.543Z - trace: sync-client: Connection[4]: Session[4]: Changeset: 05 00 02 0E 00 01 01 01
2017-08-11T13:13:01.543Z - trace: sync-client: Connection[4]: handle_write_output_buffer
2017-08-11T13:13:01.543Z - debug: sync-client: message_type = download
2017-08-11T13:13:01.543Z - debug: sync-client: Download message compression: is_body_compressed = 0, compressed_body_size=0, uncompressed_body_size=0
2017-08-11T13:13:01.543Z - detail: sync-client: Connection[3]: Session[3]: Received: DOWNLOAD(scan_server_version=5, scan_client_version=11, latest_server_version=5, latest_server_session_ident=2114854012092349581, latest_client_version=11, downloadable_bytes=0, number_of_changesets=0)
2017-08-11T13:13:01.543Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__auth.realm
2017-08-11T13:13:01.543Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__auth.realm
2017-08-11T13:13:01.543Z - debug: sync-client: Connection[3]: Session[3]: Progress handler called, downloaded = 0, downloadable = 0, uploaded = 362, uploadable = 531, progress version = 1, snapshot version = 18
2017-08-11T13:13:01.543Z - detail: sync: Sync Connection[2]: Session[4]: Received: UPLOAD(client_version=13, server_version=4, changeset_size=8, timestamp=82386781526)
2017-08-11T13:13:01.543Z - debug: sync: Using already open Realm file: /var/lib/realm/object-server/0/user_data/__permission.realm
2017-08-11T13:13:01.551Z - debug: sync-client: message_type = download
2017-08-11T13:13:01.552Z - debug: sync-client: Download message compression: is_body_compressed = 0, compressed_body_size=0, uncompressed_body_size=0
2017-08-11T13:13:01.552Z - detail: sync-client: Connection[3]: Session[3]: Received: DOWNLOAD(scan_server_version=8, scan_client_version=17, latest_server_version=8, latest_server_session_ident=2489962195618139864, latest_client_version=17, downloadable_bytes=0, number_of_changesets=0)
2017-08-11T13:13:01.552Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__auth.realm
2017-08-11T13:13:01.558Z - detail: sync: Sync Connection[2]: Session[4]: Remote changeset integrated, producing server version 5
2017-08-11T13:13:01.558Z - debug: sync: Using already open Realm file: /var/lib/realm/object-server/0/user_data/__permission.realm
2017-08-11T13:13:01.558Z - trace: sync: Sending: DOWNLOAD(scan_server_version=5, scan_client_version=13, latest_server_version=5, latest_server_session_ident=7351497047835786273, latest_client_version=13, inserted_changeset_count=0, is_body_compressed=0, body_size=0, compressed_body_size=0)
2017-08-11T13:13:01.558Z - detail: sync: Sync Connection[2]: Session[4]: Sending: DOWNLOAD(scan_server_version=5, scan_client_version=13, latest_server_version=5, latest_server_session_ident=7351497047835786273, latest_client_version=13, number of changesets=0, downloadable_bytes=0)
2017-08-11T13:13:01.564Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__auth.realm
2017-08-11T13:13:01.564Z - debug: sync-client: Connection[3]: Session[3]: Progress handler called, downloaded = 0, downloadable = 0, uploaded = 531, uploadable = 531, progress version = 1, snapshot version = 19
2017-08-11T13:13:01.564Z - debug: sync-client: message_type = download
2017-08-11T13:13:01.564Z - debug: sync-client: Download message compression: is_body_compressed = 0, compressed_body_size=0, uncompressed_body_size=0
2017-08-11T13:13:01.564Z - detail: sync-client: Connection[4]: Session[4]: Received: DOWNLOAD(scan_server_version=5, scan_client_version=13, latest_server_version=5, latest_server_session_ident=7351497047835786273, latest_client_version=13, downloadable_bytes=0, number_of_changesets=0)
2017-08-11T13:13:01.565Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__global.realm
2017-08-11T13:13:01.571Z - detail: sync-client: Using already open Realm file: /var/lib/realm/object-server/internal_data/permission/__global.realm
2017-08-11T13:13:01.571Z - debug: sync-client: Connection[4]: Session[4]: Progress handler called, downloaded = 0, downloadable = 0, uploaded = 331, uploadable = 392, progress version = 1, snapshot version = 15
2017-08-11T13:13:01.571Z - info: sync-client: Closing Realm file: /var/lib/realm/object-server/internal_data/permission/__global.realm
2017-08-11T13:13:01.571Z - info: sync-client: Connection[4]: Session[4]: Sending: UNBIND
2017-08-11T13:13:01.573Z - info: sync: Sync Connection[2]: Session[4]: Session terminated (session_ident=4).
2017-08-11T13:13:01.573Z - info: sync: Sync Connection[2]: Connection closed by client: End of input
2017-08-11T13:13:02.735Z - debug: http:  127.0.0.1 - GET / HTTP/1.1 200 1891 - 6.066 ms
2017-08-11T13:13:02.843Z - debug: http:  127.0.0.1 - GET /vendor.js HTTP/1.1 200 4837700 - 3.276 ms
2017-08-11T13:13:02.980Z - debug: http:  127.0.0.1 - GET /app.js HTTP/1.1 200 20296038 - 7.938 ms
2017-08-11T13:13:06.527Z - debug: http:  127.0.0.1 - GET /api/info HTTP/1.1 200 61 - 4.283 ms
2017-08-11T13:13:06.528Z - debug: http:  127.0.0.1 - GET /api/stats HTTP/1.1 401 24 - 5.732 ms
2017-08-11T13:13:06.532Z - debug: http:  127.0.0.1 - GET /assets/images/nav_logo.png HTTP/1.1 200 2910 - 7.918 ms
2017-08-11T13:13:06.550Z - debug: http:  127.0.0.1 - GET /api/info HTTP/1.1 304 - - 0.853 ms
2017-08-11T13:13:06.906Z - debug: http:  127.0.0.1 - GET /assets/favicons/favicon-32x32.png HTTP/1.1 200 2044 - 1.244 ms
2017-08-11T13:13:07.008Z - debug: http:  127.0.0.1 - GET /assets/favicons/favicon-16x16.png HTTP/1.1 200 1625 - 0.973 ms
2017-08-11T13:13:07.056Z - debug: http:  127.0.0.1 - GET /assets/favicons/favicon-96x96.png HTTP/1.1 200 5427 - 1.445 ms
2017-08-11T13:13:07.077Z - debug: http:  127.0.0.1 - GET /assets/favicons/android-icon-192x192.png HTTP/1.1 200 9649 - 0.951 ms```
morten-krogh commented 7 years ago

How many users and Realms do you have?

morten-krogh commented 7 years ago

Oh, you wrote 600 realms

dannygrob commented 7 years ago

Yeah, I know that I have around 600. Number of folders in the /0/user_data folder is 569

morten-krogh commented 7 years ago

That is not very many.

Could you monitor the memory consumption? What is the RAM size on your machine?

dannygrob commented 7 years ago

Mem: 4096, free: 3975 Disk: 215G, 55G free (other partitions 0 - 2% usage)

morten-krogh commented 7 years ago

And your Realms are not gigantic either? What is the total size of those 600 realms?

dannygrob commented 7 years ago

There are some huge realms, total size of that folder is 41G.

This is the last folder:


-rw-r--r--   1 root root     1456 jul 14 11:04 __permission.realm.lock
drwxr-xr-x   2 root root     4096 jun 17 12:01 __permission.realm.management
-rw-r--r--   1 root root 41943040 jul 16 01:09 usersync.realm
-rw-r--r--   1 root root     1456 jul 31 16:29 usersync.realm.lock
drwxr-xr-x   2 root root     4096 jul 16 01:09 usersync.realm.management`

and here is a smaller one:
`-rw-r--r--   1 root root  4096 jun 17 12:00 __permission.realm
-rw-r--r--   1 root root  1456 jul 14 11:04 __permission.realm.lock
drwxr-xr-x   2 root root  4096 jun 17 12:01 __permission.realm.management
-rw-r--r--   1 root root  8192 jun 17 12:00 usersync.realm
-rw-r--r--   1 root root     0 jun 17 12:00 usersync.realm.lock```
morten-krogh commented 7 years ago

It is not clear to me that you should run out of memory, sockets or anything else with this data set.

Would you be willing to allow ssh access to us?

Is the server stopped now? You can't start it at all.

dannygrob commented 7 years ago

I can't get it to start no. ssh access is fine, i've contacted help@realm.io too, you can reply with details danny at digitalfactor.nl.