Pool balance errors

Troubleshooting
1

I recently set up an install of Rockstor and moved over four varying size hard drives into a pool, adding one at a time. When I added the last one, I received an error in the Balances tab:

Error running a command. cmd = ['btrfs', 'balance', 'start', '-mconvert=single', '-dconvert=single', '/mnt2/media']. rc = 1. stdout = ['']. stderr = ["ERROR: error during balancing '/mnt2/media': Input/output error", 'There may be more info in syslog - try dmesg | tail', '']

Running a manual balance yielded another error:

Error running a command. cmd = ['btrfs', 'balance', 'start', '/mnt2/media']. rc = 1. stdout = ['WARNING:', '', '\tFull balance without filters requested. This operation is very', '\tintense and takes potentially very long. It is recommended to', '\tuse the balance filters to narrow down the balanced data.', "\tUse 'btrfs balance start --full-balance' option to skip this", '\twarning. The operation will start in 10 seconds.', '\tUse Ctrl-C to stop it.', '10 9 8 7 6 5 4 3 2 1', 'Starting balance without any filters.', '']. stderr = ["ERROR: error during balancing '/mnt2/media': Input/output error", 'There may be more info in syslog - try dmesg | tail', '']

Running btrfs fi show I can see the last HDD added is not balanced:

Label: 'media'  uuid: 39fc85f1-e863-41a7-9bc9-3452c9bd9e4d
Total devices 4 FS bytes used 2.42TiB
devid    1 size 596.17GiB used 294.01GiB path /dev/sda
devid    2 size 1.82TiB used 1.52TiB path /dev/sdg
devid    3 size 931.51GiB used 629.00GiB path /dev/sdf
devid    4 size 2.73TiB used 2.00GiB path /dev/sdh

In the Rockstor Logs I see the following errors:

[12/Oct/2016 09:04:58] ERROR [smart_manager.data_collector:620] Failed to update disk state.. exception: 500 Server Error: INTERNAL SERVER ERROR
[12/Oct/2016 09:06:14] ERROR [storageadmin.views.command:75] Exception while refreshing state for Pool(rockstor_rockstor). Moving on: deadlock detected
DETAIL:  Process 7634 waits for ShareLock on transaction 24086; blocked by process 7689.
Process 7689 waits for ShareLock on transaction 24088; blocked by process 7634.
HINT:  See server log for query details.

[12/Oct/2016 09:06:14] ERROR [storageadmin.views.command:76] deadlock detected
DETAIL:  Process 7634 waits for ShareLock on transaction 24086; blocked by process 7689.
Process 7689 waits for ShareLock on transaction 24088; blocked by process 7634.
HINT:  See server log for query details.
Traceback (most recent call last):
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 71, in _refresh_pool_state
    p.save()
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 545, in save
    force_update=force_update, update_fields=update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 573, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 635, in _save_table
    forced_update)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 679, in _do_update
    return filtered._update(values) > 0
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/query.py", line 510, in _update
    return query.get_compiler(self.db).execute_sql(None)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 980, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 786, in execute_sql
    cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/utils.py", line 99, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
OperationalError: deadlock detected
DETAIL:  Process 7634 waits for ShareLock on transaction 24086; blocked by process 7689.
Process 7689 waits for ShareLock on transaction 24088; blocked by process 7634.
HINT:  See server log for query details.

[12/Oct/2016 09:08:44] ERROR [storageadmin.views.command:75] Exception while refreshing state for Pool(rockstor_rockstor). Moving on: deadlock detected
DETAIL:  Process 8122 waits for ShareLock on transaction 24150; blocked by process 8168.
Process 8168 waits for ShareLock on transaction 24139; blocked by process 8122.
HINT:  See server log for query details.

