Rockstor "ERROR: can't list qgroups: quotas not enabled"

Support
1

Brief description of the problem

No share mounted after upgrade 3.9.2-0 to 3.9.2-11

Detailed step by step instructions to reproduce the problem

Updated my system from 3.9.2-0 to 3.9.2-11 using yum update from CLI… ran without error… After reboot, no shares can be mounted.
I thought this quota-related error was fixed in the latest stable release so I’m confused about the origin of the error there. Regardless, I tried the btrfs quota enable /mnt2/main_pool command, which didn’t throw an error.
After a few minutes, the rescan completed with the following output:
Jan 21 15:51:38 rockstor kernel: BTRFS info (device sdc): qgroup scan completed (inconsistency flag cleared)
The Shares page now shows all shares with correct size (they seem correct at least).

The Rock-on service was off due to the shares not being mounted at boot, and manually switching it On works and rebooted all my Rock-ons.
The samba shares seem accessible and everything seems to be working again, but I’m confused as to why the error still appeared.
Also, should I expect it to be coming at every reboot?

Let me know if you’d like more log or information if this wasn’t expected to happen.

2

@Flox Hello again and thanks for the report. Haven’t seen this myself but will take another look once I’m done with my current backlog. Could you paste a log entry around the exception that was thrown as it should contain a back trace that might help with what happened and where.

Yes me too currently. Hopefully the log entry should point to the culprit. I have most likely missed a corner case somewhere in that last sweep I did on improving quota disabled behaviour.

Cheers.

3

Here are some excerpt from rockstor.log

[20/Jan/2018 21:15:13] ERROR [storageadmin.middleware:33] Error running a command. cmd = /sbin/btrfs qgroup show . rc = 1. stdout = ['']. stderr = ["ERROR: cannot access '': No such file or directory", '']
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 323, in post
    import_snapshots(share)
  File "/opt/rockstor/src/rockstor/storageadmin/views/share_helpers.py", line 168, in import_snapshots
    rusage, eusage = volume_usage(share.pool, snaps_d[s][0])
  File "/opt/rockstor/src/rockstor/fs/btrfs.py", line 835, in volume_usage
    out, err, rc = run_command(cmd, log=True)
  File "/opt/rockstor/src/rockstor/system/osi.py", line 121, in run_command
    raise CommandException(cmd, out, err, rc)
CommandException: Error running a command. cmd = /sbin/btrfs qgroup show . rc = 1. stdout = ['']. stderr = ["ERROR: cannot access '': No such file or directory", '']
Package upgrade
[21/Jan/2018 15:01:56] ERROR [storageadmin.views.rockon:81] Rockon(Nextcloud) is in pending state but there is no pending or failed task for it.
[21/Jan/2018 15:02:32] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'show', '']. output: [''] error: ["ERROR: cannot access '': No such file or directory", '']
[21/Jan/2018 15:02:32] ERROR [storageadmin.middleware:32] Exception occured while processing a request. Path: /api/commands/refresh-snapshot-state method: POST
[21/Jan/2018 15:02:32] ERROR [storageadmin.middleware:33] Error running a command. cmd = /sbin/btrfs qgroup show . rc = 1. stdout = ['']. stderr = ["ERROR: cannot access '': No such file or directory", '']
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 323, in post
  File "/opt/rockstor/src/rockstor/storageadmin/views/share_helpers.py", line 168, in import_snapshots
    logger.debug('Db share entry does not exist - creating.')
  File "/opt/rockstor/src/rockstor/fs/btrfs.py", line 835, in volume_usage
    raise e
  File "/opt/rockstor/src/rockstor/system/osi.py", line 121, in run_command
    raise CommandException(cmd, out, err, rc)
