jonasplaum commented on issue #6183:
URL: https://github.com/apache/couchdb/issues/6183#issuecomment-6506249878
The Nouveau log set to `DEBUG ` show the following (idelTimeout set to 2
seconds for faster repo):
<details>
<summary>nouveau.log</summary>
```
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@4077fb2e
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@8061023
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@7f942cef
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@4ef7b526
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@b99cd9e
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@12c96d86
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@78c425f7
DEBUG [2026-10-29 19:10:54,093] org.eclipse.jetty.io.CyclicTimeouts:
Timeouts check for org.eclipse.jetty.http2.HTTP2Session$StreamTimeouts@190ba6ef
DEBUG [2026-10-29 19:10:54,094] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@21975bdc[{l=/127.0.0.1:5987,r=/127.0.0.1:45736,OPEN,fill=FI,flush=-,to=1951/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@3c254801]
idle timeout check, elapsed: 1951 ms, remaining: 49 ms
DEBUG [2026-10-29 19:10:54,094] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@550ac967[{l=/127.0.0.1:5987,r=/127.0.0.1:45780,OPEN,fill=FI,flush=-,to=1951/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@13b4a99e]
idle timeout check, elapsed: 1951 ms, remaining: 49 ms
DEBUG [2026-10-29 19:10:54,094] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@3a01e197[{l=/127.0.0.1:5987,r=/127.0.0.1:45720,OPEN,fill=FI,flush=-,to=1950/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@65a01eb2]
idle timeout check, elapsed: 1950 ms, remaining: 50 ms
DEBUG [2026-10-29 19:10:54,103] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@79bf38e1[{l=/127.0.0.1:5987,r=/127.0.0.1:45790,OPEN,fill=FI,flush=-,to=1990/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@53e95366]
idle timeout check, elapsed: 1990 ms, remaining: 10 ms
DEBUG [2026-10-29 19:10:54,106] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@49f16a74[{l=/127.0.0.1:5987,r=/127.0.0.1:45756,OPEN,fill=FI,flush=-,to=1996/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@34a9ac69]
idle timeout check, elapsed: 1996 ms, remaining: 4 ms
DEBUG [2026-10-29 19:10:54,106] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@1b7fc764[{l=/127.0.0.1:5987,r=/127.0.0.1:45792,OPEN,fill=FI,flush=-,to=1994/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@568e5541]
idle timeout check, elapsed: 1994 ms, remaining: 6 ms
DEBUG [2026-10-29 19:10:54,106] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@301da2ec[{l=/127.0.0.1:5987,r=/127.0.0.1:45726,OPEN,fill=FI,flush=-,to=2000/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@538e977f]
idle timeout check, elapsed: 2000 ms, remaining: 0 ms
DEBUG [2026-10-29 19:10:54,106] org.eclipse.jetty.io.IdleTimeout:
SocketChannelEndPoint@301da2ec[{l=/127.0.0.1:5987,r=/127.0.0.1:45726,OPEN,fill=FI,flush=-,to=2000/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@538e977f]
idle timeout expired
DEBUG [2026-10-29 19:10:54,106] org.eclipse.jetty.http2.HTTP2Connection:
Processed idle timeout on
HTTP2ServerSession@726708bd{local:/127.0.0.1:5987,remote:/127.0.0.1:45726,sendWindow=7993308,recvWindow=1043163,state=[streams=0,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
! java.util.concurrent.TimeoutException: Session idle timeout 2000 ms
! at
org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onIdleTimeout(HTTP2ServerConnectionFactory.java:118)
! at
org.eclipse.jetty.http2.HTTP2Session.notifyIdleTimeout(HTTP2Session.java:1230)
! at
org.eclipse.jetty.http2.HTTP2Session$StreamsState.onIdleTimeout(HTTP2Session.java:1995)
! at
org.eclipse.jetty.http2.HTTP2Session.onIdleTimeout(HTTP2Session.java:1071)
! at
org.eclipse.jetty.http2.HTTP2Connection.onIdleExpired(HTTP2Connection.java:180)
! at
org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:407)
! at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:170)
! at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:112)
! at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:545)
! at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:328)
! at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:309)
! at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1090)
! at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614)
! at java.base/java.lang.Thread.run(Thread.java:1474)
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Session: Idle
timeout confirmed for
HTTP2ServerSession@726708bd{local:/127.0.0.1:5987,remote:/127.0.0.1:45726,sendWindow=7993308,recvWindow=1043163,state=[streams=0,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Session:
Halting (idle_timeout) for
HTTP2ServerSession@726708bd{local:/127.0.0.1:5987,remote:/127.0.0.1:45726,sendWindow=7993308,recvWindow=1043163,state=[streams=0,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Session:
Sending GoAwayFrame@77c0897c{55/no_error/idle_timeout} on
HTTP2ServerSession@726708bd{local:/127.0.0.1:5987,remote:/127.0.0.1:45726,sendWindow=7993308,recvWindow=1043163,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@77c0897c{55/no_error/idle_timeout},failure=null]}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Flusher:
Appended GoAwayFrame@77c0897c{55/no_error/idle_timeout}, entries=1
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Flusher:
Flushing
HTTP2ServerSession@726708bd{local:/127.0.0.1:5987,remote:/127.0.0.1:45726,sendWindow=7993308,recvWindow=1043163,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@77c0897c{55/no_error/idle_timeout},failure=null]}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Flusher:
Processing GoAwayFrame@77c0897c{55/no_error/idle_timeout}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Flusher:
Generated 29 frame bytes for GoAwayFrame@77c0897c{55/no_error/idle_timeout}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Flusher:
Writing 1 buffers (29 bytes) - entries processed/pending 1/0:
[GoAwayFrame@77c0897c{55/no_error/idle_timeout}]/[]
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.WriteFlusher: write:
WriteFlusher@4d54e78e{IDLE}->null
[DirectByteBuffer@1cf1a1ed[p=0,l=29,c=29,r=29]={<<<\x00\x00\x14\x07\x00\x00\x00\x00\x00\x00\x00\x007\x00\x00\x00\x00idle_timeout>>>}]
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.WriteFlusher: update
WriteFlusher@4d54e78e{WRITING}->null:IDLE-->WRITING
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.SocketChannelEndPoint:
flushed 29
SocketChannelEndPoint@301da2ec[{l=/127.0.0.1:5987,r=/127.0.0.1:45726,OPEN,fill=FI,flush=W,to=2001/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@538e977f]
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.WriteFlusher:
Flushed=true written=29 remaining=0 WriteFlusher@4d54e78e{WRITING}->null
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Session:
Flushed 29/29 frame bytes for GoAwayFrame@77c0897c{55/no_error/idle_timeout}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.WriteFlusher: update
WriteFlusher@4d54e78e{IDLE}->null:WRITING-->IDLE
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Flusher:
Written 1 buffers - entries processed/pending 1/0:
[GoAwayFrame@77c0897c{55/no_error/idle_timeout}]/[]
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.ArrayByteBufferPool:
ByteBuffer
DirectByteBuffer@1cf1a1ed[p=29,l=29,c=29,r=0]={\x00\x00\x14\x07\x00\x00\x00\x00\x00...timeout<<<>>>}
does not belong to this pool, discarding it
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Session:
Terminating
HTTP2ServerSession@726708bd{local:/127.0.0.1:5987,remote:/127.0.0.1:45726,sendWindow=7993308,recvWindow=1043163,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@77c0897c{55/no_error/idle_timeout},failure=null]}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Flusher:
Terminating
HTTP2Flusher@6e8ab1ba[PROCESSING][window_queue=0,frame_queue=0,processed/pending=1/0]
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.http2.HTTP2Session:
Disconnecting
HTTP2ServerSession@726708bd{local:/127.0.0.1:5987,remote:/127.0.0.1:45726,sendWindow=7993308,recvWindow=1043163,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@77c0897c{55/no_error/idle_timeout},failure=null]}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.AbstractEndPoint: close
SocketChannelEndPoint@301da2ec[{l=/127.0.0.1:5987,r=/127.0.0.1:45726,OPEN,fill=FI,flush=-,to=0/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@538e977f]
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.AbstractEndPoint:
close(null)
SocketChannelEndPoint@301da2ec[{l=/127.0.0.1:5987,r=/127.0.0.1:45726,OPEN,fill=FI,flush=-,to=0/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@538e977f]
DEBUG [2026-10-29 19:10:54,107]
org.eclipse.jetty.io.SelectableChannelEndPoint: doClose
SocketChannelEndPoint@301da2ec[{l=/127.0.0.1:5987,r=/127.0.0.1:45726,CLOSED,fill=FI,flush=-,to=0/2000}{io=1/1,kio=1,kro=1}]->[HTTP2ServerConnection@538e977f]
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.FillInterest: onClose
FillInterest@4f0806fb{org.eclipse.jetty.http2.HTTP2Connection$FillableCallback@6d22705d}
DEBUG [2026-10-29 19:10:54,107] org.eclipse.jetty.io.AbstractConnection:
HTTP2ServerConnection@538e977f::SocketChannelEndPoint@301da2ec[{l=null,r=null,CLOSED,fill=-,flush=-,to=0/2000}{io=1/1,kio=-1,kro=-1}]->[HTTP2ServerConnection@538e977f]
onFillInterestedFailed {}
```
</details>
I also wrote a simple bash reproducer. This triggers the error on my local
computer. To speed this up, I set `idleTimeout: 2 seconds` in the nouveau.yaml.
It works with the default of 30 seconds but may take a bit longer, as the
script has fewer chances to hit the race.
<details>
<summary>Reproducer</summary>
```bash
#!/usr/bin/env bash
IDLE_MS=2000 # has to be the nouveau.yaml idleTimeout (defaults to 30000)
URL=http://adm:[email protected]:15984
DB=nouveau_goaway_repro
SEARCH="$URL/$DB/_design/repro/_nouveau/idx?q=foo:bar&limit=1"
now_ms() { local t=${EPOCHREALTIME//[.,]/}; echo $((t / 1000)); }
# 40 concurrent searches, prints the failed ones
burst() {
local i
for i in {1..40}; do
(
resp=$(curl -s -w ' %{http_code}' "$SEARCH")
[[ $resp == *' 200' ]] || echo "${resp//$'\n'/}"
) &
done
wait
}
# test database with a nouveau index
curl -s -X DELETE "$URL/$DB" >/dev/null
curl -s -X PUT "$URL/$DB" >/dev/null
docs=$(for i in {1..100}; do printf '{"foo":"bar"},'; done)
curl -s -H 'Content-Type: application/json' "$URL/$DB/_bulk_docs" -d
"{\"docs\":[${docs%,}]}" >/dev/null
curl -s -X PUT "$URL/$DB/_design/repro" \
-d '{"nouveau":{"idx":{"index":"function(doc){ index(\"string\",
\"foo\", doc.foo); }"}}}' >/dev/null
if ! curl -sf "$SEARCH" >/dev/null; then
echo "search failed, is dev/run running with --with-nouveau?"
exit 1
fi
burst >/dev/null
ref=$(now_ms)
failed=0
for it in {1..60}; do
offset=$((it % 21 * 4 - 60))
wait=$((ref + IDLE_MS + offset - $(now_ms)))
((wait > 0)) && sleep "$((wait / 1000)).$(printf '%03d' $((wait %
1000)))"
out=$(burst)
ref=$(now_ms)
n=$(grep -c . <<<"$out")
failed=$((failed + n))
echo "$(date +%T) iteration $it, offset $offset ms: $n failed"
[[ -n $out ]] && echo "$out"
done
echo "$failed of 2400 searches failed"
```
</details>
This gives me results like this:
```
20:19:22 iteration 1, offset -56 ms: 0 failed
20:19:24 iteration 2, offset -52 ms: 0 failed
20:19:56 iteration 3, offset -48 ms: 9 failed
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"stream_error","reason":"{closed,{error,closed}}"} 500
{"error":"timeout","reason":"The request could not be processed in a
reasonable amount of time."} 500
20:19:58 iteration 4, offset -44 ms: 0 failed
20:20:00 iteration 5, offset -40 ms: 0 failed
20:20:02 iteration 6, offset -36 ms: 0 failed
20:20:04 iteration 7, offset -32 ms: 0 failed
20:20:06 iteration 8, offset -28 ms: 0 failed
20:20:09 iteration 9, offset -24 ms: 0 failed
20:20:11 iteration 10, offset -20 ms: 0 failed
20:20:13 iteration 11, offset -16 ms: 3 failed
{"error":"stream_error","reason":"{goaway,no_error,'The connection is going
away.'}"} 500
{"error":"stream_error","reason":"{goaway,no_error,'The connection is going
away.'}"} 500
{"error":"stream_error","reason":"{goaway,no_error,'The connection is going
away.'}"} 500
```
There are multiple possible messages, like `closed`, `goaway` and `cancel`
depending on the timing the script hits.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
