Please feel free to let me know if any further information required or some more log files needed.

See https://bugzilla.suse.com/show_bug.cgi?id=1206814#c11.

Well, another scenario can also trigger a command hang:

Steps to reproduce:

1. crate a single snapshot

# snapper create --type single --cleanup-algorithm number --print-number --description "type=single,cleanup_algorithm=number" --userdata "type=single,cleanup_algorithm=number"
5

2. list the snapshots, and the command line hang [please see attached log]

#snapper list 

3. I can see the infinite messages in syslog as well:

2023-05-17T06:47:16.052744-04:00 susetest kernel: [  542.090181][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:17.052699-04:00 susetest kernel: [  543.091074][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:18.056728-04:00 susetest kernel: [  544.091999][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:19.056706-04:00 susetest kernel: [  545.093916][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:20.056705-04:00 susetest kernel: [  546.094816][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:21.060708-04:00 susetest kernel: [  547.095873][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:22.060711-04:00 susetest kernel: [  548.096770][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:23.060706-04:00 susetest kernel: [  549.097664][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:24.060706-04:00 susetest kernel: [  550.098541][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:25.060760-04:00 susetest kernel: [  551.099422][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress
2023-05-17T06:47:26.064736-04:00 susetest kernel: [  552.100464][ T2408] BTRFS warning (device vda2): qgroup rescan is already in progress

Corresponding automation test case fails as well at

https://openqa.opensuse.org/tests/3297316#step/snapper_create/24

Created attachment 867085 [details]
strace logs for snapper list

I noticed 'btrfs balance' running in background. It's a btrfs exclusive operation. In automated system deployments, this may lead to timing induced errors such as: XXXX operation in progress

Add '--enqueue' may workaround this issue.

commit e198c6674a440ec699e068c338e66b2632962197
Author: David Sterba <dsterba@suse.com>
Date:   Thu Nov 5 03:38:00 2020 +0100

    btrfs-progs: add enqueue parameter for exclusive ops
    
    The exclusive ops will not start if there's one already running. Now
    that we have the sysfs export (since kernel 5.10) to check if there's
    one already running, use it to allow enqueueing of the operations as a
    convenience.
    
    Supported enqueuing:
    
      btrfs balance start --enqueue
      btrfs filesystem resize --enqueue
      btrfs device add --enqueue
      btrfs device delete --enqueue
      btrfs replace start --enqueue

Most likely a related test failure in 15.5 https://progress.opensuse.org/issues/129685

This is very likely happens in Leap 15.5 also since last week, there are a lot of the same BTRFS warnings indeed then `yast2 lan` or `yast2 sw_single` command hang then, see https://openqa.opensuse.org/tests/3304500

This issue began from Build486.2(6 days ago), at that moment we probably have a snapshot repo update(ie. new changes in SLE15/Updates merged to Leap 15.5) thus I can not spot which change from SLE might be relevant, but very decent I'd say.

(In reply to Max Lin from comment #7)
> This is very likely happens in Leap 15.5 also since last week, there are a
> lot of the same BTRFS warnings indeed then `yast2 lan` or `yast2 sw_single`
> command hang then, see https://openqa.opensuse.org/tests/3304500
> 
> This issue began from Build486.2(6 days ago), at that moment we probably
> have a snapshot repo update(ie. new changes in SLE15/Updates merged to Leap
> 15.5) thus I can not spot which change from SLE might be relevant, but very
> decent I'd say.

See:
https://bugzilla.suse.com/show_bug.cgi?id=1206814#c11

(In reply to Santiago Zarate from comment #8)
> (In reply to Max Lin from comment #7)
> > This is very likely happens in Leap 15.5 also since last week, there are a
> > lot of the same BTRFS warnings indeed then `yast2 lan` or `yast2 sw_single`
> > command hang then, see https://openqa.opensuse.org/tests/3304500
> > 
> > This issue began from Build486.2(6 days ago), at that moment we probably
> > have a snapshot repo update(ie. new changes in SLE15/Updates merged to Leap
> > 15.5) thus I can not spot which change from SLE might be relevant, but very
> > decent I'd say.
> 
> See:
> https://bugzilla.suse.com/show_bug.cgi?id=1206814#c11

Yes, I read it. I'm curious how could this just happened in the very decent 15.5 https://openqa.opensuse.org/tests/3307911#next_previous , we don't have this issue in Leap 15.5 until Build486.2 (it's a tough failing), and seems like we don't have this issue in SLE15 tests on osd? in case we don't have this issue in SLE15-SP5 tests then I suppose Leap15 shouldn't have this issue as well, if that doesn't then we might have something different either in openqa or product.

(In reply to Long An from comment #5)
> I noticed 'btrfs balance' running in background. It's a btrfs exclusive
> operation. In automated system deployments, this may lead to timing induced
> errors such as: XXXX operation in progress
> 
> Add '--enqueue' may workaround this issue.
> 
> commit e198c6674a440ec699e068c338e66b2632962197
> Author: David Sterba <dsterba@suse.com>
> Date:   Thu Nov 5 03:38:00 2020 +0100
> 
>     btrfs-progs: add enqueue parameter for exclusive ops
>     
>     The exclusive ops will not start if there's one already running. Now
>     that we have the sysfs export (since kernel 5.10) to check if there's
>     one already running, use it to allow enqueueing of the operations as a
>     convenience.
>     
>     Supported enqueuing:
>     
>       btrfs balance start --enqueue
>       btrfs filesystem resize --enqueue
>       btrfs device add --enqueue
>       btrfs device delete --enqueue
>       btrfs replace start --enqueue

Thanks much, sorry for my late reply, the workaround seems not work for this issue anyway.

Moving to kernel just like the referenced bug.

as it started in May 12th, and we released snapper on May 12th (the kernel was released on May 9th), I would consider snapper to be the issue.

https://lists.suse.com/pipermail/sle-updates/2023-May/029383.html

blocks currently openqa for leap 15.4 and others

David? can you pick this urgently?

Setting ownership with Arvin, who's current maintianer of snapper.

This bug seems to be triggered by the kernel. We debugged the problem in
bug #1206814: A btrfs quota rescan was running on that machine for more
than half an hour (looked completely stuck). Bug #1206814 is still open.
The log posted in this bug shows that it is the same problem.

What is interesting is that the bug seems to not happen on SLE (at
least the new snapper package with different error handing did pass
QA there).

I haven't seen anything new in kernel that would change the behaviour, most recent fix for rescan/enable is from February. The messages in kernel are triggered after a rescan to request from ioctl when it's already running, not in some runaway loop.

In snapper I see that quota rescan requests are called from various places, like space calculation or querying quotas before cleanup. I cannot evaluate how often this happens, by the timestamps in the logs it's every 1 second, so this matches the 1206814, as said in previous comment. So far nothing new.

What can be improved is to remove the warning, it does not seem to be that critical condition, besides that it's initiated by ioctl and the caller can react based on the error.

(In reply to Richard Fan from comment #10)
> (In reply to Long An from comment #5)
> > I noticed 'btrfs balance' running in background. It's a btrfs exclusive
> > operation. In automated system deployments, this may lead to timing induced
> > errors such as: XXXX operation in progress
> > 
> > Add '--enqueue' may workaround this issue.
> 
> Thanks much, sorry for my late reply, the workaround seems not work for this
> issue anyway.

The exclusive operations do not have quota rescan among them, it's balance, device related etc, so it's possible that background balance can slow down quota rescan. The status of the running exclusive operation is exported in /sys/fs/btrfs/FSID/exclusive_operation , or 'none'.

David could this be turned into a maintenance update for SLES? I do not believe SLES would respin 15.5 GMC because of openSUSE's P1.

If we can remove working as part of the maintenance update we'd have P2 by definition.

Do we have any update on the issue team?

David wanted to look at the problem.

I don't see what could be fixed on the kernel side, removing the warning is a workaround when snapper calls the ioctl frequently. Suggested in commen 18, snapper can check if there's something running and wait witout calling the ioctl.

Well, I think the problem are not the messages per se but the fact that the
quota rescan takes so long (I cannot say how long, but in bug #1206814 more
than half an hour).

In snapper master I have improved the waiting for old btrfs quota
rescans. But since that is only cosmetic I see no point in backporting
that.

I can improved the responsiveness of snapperd when a btrfs quota rescan
is running. But a stuck rescan will still cause trouble (whether detected
by openQA or not I cannot say).

SUSE-RU-2023:2645-1: An update that has one recommended fix can now be installed.

Category: recommended (important)
Bug References: 1211459
Sources used:
SUSE Linux Enterprise Micro for Rancher 5.4 (src): snapper-0.8.16-150300.3.6.1
SUSE Linux Enterprise Micro 5.4 (src): snapper-0.8.16-150300.3.6.1
Basesystem Module 15-SP4 (src): snapper-0.8.16-150300.3.6.1
Basesystem Module 15-SP5 (src): snapper-0.8.16-150300.3.6.1
SUSE Linux Enterprise Real Time 15 SP3 (src): snapper-0.8.16-150300.3.6.1
SUSE Manager Proxy 4.2 (src): snapper-0.8.16-150300.3.6.1
SUSE Manager Retail Branch Server 4.2 (src): snapper-0.8.16-150300.3.6.1
SUSE Manager Server 4.2 (src): snapper-0.8.16-150300.3.6.1
SUSE Linux Enterprise Micro 5.1 (src): snapper-0.8.16-150300.3.6.1
SUSE Linux Enterprise Micro 5.2 (src): snapper-0.8.16-150300.3.6.1
SUSE Linux Enterprise Micro for Rancher 5.2 (src): snapper-0.8.16-150300.3.6.1
openSUSE Leap Micro 5.3 (src): snapper-0.8.16-150300.3.6.1
openSUSE Leap 15.4 (src): snapper-0.8.16-150300.3.6.1
openSUSE Leap 15.5 (src): snapper-0.8.16-150300.3.6.1
SUSE Linux Enterprise Micro for Rancher 5.3 (src): snapper-0.8.16-150300.3.6.1
SUSE Linux Enterprise Micro 5.3 (src): snapper-0.8.16-150300.3.6.1

NOTE: This line indicates an update has been released for the listed product(s). At times this might be only a partial fix. If you have questions please reach out to maintenance coordination.

I hope this is appropriate to add to this bug -- if not, I can open a new one.  Not sure if this satisfies the NEEDINFO, or were you looking for something else?


I have found that 100% of my AutoYAST installations on 15.4 and 15.5 encounter this issue.  (I also just did another 15.3 AY install for comparison, and it is not affected.)  Machines which were installed with 15.3 or earlier and then upgraded have not appeared to hit it, so far.

What happens is that once snapper-cleanup.timer fires 10 minutes after boot, the "qgroup rescan is already in progress" message gets logged once per second, e.g.:
Sep  7 19:31:47 leap154 kernel: [  423.891928][T13669] BTRFS warning (device sda3): qgroup rescan is already in progress
Sep  7 19:31:48 leap154 kernel: [  424.891992][T13669] BTRFS warning (device sda3): qgroup rescan is already in progress
Sep  7 19:31:49 leap154 kernel: [  425.892039][T13669] BTRFS warning (device sda3): qgroup rescan is already in progress

This continues indefinitely (at least overnight), until I do 'systemctl stop snapper-cleanup'.  When the system is in this state, 'snapper ls' hangs indefinitely unless I add --disable-used-space.  (Hitting Ctrl-C successfully aborts snapper, but the message continues to be logged once per second until I 'systemctl stop snapperd', which was apparently spawned via DBus by 'snapper ls'.)

Also, 'btrfs qgroup show /' reports WARNING: rescan is running, qgroup data may be incorrect, and 'btrfs qgroup show --sync /' does NOT wait but returns immediate results after printing said warning.

btrfs quota rescan reports an operation in progress, which appears to never finish (and iostat is idle):
leap154:~ # btrfs quota rescan -s /
rescan operation running (current key 273178625)

Running that without '-s' logs another "BTRFS warning (device sda3): qgroup rescan is already in progress" message.  I see the same output from other debug steps in comments on this bug and boo#1206814 as they did:
- /sys/fs/btrfs/<FSID>/exclusive_operation is "none"
- cat /proc/(pid of [btrfs-qgroup-re])/task/*/stack shows that it's idle/stuck in rescuer_thread, e.g.
[<0>] rescuer_thread+0x2de/0x360
[<0>] kthread+0x156/0x180
[<0>] ret_from_fork+0x22/0x30

I think this may be related to the pre/post snapshots created during installation (e.g. 2nd-stage autoyast installing sssd when configuring auth-client).  This is the snapshot state immediately after installation:
====
leap154:~ # snapper ls --disable-used-space
 # | Type   | Pre # | Date                            | User | Cleanup | Description           | Userdata
---+--------+-------+---------------------------------+------+---------+-----------------------+--------------
0  | single |       |                                 | root |         | current               |
1* | single |       | Thu 07 Sep 2023 07:04:46 PM CDT | root |         | first root filesystem |
2  | pre    |       | Thu 07 Sep 2023 07:09:43 PM CDT | root | number  | zypp(ruby.ruby2.5)    | important=no
3  | post   |     2 | Thu 07 Sep 2023 07:09:45 PM CDT | root | number  |                       | important=no
4  | pre    |       | Thu 07 Sep 2023 07:09:51 PM CDT | root | number  | zypp(ruby.ruby2.5)    | important=no
5  | post   |     4 | Thu 07 Sep 2023 07:09:53 PM CDT | root | number  |                       | important=no
6  | pre    |       | Thu 07 Sep 2023 07:09:56 PM CDT | root | number  | zypp(ruby.ruby2.5)    | important=no
7  | post   |     6 | Thu 07 Sep 2023 07:10:06 PM CDT | root | number  |                       | important=no
8  | single |       | Thu 07 Sep 2023 07:10:51 PM CDT | root | number  | after installation    | important=yes
====

While I've had some VMs magically fix themselves after a number of reboots, the only way I've found to reliably fix this is to remove the pre/post snapshots AND reboot afterwards (until rebooting, the rescan operation is still running with the same key).  E.g. for the above snapshot list, 'snapper rm 2-7'.

After rebooting, it logs a message about clearing an inconsistency flag:
Sep  8 13:26:39 leap154 kernel: [    6.637822][  T362] BTRFS info (device sda3): qgroup scan completed (inconsistency flag cleared)

This message is logged again (once) when snapper-cleanup starts, and also every time I run 'snapper ls', which now runs successfully at least:
Sep  8 13:36:31 leap154 systemd-helper[13438]: running cleanup for 'root'.
Sep  8 13:36:31 leap154 systemd-helper[13438]: running number cleanup for 'root'.
Sep  8 13:36:31 leap154 kernel: [  605.099983][  T362] BTRFS info (device sda3): qgroup scan completed (inconsistency flag cleared)
Sep  8 13:36:31 leap154 systemd-helper[13438]: running timeline cleanup for 'root'.
Sep  8 13:36:31 leap154 systemd-helper[13438]: running empty-pre-post cleanup for 'root'.
...
Sep  8 16:08:02 leap154 dbus-daemon[619]: [system] Activating via systemd: service name='org.opensuse.Snapper' unit='snapperd.service' requested by ':1.37' (uid=0 pid=14085 comm="snapper ls ")
Sep  8 16:08:03 leap154 dbus-daemon[619]: [system] Successfully activated service 'org.opensuse.Snapper'
Sep  8 16:08:03 leap154 kernel: [ 9696.519376][T14021] BTRFS info (device sda3): qgroup scan completed (inconsistency flag cleared)


Both 15.4 & 15.5 have snapper-0.8.16-150300.3.6.1.x86_64.  Kernels are 5.14.21-150400.24.81-default and 5.14.21-150500.55.19-default, respectively.

I may have spoken too soon -- I just did another 15.5 install, and removing the pre/post snapshots and rebooting did not fix the issue this time.

Even running btrfs check from the rescue environment still thinks a qgroup rescan is in progress, which is crazy since the filesystem isn't even mounted!
====
ttyS0:rescue:~ # btrfs check /dev/sda3
Opening filesystem to check...
Checking filesystem on /dev/sda3
UUID: f13af899-5d1d-4611-8d0c-ce42119b8f30
[1/7] checking root items
[2/7] checking extents
[3/7] checking free space cache
[4/7] checking fs roots
[5/7] checking only csums items (without verifying data)
[6/7] checking root refs
[7/7] checking quota groups
Qgroup rescan is running, qgroups will not be printed.
found 2354786304 bytes used, no error found
total csum bytes: 2061704
total tree bytes: 62324736
total fs tree bytes: 55836672
total extent tree bytes: 3457024
btree space waste bytes: 10474331
file data blocks allocated: 2443530240
 referenced 2437812224
====

Mounting it appears to "complete" the qgroup rescan.  After unmounting it and running btrfs-check again, errors are found:
====
ttyS0:rescue:~ # mount /dev/sda3 /mnt; dmesg|tail
[   38.857481] systemd[1]: Starting Rebuild Hardware Database...
[   38.858810] systemd[1]: Starting Load/Save Random Seed...
[   38.860095] systemd[1]: Starting Create System Users...
[   38.866850] systemd[1]: Started Journal Service.
[   38.985727] systemd-journald[2135]: Received client request to flush runtime journal.
[   41.709755] BTRFS: device fsid f13af899-5d1d-4611-8d0c-ce42119b8f30 devid 1 transid 76 /dev/sda3 scanned by (udev-worker) (2190)
[  680.775308] BTRFS info (device sda3): disk space caching is enabled
[  680.775313] BTRFS info (device sda3): has skinny extents
[  680.780807] BTRFS info (device sda3): enabling ssd optimizations
[  681.774359] BTRFS info (device sda3): qgroup scan completed (inconsistency flag cleared)
ttyS0:rescue:~ # umount /mnt
ttyS0:rescue:~ # btrfs check /dev/sda3
Opening filesystem to check...
Checking filesystem on /dev/sda3
UUID: f13af899-5d1d-4611-8d0c-ce42119b8f30
[1/7] checking root items
[2/7] checking extents
[3/7] checking free space cache
[4/7] checking fs roots
[5/7] checking only csums items (without verifying data)
[6/7] checking root refs
[7/7] checking quota groups
Counts for qgroup id: 0/267 are different
our:            referenced 2160812032 referenced compressed 2160812032
disk:           referenced 2160812032 referenced compressed 2160812032
our:            exclusive 20766720 exclusive compressed 20766720
disk:           exclusive 20783104 exclusive compressed 20783104
diff:           exclusive -16384 exclusive compressed -16384
Counts for qgroup id: 0/278 are different
our:            referenced 2141519872 referenced compressed 2141519872
disk:           referenced 2141519872 referenced compressed 2141519872
our:            exclusive 1474560 exclusive compressed 1474560
disk:           exclusive 1490944 exclusive compressed 1490944
diff:           exclusive -16384 exclusive compressed -16384
Counts for qgroup id: 1/0 are different
our:            referenced 2141519872 referenced compressed 2141519872
disk:           referenced 1524371456 referenced compressed 1524371456
diff:           referenced 617148416 referenced compressed 617148416
our:            exclusive 1474560 exclusive compressed 1474560
disk:           exclusive 3170304 exclusive compressed 3170304
diff:           exclusive -1695744 exclusive compressed -1695744
found 2354786304 bytes used, error(s) found
total csum bytes: 2061704
total tree bytes: 62324736
total fs tree bytes: 55836672
total extent tree bytes: 3457024
btree space waste bytes: 10474331
file data blocks allocated: 2443530240
====

Comparing to the output of btrfs subvol list, it appears that 0/267 and 0/268 correspond to the remaining "single" snapshots 1 & 8 from my last comment.

Even more strange, after rebooting back into the installed VM, it now appears to be as "fixed" as expected, i.e. 'snapper ls' works but logs "qgroup scan completed (inconsistency flag cleared)" once each time it's run; same thing for snapper-cleanup.

And in case I was not clear before: when in the "bad" state where it logs that warning once per second, snapper-cleanup never finishes.  In this "fixed but logs the warning once" state, it completes in a couple seconds.

Setting version to Leap 15.5 and clearing NEEDINFO based on comment 29.

Not familiar with snapper, thus can only say from the point of view from btrfs side.

The warning message is triggered because there is a running btrfs quota rescan work.

The rescan work is needed if there is an operation which would lead to qgroup number inconsistency.
(Quite some operations are known to cause qgroup inconsistency, like doing certain snapshot creation with qgroup inherit)

In that case, the first thing we can do is, if snapper sees qgroup is inconsistent, it can also check if qgroup rescan is already running.
This is done by checking the QGROUP_STATUS item for its flags:

- BTRFS_QGROUP_STATUS_FLAG_INCONSISTENT
  Indicates the qgroup is inconsistent.

- BTRFS_QGROUP_STATUS_FLAG_RESCAN
  Indicates there is already a running inconsistent.

By doing this, we can avoid unnecessary rescan (thus avoid the warning message).

For the yast hang, I'm not sure what btrfs feature is triggered, but overall, qgroup rescan itself is both a CPU and IO heavy operation.
Thus it would slow down the system, but should not be that huge.

The exception is snapshot dropping, that's the biggest and the final known quirk of qgroup, which can hugely slow down
the system very much, and it would block the btrfs from committing the current transaction until fully down.
Which I believe is the root cause.

To avoid the problem, newer kernel has introduced a sysfs interface:
- /sys/fs/btrfs/<uuid>/qgroups/drop_subtree_threshold

This interface is to set a threshold that if we're dropping a large qgroup, we disable qgroup temporarily until the
drop is done.
By this we avoid the slowdown, but requires a qgroup rescan later.

I may need to slightly enhance the feature, by setting a good default (by default it's disabled) and do not allow
qgroup rescan to be triggered during the snapshot drop just in case.

Since there are quite some layers involved in the case, let's do it step by step:

- Please update snapper to utilize that drop_subtree_threshold
  Setting it to 3 or 2 would be good enough.

  Then see if the slow down is gone.

- Please update snapper to check if qgroup rescan is already running
  Then see if the warning message flood is gone.

I don't really understand any of that, but that sysfs tunable is not present in the Leap 15.4 or 15.5 kernels (apparently it was added in 6.1?).

Leap 15.6 has kernel 6.4.0, which does have the tunable, but it does not help.  It's 8 by default; I've tried setting it to 3, 2, 1, and even 0, but the behavior in comment 28 still holds: 'snapper ls' or snapper-cleanup hangs and the kernel logs the warning once per second, until snapperd.service is stopped.

That tunable needs to be set early, preferable at mount time.
Or the auto-cleanup can kick in and cause the hang.

I'm considering to make the kernel to default to a lower value.

For older kernels, unfortunately it's not backported thus no way other than disable quota completely.