CommandException: Error running a command. cmd = /sbin/btrfs qgroup show . rc = 1. stdout = ['']. stderr = ["ERROR: cannot access '': No such file or directory", '']
[21/Jan/2018 15:06:01] ERROR [storageadmin.views.rockon:81] Rockon(DuckDNS) is in pending state but there is no pending or failed task for it.
[21/Jan/2018 15:27:36] ERROR [storageadmin.util:44] exception: Failed to reboot the system due to a low level error: Error running a command. cmd = /usr/sbin/shutdown -r now. rc = -15. stdout = ['']. stderr = ['']
Traceback (most recent call last):
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 257, in post
    msg = ('Failed to reboot the system due to a low level error: '
  File "/opt/rockstor/src/rockstor/system/osi.py", line 1145, in system_reboot
    return run_command([SHUTDOWN, '-r', delta])
  File "/opt/rockstor/src/rockstor/system/osi.py", line 121, in run_command
    raise CommandException(cmd, out, err, rc)
CommandException: Error running a command. cmd = /usr/sbin/shutdown -r now. rc = -15. stdout = ['']. stderr = ['']
[21/Jan/2018 15:28:55] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'show', '/mnt2/main_pool/Windows_Backups']. output: [''] error: ["ERROR: can't list qgroups: quotas not enabled", '']
########################### LINE ABOVE REPEATED FOR EACH OF MY SHARES AND SNAPSHOTS

Then, I rebooted the machine again using the webUI’s reboot button:

[21/Jan/2018 15:33:52] ERROR [storageadmin.util:44] exception: Failed to reboot the system due to a low level error: Error running a command. cmd = /usr/sbin/shutdown -r now. rc = -15. stdout = ['']. stderr = ['']
Traceback (most recent call last):
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 255, in post
    system_reboot(delay)
  File "/opt/rockstor/src/rockstor/system/osi.py", line 1145, in system_reboot
    return run_command([SHUTDOWN, '-r', delta])
  File "/opt/rockstor/src/rockstor/system/osi.py", line 121, in run_command
    raise CommandException(cmd, out, err, rc)
CommandException: Error running a command. cmd = /usr/sbin/shutdown -r now. rc = -15. stdout = ['']. stderr = ['']
[21/Jan/2018 15:35:10] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'show', '/mnt2/main_pool/Windows_Backups']. output: [''] error: ["ERROR: can't list qgroups: quotas not enabled", '']
########################### LINE ABOVE REPEATED FOR EACH OF MY SHARES AND SNAPSHOTS

And then what I believe was after I re-enabled quote through the CLI:

[21/Jan/2018 15:41:46] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/1658', '2015/1', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '
[21/Jan/2018 15:41:47] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/3359', '2015/4', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '
[21/Jan/2018 15:41:47] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/1131', '2015/5', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '
[21/Jan/2018 15:41:47] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/258', '2015/6', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', ''
[21/Jan/2018 15:41:47] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/668', '2015/7', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', ''
[21/Jan/2018 15:41:48] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/413', '2015/10', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '
[21/Jan/2018 15:41:49] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/1472', '2015/13', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed',
[21/Jan/2018 15:41:49] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/1130', '2015/15', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed',
[21/Jan/2018 15:41:49] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/1926', '2015/16', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed',
[21/Jan/2018 16:09:12] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'show', '']. output: [''] error: ["ERROR: cannot access '': No such file or directory", '']

I hope this can prove useful… As you can see, I was already having an error before the upgrade to 3.9.2-11:

[20/Jan/2018 21:15:13] ERROR [storageadmin.middleware:33] Error running a command. cmd = /sbin/btrfs qgroup show . rc = 1. stdout = ['']. stderr = ["ERROR: cannot access '': No such file or directory", '']
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 323, in post
    import_snapshots(share)
  File "/opt/rockstor/src/rockstor/storageadmin/views/share_helpers.py", line 168, in import_snapshots
    rusage, eusage = volume_usage(share.pool, snaps_d[s][0])
  File "/opt/rockstor/src/rockstor/fs/btrfs.py", line 835, in volume_usage
    out, err, rc = run_command(cmd, log=True)
  File "/opt/rockstor/src/rockstor/system/osi.py", line 121, in run_command
    raise CommandException(cmd, out, err, rc)
