Andrey Yarovoy created HDDS-17212:
-------------------------------------
Summary: KeyOutputStream.close() fails with "refCnt: expected == 0
but computed == 1" after the key is committed
Key: HDDS-17212
URL: https://issues.apache.org/jira/browse/HDDS-17212
Project: Apache Ozone
Issue Type: Bug
Components: Ozone Client
Reporter: Andrey Yarovoy
## Summary
KeyOutputStream.close() fails with "refCnt: expected == 0 but computed == 1"
after the key has been committed
## Description
### Problem
Closing a key output stream failed while releasing its buffers. The key had
already been committed:
```
java.lang.IllegalStateException: refCnt: expected == 0 but computed == 1
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:77)
at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:82)
at
org.apache.hadoop.hdds.utils.db.CodecBuffer.assertRefCnt(CodecBuffer.java:262)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.release(CodecBuffer.java:304)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.close(CodecBuffer.java:293)
at
org.apache.hadoop.ozone.common.ChunkBufferImplWithByteBuffer.close(ChunkBufferImplWithByteBuffer.java:50)
at java.lang.Iterable.forEach(Iterable.java:75)
at
org.apache.hadoop.hdds.scm.storage.BufferPool.clearBufferPool(BufferPool.java:166)
at
org.apache.hadoop.ozone.client.io.BlockOutputStreamEntryPool.cleanup(BlockOutputStreamEntryPool.java:413)
at
org.apache.hadoop.ozone.client.io.KeyOutputStream.closeInternal(KeyOutputStream.java:670)
at
org.apache.hadoop.ozone.client.io.KeyOutputStream.doInWriteLock(KeyOutputStream.java:259)
at
org.apache.hadoop.ozone.client.io.KeyOutputStream.close(KeyOutputStream.java:646)
at
org.apache.hadoop.ozone.client.io.OzoneOutputStream.close(OzoneOutputStream.java:104)
at
org.apache.hadoop.fs.ozone.OzoneFSOutputStream.close(OzoneFSOutputStream.java:64)
at org.apache.hadoop.fs.FSDataOutputStream.close(FSDataOutputStream.java:106)
at org.apache.hadoop.io.SequenceFile$Writer.close(SequenceFile.java:1437)
at org.apache.hadoop.fs.TestDFSIO$ControlFileCreateTask.run(TestDFSIO.java:326)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
```
Seen once, during TestDFSIO's control-file creation. TestDFSIO writes one small
SequenceFile per map task from a
thread pool, so many `KeyOutputStream`s in one client JVM are written and
closed concurrently. Here that was 250
files on a RATIS/THREE FSO bucket over `ofs://`. The exception aborted the
whole TestDFSIO job. Environment: 12
datanodes, Ozone 2.2.0, Kerberos, `hdds.grpc.tls.enabled=true`.
It's rare. It hit once in about 960 TestDFSIO jobs, which closed several
hundred thousand control-file streams, so
reproducing it will probably need a stress loop.
### Analysis
`CodecBuffer.release()`:
```java
if (buf.release()) {
assertRefCnt(0); // <- fails: computed == 1
} else \{ ... }
```
The `if` branch was taken, so `buf.release()` returned true: Netty decremented
the reference count from 1 to 0 and
deallocated the buffer. For a buffer from `PooledByteBufAllocator`,
deallocation returns both the memory and the
`PooledByteBuf` object itself (through Netty's `Recycler`) to the pools. A
count of 1 on the next line means the
object had already been handed out to a new allocation, which resets the count
to 1.
So `assertRefCnt(0)` after a successful `release()` reads a pooled object that
may no longer belong to this
`CodecBuffer`. That's a use-after-release, and the check can fail for a release
that was correct. Netty already
guarantees that `release()` returning true means the count reached 0, so the
second check adds nothing.
Not yet determined: which concurrent allocation reused the object. Netty
normally recycles an object to the pool
of the thread that created it, and here the allocating and closing thread look
like the same `ControlFileCreateTask`
pool thread. A real double ownership, where two owners release the same
`ByteBuf`, would also produce this, so it
can't be ruled out yet.
### Impact
Whatever the trigger, two problems in the close path turn it into a failure of
a successful write:
1. **close() fails after commitKey().** `KeyOutputStream.closeInternal()`
commits the key and then runs
`blockOutputStreamEntryPool.cleanup()` in `finally`. An exception from buffer
cleanup reaches the caller even
though the key is complete and visible. Callers treat the write as failed:
TestDFSIO aborts the job, and other
applications may retry or delete a good file.
2. **clearBufferPool() stops at the first failure.**
`allocated.forEach(ChunkBuffer::close)` and
`released.forEach(ChunkBuffer::close)` propagate the first exception. The
remaining direct buffers are never
released (a direct-memory leak), and `allocated`/`released`/`currentBuffer`
aren't cleared.
### Proposed fix
1. `CodecBuffer.release()`: don't read `refCnt()` after `buf.release()` returns
true. Either drop the check, or
check `refCnt() == 1` before releasing, while the buffer is still owned.
2. `BufferPool.clearBufferPool()`: close each buffer independently, collecting
failures (log them, or rethrow one
with the rest suppressed after everything has been released), and always clear
the lists.
3. `KeyOutputStream.closeInternal()` (and the other key output streams that
clean up after commit): once the key is
committed, log a buffer-cleanup failure rather than failing `close()`.
Fix 1 removes the trigger if the race hypothesis holds; 2 and 3 make the close
path tolerate any cleanup failure.
### How to reproduce
Not reproduced deliberately yet. Candidate stress test: in one client JVM, N
threads (eg. 64) each repeatedly
create, write a few KB to, and close their own key on a RATIS/THREE bucket,
until `close()` throws
`IllegalStateException: refCnt`. Or run `TestDFSIO -write -nrFiles 1000`
repeatedly; the failure is in the client
before any map task starts.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