[12/Oct/2016 09:08:44] ERROR [storageadmin.views.command:76] deadlock detected
DETAIL:  Process 8122 waits for ShareLock on transaction 24150; blocked by process 8168.
Process 8168 waits for ShareLock on transaction 24139; blocked by process 8122.
HINT:  See server log for query details.
Traceback (most recent call last):
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 71, in _refresh_pool_state
    p.save()
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 545, in save
    force_update=force_update, update_fields=update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 573, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 635, in _save_table
    forced_update)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 679, in _do_update
    return filtered._update(values) > 0
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/query.py", line 510, in _update
    return query.get_compiler(self.db).execute_sql(None)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 980, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 786, in execute_sql
    cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/utils.py", line 99, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
OperationalError: deadlock detected
DETAIL:  Process 8122 waits for ShareLock on transaction 24150; blocked by process 8168.
Process 8168 waits for ShareLock on transaction 24139; blocked by process 8122.
HINT:  See server log for query details.

[12/Oct/2016 09:09:58] ERROR [storageadmin.views.command:75] Exception while refreshing state for Pool(rockstor_rockstor). Moving on: deadlock detected
DETAIL:  Process 8341 waits for ShareLock on transaction 24173; blocked by process 8343.
Process 8343 waits for ShareLock on transaction 24175; blocked by process 8341.
HINT:  See server log for query details.

[12/Oct/2016 09:09:58] ERROR [storageadmin.views.command:76] deadlock detected
DETAIL:  Process 8341 waits for ShareLock on transaction 24173; blocked by process 8343.
Process 8343 waits for ShareLock on transaction 24175; blocked by process 8341.
HINT:  See server log for query details.
Traceback (most recent call last):
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 71, in _refresh_pool_state
    p.save()
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 545, in save
    force_update=force_update, update_fields=update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 573, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 635, in _save_table
    forced_update)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 679, in _do_update
    return filtered._update(values) > 0
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/query.py", line 510, in _update
    return query.get_compiler(self.db).execute_sql(None)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 980, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 786, in execute_sql
    cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/utils.py", line 99, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
OperationalError: deadlock detected
DETAIL:  Process 8341 waits for ShareLock on transaction 24173; blocked by process 8343.
Process 8343 waits for ShareLock on transaction 24175; blocked by process 8341.
HINT:  See server log for query details.

[12/Oct/2016 09:10:51] ERROR [storageadmin.views.command:75] Exception while refreshing state for Pool(files). Moving on: deadlock detected
DETAIL:  Process 8518 waits for ShareLock on transaction 24205; blocked by process 8603.
Process 8603 waits for ShareLock on transaction 24200; blocked by process 8518.
HINT:  See server log for query details.

[12/Oct/2016 09:10:51] ERROR [storageadmin.views.command:76] deadlock detected
DETAIL:  Process 8518 waits for ShareLock on transaction 24205; blocked by process 8603.
Process 8603 waits for ShareLock on transaction 24200; blocked by process 8518.
HINT:  See server log for query details.
Traceback (most recent call last):
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 71, in _refresh_pool_state
    p.save()
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 545, in save
    force_update=force_update, update_fields=update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 573, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 635, in _save_table
    forced_update)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/base.py", line 679, in _do_update
    return filtered._update(values) > 0
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/query.py", line 510, in _update
    return query.get_compiler(self.db).execute_sql(None)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 980, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 786, in execute_sql
    cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/utils.py", line 99, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)
OperationalError: deadlock detected
DETAIL:  Process 8518 waits for ShareLock on transaction 24205; blocked by process 8603.
Process 8603 waits for ShareLock on transaction 24200; blocked by process 8518.
HINT:  See server log for query details.

