Ceph » CephFS

Started seeing this frequently in mimic test runs:

Things look fine initially:

2019-10-19T14:40:52.036 INFO:tasks.cephfs.test_full:Writing 32MB should fill this cluster
2019-10-19T14:40:52.107 INFO:teuthology.orchestra.run.smithi156:Running:
2019-10-19T14:40:52.107 INFO:teuthology.orchestra.run.smithi156:> cd /home/ubuntu/cephtest/mnt.0 && sudo dd if=/dev/urandom of=large_file_a bs=1M conv=fdatasync count=16 seek=0
2019-10-19T14:40:52.691 INFO:teuthology.orchestra.run.smithi156.stderr:16+0 records in
2019-10-19T14:40:52.691 INFO:teuthology.orchestra.run.smithi156.stderr:16+0 records out
2019-10-19T14:40:52.691 INFO:teuthology.orchestra.run.smithi156.stderr:16777216 bytes (17 MB) copied, 0.50137 s, 33.5 MB/s
2019-10-19T14:40:52.766 INFO:teuthology.orchestra.run.smithi156:Running:
2019-10-19T14:40:52.766 INFO:teuthology.orchestra.run.smithi156:> cd /home/ubuntu/cephtest/mnt.0 && sudo dd if=/dev/urandom of=large_file_b bs=1M conv=fdatasync count=16 seek=0
2019-10-19T14:40:53.395 INFO:teuthology.orchestra.run.smithi156.stderr:16+0 records in
2019-10-19T14:40:53.395 INFO:teuthology.orchestra.run.smithi156.stderr:16+0 records out
2019-10-19T14:40:53.395 INFO:teuthology.orchestra.run.smithi156.stderr:16777216 bytes (17 MB) copied, 0.549403 s, 30.5 MB/s
2019-10-19T14:40:53.397 INFO:tasks.cephfs.test_full:Writing file B succeeded (full status will happen soon)

At this point the cluster is full -- the test waits until pool flags hit `full,full_quota` -- after which I/O operations should fail with ENOSPC, but that does not happen.

019-10-19T14:41:04.707 INFO:teuthology.orchestra.run.smithi156:Running:
2019-10-19T14:41:04.707 INFO:teuthology.orchestra.run.smithi156:> cd /home/ubuntu/cephtest/mnt.0 && sudo dd if=/dev/urandom of=large_file_b bs=1M conv=fdatasync count=50 seek=16
2019-10-19T14:41:06.420 INFO:teuthology.orchestra.run.smithi156.stderr:50+0 records in
2019-10-19T14:41:06.420 INFO:teuthology.orchestra.run.smithi156.stderr:50+0 records out
2019-10-19T14:41:06.421 INFO:teuthology.orchestra.run.smithi156.stderr:52428800 bytes (52 MB) copied, 1.62985 s, 32.2 MB/s
2019-10-19T14:41:06.423 INFO:tasks.cephfs_test_runner:test_full_different_file (tasks.cephfs.test_full.TestQuotaFull) ... FAIL

The monitors have been notified about pool getting full:

2019-10-19 14:41:02.760 7f0d7064f700  0 log_channel(cluster) log [WRN] : pool 'cephfs_data' is full (reached quota's max_bytes: 32 MiB)
2019-10-19 14:41:02.761 7f0d6de4a700 10 mon.b@0(leader).log v351  logging 2019-10-19 14:41:02.761881 mon.b mon.0 172.21.15.62:6789/0 752 : cluster [WRN] pool 'cephfs_data' is full (reached quota's max_bytes: 32 MiB)
2019-10-19 14:41:02.813 7f0d69e42700  7 mon.b@0(leader).log v160 update_from_paxos applying incremental log 160 07e3-0a-13 0e:29:02.0ba019 mon.b mon.0 172.21.15.62:6789/0 2f0 : cluster [WRN] pool 'cephfs_data' is full (reached quota's max_bytes: 32 MiB)

From client/objecter logs the `fsync` goes through directly:

2019-10-19 14:41:06.423 7f7e00ea6700 15 client.5860 using return-valued form of _fsync
2019-10-19 14:41:06.423 7f7e00ea6700 10 client.5860 no metadata needs to commit
2019-10-19 14:41:06.423 7f7e00ea6700 15 client.5860 waiting on data to flush
2019-10-19 14:41:06.426 7f7e09eb8700  1 -- 172.21.15.156:0/3578027966 <== osd.0 172.21.15.156:6801/27852 10 ==== osd_op_reply(27 10000000001.00000010 [write 0~2097152] v109'4 uv4 ondisk = 0) v8 ==== 164+0+0 (1878422747 0 0) 0x56007b631600 con 0x56007b423000
2019-10-19 14:41:06.426 7f7e09eb8700 10 client.5860.objecter ms_dispatch 0x56007b12a5a0 osd_op_reply(27 10000000001.00000010 [write 0~2097152] v109'4 uv4 ondisk = 0) v8
2019-10-19 14:41:06.426 7f7e09eb8700 10 client.5860.objecter in handle_osd_op_reply

ideally, the `fsync` should have requested a new map marking ops for the pool to fail with ENOSPC (log snippet from a different test):

2019-10-19 14:25:39.768 7fa58e13f700 15 client.4906 using return-valued form of _fsync
2019-10-19 14:25:39.768 7fa58e13f700 10 client.4906 no metadata needs to commit
2019-10-19 14:25:39.768 7fa58e13f700 15 client.4906 waiting on data to flush
2019-10-19 14:25:39.774 7fa592948700  1 -- 172.21.15.156:0/4182787481 <== osd.3 172.21.15.156:6807/27857 23 ==== osd_map(1..40 src has 1..43) v4 ==== 17112+0+0 (4122988117 0 0) 0x559538114f00 con 0x559537325600