AccessLog error when setting more than one cookie in a response (Dropwizard 3.0.0)

[staffors]

I'm upgrading our existing DropWizard app to v3.0.0 and now am seeing the following exception in our logs:

16:25:30,693 |-ERROR in io.dropwizard.request.logging.async.AsyncAccessEventAppenderFactory$1[async-console-appender] - Appender [async-console-appender] failed to append. java.lang.IllegalStateException: Duplicate key Set-Cookie (attempted merging values auth=<authValue>; Path=/; Secure; HttpOnly and csrf-token=<csrfValue>; Path=/; Secure; HttpOnly)
	at java.lang.IllegalStateException: Duplicate key Set-Cookie (attempted merging values auth=<authValue>; Path=/; Secure; HttpOnly and csrf-token=<csrfValue>; Path=/; Secure; HttpOnly)
	at 	at java.base/java.util.stream.Collectors.duplicateKeyException(Collectors.java:135)
	at 	at java.base/java.util.stream.Collectors.lambda$uniqKeysMapAccumulator$1(Collectors.java:182)
	at 	at java.base/java.util.stream.ReduceOps$3ReducingSink.accept(ReduceOps.java:169)
	at 	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:992)
	at 	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
	at 	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
	at 	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:921)
	at 	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at 	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:682)
	at 	at io.dropwizard.request.logging.DropwizardJettyServerAdapter.buildResponseHeaderMap(DropwizardJettyServerAdapter.java:37)
	at 	at ch.qos.logback.access.spi.AccessEvent.buildResponseHeaderMap(AccessEvent.java:599)
	at 	at ch.qos.logback.access.spi.AccessEvent.getResponseHeaderMap(AccessEvent.java:604)
	at 	at ch.qos.logback.access.spi.AccessEvent.prepareForDeferredProcessing(AccessEvent.java:616)
	at 	at io.dropwizard.request.logging.async.AsyncAccessEventAppenderFactory$1.preprocess(AsyncAccessEventAppenderFactory.java:22)
	at 	at io.dropwizard.request.logging.async.AsyncAccessEventAppenderFactory$1.preprocess(AsyncAccessEventAppenderFactory.java:19)
	at 	at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:165)
	at 	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
	at 	at io.dropwizard.request.logging.LogbackAccessRequestLog.appendLoopOnAppenders(LogbackAccessRequestLog.java:38)
	at 	at io.dropwizard.request.logging.LogbackAccessRequestLog.log(LogbackAccessRequestLog.java:32)
	at 	at org.eclipse.jetty.server.Request.onCompleted(Request.java:1465)
	at 	at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:966)
	at 	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:485)
	at 	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:282)
	at 	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
	at 	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
	at 	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:558)
	at 	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:379)
	at 	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:146)
	at 	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
	at 	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:416)
	at 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:385)
	at 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:272)
	at 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:194)
	at 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:936)
	at 	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1080)
	at 	at java.base/java.lang.Thread.run(Thread.java:833)

I'm not sure what aspects of our configuration are relevant, but we're running Java 17 and here are the libraries involved

    implementation group: 'io.dropwizard', name: 'dropwizard-core', version: '3.0.0'
    implementation group: 'ch.qos.logback', name: 'logback-core', version: '1.3.7'
    implementation group: 'ch.qos.logback', name: 'logback-classic', version: '1.3.7'
    implementation group: 'ch.qos.logback', name: 'logback-access', version: '1.3.7'

And the relevant bit of our config.yml is

server:
  requestLog:
    appenders:
      - type: console

Does anyone have suggestions of how to work around this? Am I pulling in the wrong dependencies or anything?

The underlying issue appears to be this code fro DropwizardJettyServerAdapter.java:

@Override
public Map<String, String> buildResponseHeaderMap() {
    return response.getHttpFields().stream().collect(Collectors.toMap(HttpField::getName, HttpField::getValue));
}

It could be fixed by adding a merge function along the lines of this:

public Map<String, String> buildResponseHeaderMap() {
    return response.getHttpFields().stream().collect(Collectors.toMap(HttpField::getName, HttpField::getValue, (oldValue, newValue) -> newValue));
}

Of course that would lose values in the resulting map, but then we're losing them anyway with the exception. It looks like this code has changed significantly in DropWizard 4. I'm investigating upgrading to that, but we have a number of old Criteria queries that I think I'd need to rewrite, so that may be more work than I'd like to take on at the moment.

Any thoughts or advice would be appreciated. Thanks!

[zUniQueX]

Hi @staffors. Logback uses the ServerAdapter interface to share logic between various web servers. The return type of the buildResponseHeaderMap() method is Map<String, String> which doesn't reflect the possibility to declare a header multiple times. In contrast, the JAX-RS spec uses a MultivaluedMap<String, String> for request headers.

This wasn't a problem before because Logback simply uses a call to Map#put in their Jetty implementation overriding previous header values which is invisible to a user.

Due to the lack of support for Jetty 10.x, I've had to write a custom ServerAdapter for Dropwizard. This adapter fails (as I think, correctly) with multiple headers and therefore a header conflict is visible to a user.

Dropwizard 4.x doesn't use the custom adapter any more because Logback supports Jetty 11.x in version 1.4.x. There the same code of Logback 1.2.x (used in Dropwizard 2.1.x) is executed again failing silently.

[staffors]

So it feels like the underlying issue is really a shortcoming in the Logback interface, and just happens to be noticeable here because the DropwizardJettyServerAdapter uses a different mechanism to build the Map of headers. What do you think about the idea of updating DropwizardJettyServerAdapter to match the behavior of the Logback implementations? I understand your desire for correctness and to expose the header conflict, but it seems like matching the existing Logback behavior might be better in this instance? It certainly feels like it would be more convenient from a developer standpoint.

[zUniQueX]

My only concern is to build a correct implementation. Because the Logback interface doesn't support this, the only thing we can do is to warn about a conflict. If it's with an exception or a log message or something similar is just an implementation detail. Maybe we can change the implementation to gracefully fail with an additional warning of a suppressed header value.

However, the best option would be a fix on Logback's side. I attempted that in this PR which is still unmerged. This doesn't solve the underlying problem, but would keep our implementation consistent between Dropwizard versions.

As an alternative to the logback-access request log, Jetty provides an own implementation with their CustomRequestLog. You could take a look at that with the Dropwizard classic request log.

[staffors]

Ah, thanks for pointing me toward the classic request log, that appears to be a good workaround that will solve my immediate issue.

I'm not sure what the best solution is otherwise. To me the exception seems a bit heavy handed in this situation, and a warn level log message might be better. But it also might not be worth the effort, particularly given that there are workarounds (classic request log) and that the issue doesn't seem to be a problem for most teams.

Thanks for your work on this issue, I appreciate your thoughtful responses! I think I'll go ahead and close this issue as "not planned" but feel free to re-open it if you'd like a different resolution