[12/Oct/2016 09:10:51] ERROR [storageadmin.middleware:35] Exception occured while processing a request. Path: /api/commands/refresh-pool-state method: POST
[12/Oct/2016 09:10:51] ERROR [storageadmin.middleware:36] An error occurred in the current transaction. You can't execute queries until the end of the 'atomic' block.
Traceback (most recent call last):
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/core/handlers/base.py", line 112, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/views/decorators/csrf.py", line 57, in wrapped_view
    return view_func(*args, **kwargs)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/views/generic/base.py", line 69, 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.6.11-py2.7.egg/django/db/transaction.py", line 371, in inner
    return func(*args, **kwargs)
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 253, in post
    self._refresh_pool_state()
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/transaction.py", line 371, in inner
    return func(*args, **kwargs)
  File "/opt/rockstor/src/rockstor/storageadmin/views/command.py", line 61, in _refresh_pool_state
    if (p.disk_set.count() == 0):
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/manager.py", line 136, in count
    return self.get_queryset().count()
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/query.py", line 294, in count
    return self.query.get_count(using=self.db)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/query.py", line 390, in get_count
    number = obj.get_aggregation(using=using)[None]
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/query.py", line 356, in get_aggregation
    result = query.get_compiler(using).execute_sql(SINGLE)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/models/sql/compiler.py", line 786, in execute_sql
    cursor.execute(sql, params)
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/util.py", line 47, in execute
    self.db.validate_no_broken_transaction()
  File "/opt/rockstor/eggs/Django-1.6.11-py2.7.egg/django/db/backends/__init__.py", line 372, in validate_no_broken_transaction
    "An error occurred in the current transaction. You can't "
TransactionManagementError: An error occurred in the current transaction. You can't execute queries until the end of the 'atomic' block.
[12/Oct/2016 09:10:51] ERROR [smart_manager.data_collector:620] Failed to update pool state.. exception: ['Internal Server Error: No JSON object could be decoded']

Any help is greatly appreciated!

2

Some additional details. I found corrupted files using btrfs scrub. While copying large amounts of data into pools, Rockstor froze on me multiple times which most likely caused these corruptions. I tracked it down to a Samba share I turned on midway, which once turned off did not cause any more freezes.

I found the corrupted files and removed them using:

btrfs scrub start /mnt2/media

Then once uncorrectable errors were detected, the files were located and removed using:

dmesg | grep "checksum error at"

I re-ran the balance and it failed. Dmesg errors:

[89375.033082] BTRFS info (device sda): relocating block group 3179370512384 flags 1
[89375.802262] BTRFS info (device sda): relocating block group 3175075545088 flags 1
[89399.829623] BTRFS warning (device sda): csum failed ino 317 off 1043300352 csum 3526789048 expected csum 1166352627
[89399.891705] BTRFS warning (device sda): csum failed ino 317 off 1043300352 csum 3526789048 expected csum 1166352627
[89423.666611] blk_update_request: I/O error, dev fd0, sector 0
[89423.666765] floppy: error -5 while reading block 0
[89435.984248] blk_update_request: I/O error, dev fd0, sector 0
[89435.984422] floppy: error -5 while reading block 0
[89449.462069] blk_update_request: I/O error, dev fd0, sector 0
[89449.462213] floppy: error -5 while reading block 0
[89461.776918] blk_update_request: I/O error, dev fd0, sector 0
3

@veeco Welcome to the Rockstor community.

This sounds more like there were bad areas on a drive that happened to be accessed / used by a particular share, hence triggering drive hardware time outs which on desktop drives can be in the order of a couple of minutes.

I would first make sure you have all your data backed up and then run full SMART tests on each of the drives in order to check that they can read their entire surface.

Just a thought.

Also note that the single profile has no data redundancy. This makes it particularly vulnerable to drive failure.

The floppy blk_update_request io errors are also strange. Don’t know why anything would be accessing the floppy drive!

4

I did run a quick test that passed. I’ll run full scans.

I’m aware of that. I have two pools, one is raid1 for more important files. The /media pool involved in these issues I don’t really care if I lose some files so storage space is greater priority until I can get some bigger drives for raid6 or similar.[quote=“phillxnet, post:3, topic:2189”]
The floppy blk_update_request io errors are also strange. Don’t know why anything would be accessing the floppy drive!
[/quote]

Yeah that was strange. I went into the bios and disabled A drive floppy support and the errors went away. I don’t even have a floppy drive plugged in.

5

I ran all extended SMART tests on all four drives in the pool. All completed without error.