CommandException: Error running a command. cmd = /sbin/btrfs qgroup show . rc = 1. stdout = ['']. stderr = ["ERROR: cannot access '': No such file or directory", '']

Do you think this will happen again upon reboot?

I hope this will be able to help, let me know if you’d like more info and I’ll do my best.

4

@Flox Thanks, that looks to be what we’re after. Can’t dig in too much right now but does look like we need to catch yet another qgroup error, just a little perplexed at it not showing up here. But the following:

ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'show', '']. output: [''] error: ["ERROR: cannot access '': No such file or directory", '']

Looks very suspicious as the “No such file or directory” is down to nothing being passed ie look to that 3rd parameter, we have’ qgroup’ then ‘show’ then ‘’ an empty string. So looks like we have some case where an empty parameter is falling where it shouldn’t. I.e. a fail through call that should have been caught earlier. We should never have a mnt_pt that is blank, at least by the time it’s used for a call. So this is more an indication of another logical error is my bet. That is we find where and why that happened not just cover it up in catching an exception as things will not go well from there on either if we do. Where as the quota errors we ignore we can work around later (if only just currently).

Note that from a quick look many of the errors logged are not fatal (at least after the update) and are just logged as quotas disabled is still considered an error state for Rockstor but the updates were intended for it to be non ‘fatal’ from the point of view of a mount. But still logged non the less.

If you take a peek at the changes made under the following pull request:

You can see how various errors are caught (in a try except arrangement), logged, and ignored so that the ultimate goal of mounting is then achieved (except in your case unfortunately).

And just prior to that we had the more ‘emergency’ measures patch of:

Which kind of forced our hand at becoming more robust on no quotas.

Hope that helps to fill in what’s going on in that area and I’ll try and take a look shortly. You may find that with those pointers you can work out what I missed. I’d start with backtracking where that empty string came from myself (as well as ensuring all other logged errors were intentionally caught logged and ignored of course). Non ignored exceptions are usually thrown up on the UI though.

Cheers and thanks for you patience. Just got to round out what I’m currently working on first. But others, or yourself of course, may step in with a solution in the mean time. Well done on jury rigging things back up to ‘up-and-running’ again.

5

Thanks for the info @phillxnet!
In case it brings more informaiton for you, upon looking at the log this morning, I noticed the following errors appearing again:

[22/Jan/2018 01:42:05] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/5743', '2015/1', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[22/Jan/2018 04:42:04] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/5744', '2015/1', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']

The timestamps for these seemed like some of my scheduled snapshots, and indeed two snapshots were ran at these times (seemed to have completed successfully).

Should I indeed run a btrfs rescan /mnt2/main_pool again? When I tried after restarting (post-upgrade) and re-enabling quota yesterday, I couldn’t as a rescan was already in progress and completed (seemingly) successfully:

Jan 21 15:51:38 rockstor kernel: BTRFS info (device sdc): qgroup scan completed (inconsistency flag cleared)
6

@Flox Hello again.

That’s a useful addition: thanks.

Not required but desirable for more accurate use reporting. We will get on top of this and we do run a qgroup rescan on occasions but not in all required cases plus the complication is that, as you see, sometimes one is already running due to a prior trigger. Tricky.

Thanks for the additional info, bound to help.

7

@Flox Hello again. As per:

I’m currently looking at share/snapshot import/update code re qgroup/ro failure for another issue but it may be that I can make some headway on your reported issue at the same time.

Could you update to latest stable release and execute the following command to enable debug logging:

/opt/rockstor/bin/debug-mode on

and then reproduce your issue where the ‘bttrfs qroup show’ command was called with a blank 3 parameter? As per:

Which is the currently suspected culprit for the uncaught exception that is ‘spoiling’ the flow through to mounts being enabled.

A copy of the log surrounding this ERROR, with it’s DEBUG enhanced entries should help with find out where this is happening.

