“待处理/未准备中时关闭"；码头的警告 [英] "Closed while Pending/Unready" warnings from Jetty
问题描述
在我们的异步servlet中修复了同步问题之后，我们仍然很少见
After fixing synchronization issues in our async servlet we still got rare
java.io.IOException: Closed while Pending/Unready
来自码头的警告.通过以上修复，在我们的生产系统中，它从〜90/天减少至〜5/天. 它很少见，看起来似乎好很多，但可能仍缺少一些细微之处.
warnings from Jetty. With the fixes above it decreased from ~90/day to ~5/day in our production system. It's rare and it seems a lot better but probably something minor is still missing.
完整的堆栈跟踪:
[jetty-63523] (HttpOutput.java:287) -
java.io.IOException: Closed while Pending/Unready
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:285)
at org.eclipse.jetty.server.Response.closeOutput(Response.java:1044)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:493)
at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:293)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680)
at java.lang.Thread.run(Thread.java:748)
唯一写入输出流(不同步)的代码是以下setContentType()，setStatus()和flushBuffer()调用:
The only code which writes to the output stream (without synchronization) is the following setContentType(), setStatus() and flushBuffer() calls here:
@Override
protected void doPost(final HttpServletRequest req, final HttpServletResponse resp)
throws ServletException, IOException {
resp.setContentType(MediaType.OCTET_STREAM.type());
resp.setStatus(HttpServletResponse.SC_OK);
resp.setBufferSize(4096);
resp.flushBuffer();
final AsyncContext async = req.startAsync();
async.setTimeout(5_000); // millis
final ServletOutputStream output = resp.getOutputStream();
final QueueWriteListener writeListener = new QueueWriteListener(async, output);
async.addListener(writeListener);
output.setWriteListener(writeListener);
}
这是在设置我们的QueueWriteListener之前运行的，因此，如果flushBuffer()是同步的，那应该没问题.
This runs before our QueueWriteListener is set, so if flushBuffer() is synchronous it should not be a problem.
Anyway, looking up source code of Jetty, Reponse.flush() calls HttpOutput.flush() where calling new AsyncFlush().iterate() seems suspicious but debugging the doPost()/flushBuffer() this case branch is not run.
完整代码:
@Override
protected void doPost(final HttpServletRequest req, final HttpServletResponse resp)
throws ServletException, IOException {
resp.setContentType(MediaType.OCTET_STREAM.type());
resp.setStatus(HttpServletResponse.SC_OK);
resp.setBufferSize(4096);
resp.flushBuffer();
final AsyncContext async = req.startAsync();
async.setTimeout(5_000); // millis
final ServletOutputStream output = resp.getOutputStream();
final QueueWriteListener writeListener = new QueueWriteListener(async, output);
async.addListener(writeListener);
output.setWriteListener(writeListener);
}
private static class QueueWriteListener implements AsyncListener, WriteListener {
private static final Logger logger = LoggerFactory.getLogger(QueueWriteListener.class);
private final AsyncContext asyncContext;
private final ServletOutputStream output;
@GuardedBy("this")
private boolean completed = false;
public QueueWriteListener(final AsyncContext asyncContext, final ServletOutputStream output) {
this.asyncContext = checkNotNull(asyncContext, "asyncContext cannot be null");
this.output = checkNotNull(output, "output cannot be null");
}
@Override
public void onWritePossible() throws IOException {
writeImpl();
}
private synchronized void writeImpl() throws IOException {
if (completed) {
return;
}
while (output.isReady()) {
final byte[] message = getNextMessage();
if (message == null) {
output.flush();
return;
}
output.write(message);
}
}
private synchronized void completeImpl() {
// also stops DataFeederThread to call bufferArrived
completed = true;
asyncContext.complete();
}
@Override
public void onError(final Throwable t) {
logger.error("Writer.onError", t);
completeImpl();
}
public void dataArrived() {
try {
writeImpl();
} catch (RuntimeException | IOException e) {
...
}
}
public void noMoreData() {
completeImpl();
}
@Override
public synchronized void onComplete(final AsyncEvent event) throws IOException {
completed = true; // might not needed but does not hurt
}
@Override
public synchronized void onTimeout(final AsyncEvent event) throws IOException {
completeImpl();
}
@Override
public void onError(final AsyncEvent event) throws IOException {
logger.error("onError", event.getThrowable());
}
...
}
因此，似乎在Jetty完成和(异步)关闭输出之间，没有人可以写入输出，因此不应将其状态更改为未决或未就绪.尽管如此，它仍然会以某种方式发生. Closed while Pending/Unready警告的可能原因是什么?
So, it seems that between completing and (asynchronously) closing the output by Jetty noone can write to the output, therefore its state should not be changed to pending or unready. Despite of that it still happens somehow. What could be the cause of this Closed while Pending/Unready warning?
我已经检查了日志(无相关内容).
I have checked our logs (nothing relevant).
onError(AsyncEvent event)在我们的代码中还不是synchronized(但是)，因为它的日志消息从未出现在我们的日志中，所以它并不相关.
onError(AsyncEvent event) is not synchronized in our code (yet) but it's not relevant since its log message has never shown up in our log.
在GitHub上的相关讨论: https://github.com/eclipse/jetty. project/issues/2689
Related discussion on GitHub: https://github.com/eclipse/jetty.project/issues/2689
推荐答案
我能够使用以下代码重现警告:
I was able to reproduce the warning with this code:
@Override
protected void doPost(final HttpServletRequest req, final HttpServletResponse resp)
throws ServletException, IOException {
resp.setContentType(MediaType.OCTET_STREAM.type());
resp.setStatus(HttpServletResponse.SC_OK);
resp.setBufferSize(8192);
resp.flushBuffer();
final AsyncContext async = req.startAsync();
async.setTimeout(10_000); // millis
final ServletOutputStream output = resp.getOutputStream();
final QueueWriteListener writeListener = new QueueWriteListener(output);
async.addListener(writeListener);
output.setWriteListener(writeListener);
}
private static class QueueWriteListener implements AsyncListener, WriteListener {
private static final Logger logger = LoggerFactory.getLogger(QueueWriteListener.class);
private final ServletOutputStream output;
public QueueWriteListener(final ServletOutputStream output) {
this.output = checkNotNull(output, "output cannot be null");
}
@Override
public void onWritePossible() throws IOException {
logger.info("onWritePossible()");
long written = 0;
while (output.isReady()) {
final byte[] data = new byte[8 * 1024 * 1024];
Arrays.fill(data, (byte) 'W');
output.write(data);
written += data.length;
logger.info("write OK, written: {} KB", written / 1024);
}
logger.info("onWritePossible() end");
}
@Override
public void onError(final Throwable t) {
logger.info("Writer.onError -Error: {}, Message: {}", t.getClass().getName(), t.getMessage());
}
@Override
public void onComplete(final AsyncEvent event) throws IOException {
logger.warn("onComplete: {}", event);
}
@Override
public void onTimeout(final AsyncEvent event) throws IOException {
logger.warn("onTimeout()");
}
@Override
public void onError(final AsyncEvent event) throws IOException {
logger.error("onError: {}", event, event.getThrowable());
}
@Override
public void onStartAsync(final AsyncEvent event) throws IOException {
logger.info("onStartAsync: {}", event);
}
}
并且使用慢速的curl客户端:
And with a slow curl client:
curl --limit 16 -XPOST http://localhost:35419/example2
结果:
10:39:29,063 INFO [jetty-16] {Example2Servlet.java:52} - onWritePossible()
10:39:29,084 INFO [jetty-16] {Example2Servlet.java:59} - write OK, written: 8192 KB
10:39:29,084 INFO [jetty-16] {Example2Servlet.java:61} - onWritePossible() end
10:39:39,085 WARN [jetty-17] {Example2Servlet.java:76} - onTimeout()
10:39:39,088 WARN [jetty-17] {HttpOutput.java:286} - java.io.IOException: Closed while Pending/Unready, requestUrl=http://localhost:35419/example2
10:39:39,090 INFO [jetty-17] {HttpOutput.java:287} -
java.io.IOException: Closed while Pending/Unready, requestUrl=http://localhost:35419/example2
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:285)
at org.eclipse.jetty.server.Response.closeOutput(Response.java:1044)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:493)
at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:293)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680)
at java.lang.Thread.run(Thread.java:748)
10:39:39,091 WARN [jetty-17] {Example2Servlet.java:71} - onComplete: org.eclipse.jetty.server.AsyncContextEvent@3b51901
注意事项:
- 它不使用任何第三方线程.
- 在原始代码中，在
onTimeout()中有一个complete()调用，但是它不影响行为，因此我将其删除. - 我还从方法声明中删除了
synchronized关键字-它们不影响行为. -
我能够使用不同的缓冲区和数组大小来重现相同的行为，该警告迟早会出现. (例如，缓冲区大小为8192字节，数组大小为1024字节也可以重现警告，但需要更多时间.)这通常会导致其他调试日志，如下所示:
- It does not use any third party threads.
- In the original code there was a
complete()call inonTimeout(), but it does not influence the behavior, so I removed it. - I also removed the
synchronizedkeywords from method declarations - they do not influence the behavior. I was able to reproduce the same behavior with different buffer and array sizes, the warning came sooner or later. (For example, buffer size of 8192 bytes and array size of 1024 bytes also reproduces the warning but needs a little bit more time.) This usually results additional debug logs, like this one:
DEBUG [jetty-12] {HttpOutput.java:1271} - EOF of org.eclipse.jetty.server.HttpOutput$AsyncWrite@4b8dff34[PROCESSING]
这篇关于“待处理/未准备中时关闭"；码头的警告的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
