[Solved] Error 500 for JSON requests after update to 3.9.1-15 or -16

[doenietzomoeilijk (Max)]

Yesterday I updated to 3.9.1-15, and right after that was done, the next update appeared. Installed that as well, of course. Since then, I’m getting errors all over the web UI, most seem to be caused by the same problem:

[23/Oct/2017 07:57:43] ERROR [storageadmin.middleware:32] Exception occured while processing a request. Path: /api/commands/refresh-share-state method: POST
[23/Oct/2017 07:57:43] ERROR [storageadmin.middleware:33] Exception while running command(['/sbin/btrfs', 'subvolume', 'list', '-s', '/mnt2/pool1']): [Errno 24] Too many open files
Traceback (most recent call last):
File "/opt/rockstor/eggs/Django-1.8.16-py2.7.egg/django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/opt/rockstor/eggs/Django-1.8.16-py2.7.egg/django/views/decorators/csrf.py", line 58, in wrapped_view
    return view_func(*args, **kwargs)
File "/opt/rockstor/eggs/Django-1.8.16-py2.7.egg/django/views/generic/base.py", line 71, in view
    return self.dispatch(request, *args, **kwargs)
File "/opt/rockstor/eggs/djangorestframework-3.1.1-py2.7.egg/rest_framework/views.py", line 452, in dispatch
    response = self.handle_exception(exc)
File "/opt/rockstor/eggs/djangorestframework-3.1.1-py2.7.egg/rest_framework/views.py", line 449, in dispatch
    response = handler(request, *args, **kwargs)
File "/opt/rockstor/eggs/Django-1.8.16-py2.7.egg/django/utils/decorators.py", line 145, in inner
    return func(*args, **kwargs)
File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 318, in post
    import_shares(p, request)
File "/opt/rockstor/src/rockstor/storageadmin/views/share_helpers.py", line 80, in import_shares
    shares_in_pool = shares_info(pool)
File "/opt/rockstor/src/rockstor/fs/btrfs.py", line 431, in shares_info
    raise
File "/opt/rockstor/src/rockstor/system/osi.py", line 113, in run_command
    'Exception while running command({}): {}'.format(cmd, e))
Exception: Exception while running command(['/sbin/btrfs', 'subvolume', 'list', '-s', '/mnt2/pool1']): [Errno 24] Too many open files

Apart from that, everything works just fine, file shares are active, Docker containers humming along, etc. Any idea what might cause this and more importantly, how I’m getting rid of it?

Edit: formatting.

[KarstenV (Karsten Vinding)]

I don’t know anything about the errors you are seeing, but I upgraded yesterday also, to first -15 and later to -16, and I dont see anything unusual on the web UI. Everything works as usual.

Are there any specific pages you are seeing errors on?

[doenietzomoeilijk (Max)]

All of them, pretty much. I’m starting to think “botched update”, but I’d have to dig some more. At least I know it’s not an issue for everyone.

[phillxnet (Philip Guyton)]

@doenietzomoeilijk Hello again.

@doenietzomoeilijk

… [Errno 24] Too many open files …

This is something we have seen on occasion and should be sorted by a reboot. Let us know how it goes. @suman may have addressed this going forward in:

Dev log for 3.9.2

Happy Saturday everyone! 3.9.1-15 is now available! I’ve updated a backend dependency(gunicorn) and @KaiRo contributed a convenient abstraction to disk management. Thanks Robert!

which was your first update but the library concerned may not have taken effect.

the issue we are monitoring this in is:
https://github.com/rockstor/rockstor-core/issues/1656

Your system will essentially be disabled until the file handles are reset/released. Here’s hoping our very old version of gunicorn was the culprit.

See also the forum thread by @nfriedly linked to in that issue:

Web UI errors (too many open files) while runing a balance

Hey folks, I added a couple of drives and started a balance last Friday. I noticed that it was proceeding slowly so I shutdown the rockons service and just let it run. Last night (Sunday), I noticed that I was receiving lots of errors just trying to navigate the Web UI, and that one CPU core was maxed at 100%, and when I was eventually able to load the status page, it showed only 9% complete! So, I poked around on here and found Balance is really disruptive - running the command quoted there …

ie:

@nfriedly

but they basically all boil down to either “[Errno 24] Too many open files” or else nondescript “unknown internal errors.” (Presumably those are also be due to too many files errors.)

Hope that helps.

[doenietzomoeilijk (Max)]

I’ll give it a reboot later today and I’ll update this thread with the results. Thanks for your very complete reply!

[doenietzomoeilijk (Max)]

Update: a reboot later, the issues are gone!

[phillxnet (Philip Guyton)]

@doenietzomoeilijk Great, glad it’s sorted for you. Thanks for the update.

If you have a return of this “Too many open files” issue please contribute what ever you can to that issue as it would be nice to get this one sorted. Tricky as intermittent, doesn’t affect all systems, and can take a while to emerge.

Cheers.

[doenietzomoeilijk (Max)]

I’ve done some digging, and the only thing I did besides upgrading, was working on a Rock-on. I can’t find anything interesting in the logs (Docker logs don’t appear to go back as far, syslog is very busy with netatalk restarting constantly for some reason (I’ve disabled it for now, since my lone Mac can connect using Samba just fine), but nothing else.

I guess it’s a bit of a compound issue, in my case triggered by the yum update, and in other cases by other actions. That’d explain the intermittent surfacing, at least. Whenever I run into it again, I’ll try to get some lsof output, but let’s hope the newer gunicorn does indeed help.

[doenietzomoeilijk (Max)]

I’ve run into the error again. So far I’ve dumped the output of lsof (currently 33k+ lines), anything else I could do to aid in debugging this? I’m in no huge hurry to reboot, since I can boss the Docker containers around by command line / Portainer, and other things seem to work just fine.