No worries if not but while I’m here it may well help as I’ve already made some changes locally (not in pull request yet) that have made qgroup and ro mix more robust re share/snap import/update and mout and if I can see where your issue is happening I may be able to tie in a relevant change as I go.

Cheers.

8

Hi @phillxnet, thanks for sending time on this!

I would gladly provide more info but I’m unfortunately unsure how to reproduce the error… I had to reboot my machine a few days ago and didn’t notice any error since.
Should I simply run btrfs qgroup show ?

9

@Flox

OK, so that’s good news in a way, but what ever caused this empty parameter may still be around and it would be a nice find.

You could still enable the debug logging in case it’s intermittent (ie a race condition) during boot so if your config/install still has the trigger present, but it only shows up intermittently, we can catch more info if it does pop up again.

Thanks.

10

Hi again @phillxnet,
I’m reviving this thread because I noticed a wrong data usage reporting that seems to be the follow-up of this issue I had.

Indeed, the btrfs usage reporting in the web-UI does not seem to fit the actual disk usage. For instance, the following share shows as follows in the webUI:
image

but is:

 btrfs fi du -s /mnt2/emby-media
     Total   Exclusive  Set shared  Filename
  73.41GiB       0.00B    73.41GiB  /mnt2/emby-media

Is this discrepancy normal? Is it related to the snapshots?

image
image1611×377 23.7 KB

The reason I’m wondering whether this could be related to the quota issue I faced in the original post of this topic is because of the following in rockstor.log:

[19/Apr/2018 03:42:06] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11148', '2015/5', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[20/Apr/2018 00:42:05] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11152', '2015/16', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[20/Apr/2018 01:42:03] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11153', '2015/1', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[20/Apr/2018 03:42:21] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11154', '2015/15', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[21/Apr/2018 01:42:06] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11158', '2015/1', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[21/Apr/2018 03:42:03] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11159', '2015/7', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[22/Apr/2018 01:42:03] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11160', '2015/1', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']
[22/Apr/2018 05:42:03] ERROR [system.osi:119] non-zero code(1) returned by command: ['/sbin/btrfs', 'qgroup', 'assign', '0/11161', '2015/13', '/mnt2//main_pool']. output: [''] error: ['WARNING: quotas may be inconsistent, rescan needed', '']

Note that I tried to force a rescan with the same command as my posts above (btrfs rescan /mnt2/main_pool), but the command failed and seems to now be btrfs quota rescan [-sw] <path>. Is the latter a more recent replacement and safe to run?

In advance, thanks, again, for your help!

11

@Flox Hello again.

Don’t know but Rockstor does make some (still incomplete) efforts to account for snapshots via size calculations based on the following command:

btrfs qgroup show /mnt2/share2/

called in the following function:

Also those warning log entries are normal and we do need to improve our quota re-scans a little bit, see @Flyer’s:

https://github.com/rockstor/rockstor-core/issues/1624

Yes, that’s the one; and I don’t think it’s changed: at least for a goodly while:

Not sure if you are still running 3.9.2-11 (that you reported in another forum thread we are both in) but there have been a number of improvements in the quota / size calculation area of things since then, including the ability to disable and re-enable quotas on a pool:

I was able to copy the work done by @ganti_priya on using inline edit in other areas of the UI for this feature which was handy. Thanks Priyanka.

And upon re-enabling quotas a fresh quota rescan is auto initiated. So that might be of interest. That post includes a pic of where this feature was put in the UI and a rough guide on it’s expected behaviour.

But there are known limitations / bugs still existing in how we calculate size but we are getting better at it. I have planned another session on this area of the code but it may take me a while to get to it as there are a few more pressing Rockstor engagements for me to tack first.

Hope that helps and do keep in mind that it can take several minutes for a quota rescan to complete and while it is on going Rockstor will display ‘interim’ values that are obviously incomplete.

12

Thanks a lot for the details!

Everything seems good, then… I’ll wait for a rescan to be triggered automatically after a snaphot, or simply will trigger one manually if I get too impatient.

Thanks again!