Finagle exception: "This writer's reader has been discarded"

prdoyle · August 17, 2017, 4:18pm

When I apply load to linkerd for my service (~30 requests per second) I start seeing a few of these exceptions per minute. Any hints?

I’m happy to supply any more info that would help. I’m a bit new to linkerd so I’m not even sure what sorts of things are helpful. Want to see my config files? OS / platform info? (I’m using Docker for Windows BTW.)

W 0817 15:16:33.020 UTC THREAD24 TraceId:6cf8fbc2d0b9399f: Exception propagated to the default monitor (upstream address: /172.20.0.3:60158, downstream address: /172.20.0.3:4567, label: #/io.l5d.fs/icecube).

com.twitter.io.Reader$ReaderDiscarded: This writer's reader has been discarded
   at com.twitter.finagle.netty4.http.StreamTransports$$anon$1.discard(StreamTransports.scala:70)
   at com.twitter.finagle.http.DelayedReleaseService$$anon$2.discard(DelayedReleaseService.scala:56)
   at com.twitter.finagle.http.codec.HttpServerDispatcher$$anonfun$handle$2.applyOrElse(HttpServerDispatcher.scala:61)
   at com.twitter.finagle.http.codec.HttpServerDispatcher$$anonfun$handle$2.applyOrElse(HttpServerDispatcher.scala:60)
   at com.twitter.util.Promise.raise(Promise.scala:681)
   at com.twitter.util.Future$JoinPromise$$anonfun$2.applyOrElse(Future.scala:254)
   at com.twitter.util.Future$JoinPromise$$anonfun$2.applyOrElse(Future.scala:251)
   at com.twitter.util.Promise.raise(Promise.scala:681)
   at com.twitter.util.Promise.raise(Promise.scala:686)
   at com.twitter.finagle.http.exp.GenSerialServerDispatcher.$anonfun$new$1(ServerDispatcher.scala:125)
   at com.twitter.util.Future.$anonfun$ensure$1(Future.scala:941)
   at com.twitter.util.Future.$anonfun$ensure$1$adapted(Future.scala:941)
   at com.twitter.util.Promise$Monitored.apply(Promise.scala:202)
   at com.twitter.util.Promise$Monitored.apply(Promise.scala:193)
   at com.twitter.util.Promise$$anon$7.run(Promise.scala:530)
   at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:200)
   at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:158)
   at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:272)
   at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:108)
   at com.twitter.util.Promise.runq(Promise.scala:520)
   at com.twitter.util.Promise.updateIfEmpty(Promise.scala:877)
   at com.twitter.finagle.netty4.transport.ChannelTransport.com$twitter$finagle$netty4$transport$ChannelTransport$$fail(ChannelTransport.scala:95)
   at com.twitter.finagle.netty4.transport.ChannelTransport$$anon$1.channelInactive(ChannelTransport.scala:186)
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)

olix0r · August 17, 2017, 4:25pm

Hi @prdoyle!

Can you share your linkerd configuration?

At a fist guess, this could be related to timeouts or request cancellations.

To that end, if you can share linkerd’s runtime metrics (when it’s in this state), that would also be helpful. You can get metrics with, for example

curl  -Os "http://$linkerdhost:9990/admin/metrics.json?pretty=1"

prdoyle · August 17, 2017, 4:42pm

Ok, I’ve included the config below. Thanks!

The metrics are too large to paste in here. I’m not sure how to get them to you. Any suggestions?

linkerd.yaml:

admin:
  port: 9990

routers:
- protocol: http
  label: icecube
  servers:
  - port: 4568
    ip: 0.0.0.0
  identifier:
    kind: io.l5d.path
    segments: 2 # /cube/shard
    consume: true
  interpreter:
    kind: io.l5d.namerd
    dst: /$/inet/namerd/4100

telemetry:
- kind: io.l5d.tracelog
  sampleRate: 1.0
  level: DEBUG

namerd.yaml:

storage:
  kind: io.l5d.inMemory
  namespaces:
    default: |
      /hosts => /#/io.l5d.fs;
      /svc/shardedCube/oddShard  => /hosts/icecube;
      /svc/shardedCube/evenShard => /hosts/icecube;
namers:
- kind: io.l5d.fs
  rootDir: static-config
interfaces:
- kind: io.l5d.thriftNameInterpreter
  port: 4100
  ip: 0.0.0.0
  retryBaseSecs:  600
  retryJitterSecs: 60
- kind: io.l5d.httpController
  port: 4180
  ip: 0.0.0.0

linker-compose.yaml sections:

version: '3'
services:
  linkerd:
    build:
      context: linkerd
    networks:
     main-network:
       aliases:
         - linkerd
    ports:
     - "4568:4568" # My service
     - "9990:9990" # Admin
  namerd:
    build:
      context: namerd
    networks:
     main-network:
       aliases:
         - namerd
    ports:
     - "9991:9991" # Admin
     - "4180:4180"
networks:
  main-network:

Alex · August 17, 2017, 5:07pm

Are any of the requests failing? Can you describe what the caller of Linkerd sees in this case? A 5XX response? What symptoms are there other than the errors messages in the Linkerd logs?

prdoyle · August 17, 2017, 5:28pm

Oh boy, I can’t believe I didn’t even tell you the symptom! The caller is seeing a 502: Bad Gateway. I’m not exactly sure how to check the linkerd logs.

Alex · August 17, 2017, 7:05pm

Is there any message in the body of the 502 response?

esbie · August 17, 2017, 7:07pm

There should be an upload file button on the toolbar above the text field.

esbie · August 17, 2017, 7:11pm

getting logs from docker-compose usually looks something like docker-compose logs linkerd

prdoyle · August 17, 2017, 7:29pm

Sadly, with the upload button, I get “Sorry, new users can not upload attachments.”

The 502 body is the text This writer's reader has been discarded.

Running docker-compose logs linkerd just showed the same JVM backtrace throwing com.twitter.io.Reader$ReaderDiscarded.

linkerd_1  | Aug 17, 2017 7:27:45 PM com.twitter.finagle.http.HttpMuxer$ $anonfun$new$1
linkerd_1  | INFO: HttpMuxer[/admin/metrics.json] = com.twitter.finagle.stats.MetricsExporter(<function1>)
linkerd_1  | Aug 17, 2017 7:27:45 PM com.twitter.finagle.http.HttpMuxer$ $anonfun$new$1
linkerd_1  | INFO: HttpMuxer[/admin/per_host_metrics.json] = com.twitter.finagle.stats.HostMetricsExporter(<function1>)
linkerd_1  | I 0817 19:27:45.696 UTC THREAD1: linkerd 1.1.3 (rev=6ae598a0f4cd34624fdffe921bc0fb7890c1028f) built at 20170809-135256
linkerd_1  | I 0817 19:27:46.081 UTC THREAD1: Finagle version 6.45.0 (rev=fadc80cdd804f2885ebc213964542d5568a4f485) built at 20170609-103217
linkerd_1  | I 0817 19:27:48.638 UTC THREAD1: Tracer: com.twitter.finagle.zipkin.thrift.ScribeZipkinTracer
linkerd_1  | I 0817 19:27:48.762 UTC THREAD1: connecting to usageData proxy at Set(Inet(stats.buoyant.io/104.28.22.233:443,Map()))
linkerd_1  | I 0817 19:27:48.880 UTC THREAD1: tracer: io.buoyant.telemetry.TracelogTracer@7c7270af
linkerd_1  | I 0817 19:27:49.001 UTC THREAD1: Resolver[inet] = com.twitter.finagle.InetResolver(com.twitter.finagle.InetResolver@6573d2f7)
linkerd_1  | I 0817 19:27:49.002 UTC THREAD1: Resolver[fixedinet] = com.twitter.finagle.FixedInetResolver(com.twitter.finagle.FixedInetResolver@4052c8c2)
linkerd_1  | I 0817 19:27:49.007 UTC THREAD1: Resolver[neg] = com.twitter.finagle.NegResolver$(com.twitter.finagle.NegResolver$@181b8c4b)
linkerd_1  | I 0817 19:27:49.009 UTC THREAD1: Resolver[nil] = com.twitter.finagle.NilResolver$(com.twitter.finagle.NilResolver$@38eb0f4d)
linkerd_1  | I 0817 19:27:49.011 UTC THREAD1: Resolver[fail] = com.twitter.finagle.FailResolver$(com.twitter.finagle.FailResolver$@437486cd)
linkerd_1  | I 0817 19:27:49.012 UTC THREAD1: Resolver[flag] = com.twitter.server.FlagResolver(com.twitter.server.FlagResolver@15b642b9)
linkerd_1  | I 0817 19:27:49.013 UTC THREAD1: Resolver[zk] = com.twitter.finagle.zookeeper.ZkResolver(com.twitter.finagle.zookeeper.ZkResolver@518bfd90)
linkerd_1  | I 0817 19:27:49.015 UTC THREAD1: Resolver[zk2] = com.twitter.finagle.serverset2.Zk2Resolver(com.twitter.finagle.serverset2.Zk2Resolver@317a118b)
linkerd_1  | I 0817 19:27:49.583 UTC THREAD1: serving http admin on /0.0.0.0:9990
linkerd_1  | I 0817 19:27:49.612 UTC THREAD1: serving icecube on /0.0.0.0:4568
linkerd_1  | I 0817 19:27:49.647 UTC THREAD1: initialized
linkerd_1  | W 0817 19:28:47.327 UTC THREAD26 TraceId:0ae019c580eb4f08: Exception propagated to the default monitor (upstream address: /172.20.0.2:53236, downstream address: /172.20.0.2:4567, label: #/io.l5d.fs/icecube).
linkerd_1  | com.twitter.io.Reader$ReaderDiscarded: This writer's reader has been discarded
linkerd_1  |    at com.twitter.finagle.netty4.http.StreamTransports$$anon$1.discard(StreamTransports.scala:70)
linkerd_1  |    at com.twitter.finagle.http.DelayedReleaseService$$anon$2.discard(DelayedReleaseService.scala:56)
linkerd_1  |    at com.twitter.finagle.http.codec.HttpServerDispatcher$$anonfun$handle$2.applyOrElse(HttpServerDispatcher.scala:61)
linkerd_1  |    at com.twitter.finagle.http.codec.HttpServerDispatcher$$anonfun$handle$2.applyOrElse(HttpServerDispatcher.scala:60)
linkerd_1  |    at com.twitter.util.Promise.raise(Promise.scala:681)
linkerd_1  |    at com.twitter.util.Future$JoinPromise$$anonfun$2.applyOrElse(Future.scala:254)
linkerd_1  |    at com.twitter.util.Future$JoinPromise$$anonfun$2.applyOrElse(Future.scala:251)
linkerd_1  |    at com.twitter.util.Promise.raise(Promise.scala:681)
linkerd_1  |    at com.twitter.util.Promise.raise(Promise.scala:686)
linkerd_1  |    at com.twitter.finagle.http.exp.GenSerialServerDispatcher.$anonfun$new$1(ServerDispatcher.scala:125)
linkerd_1  |    at com.twitter.util.Future.$anonfun$ensure$1(Future.scala:941)
linkerd_1  |    at com.twitter.util.Future.$anonfun$ensure$1$adapted(Future.scala:941)
linkerd_1  |    at com.twitter.util.Promise$Monitored.apply(Promise.scala:202)
linkerd_1  |    at com.twitter.util.Promise$Monitored.apply(Promise.scala:193)
linkerd_1  |    at com.twitter.util.Promise$$anon$7.run(Promise.scala:530)
linkerd_1  |    at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:200)
linkerd_1  |    at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:158)
linkerd_1  |    at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:272)
linkerd_1  |    at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:108)
linkerd_1  |    at com.twitter.util.Promise.runq(Promise.scala:520)
linkerd_1  |    at com.twitter.util.Promise.updateIfEmpty(Promise.scala:877)
linkerd_1  |    at com.twitter.finagle.netty4.transport.ChannelTransport.com$twitter$finagle$netty4$transport$ChannelTransport$$fail(ChannelTransport.scala:95)
linkerd_1  |    at com.twitter.finagle.netty4.transport.ChannelTransport$$anon$1.channelInactive(ChannelTransport.scala:186)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at com.twitter.finagle.netty4.channel.ChannelRequestStatsHandler.channelInactive(ChannelRequestStatsHandler.scala:36)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.handler.codec.MessageAggregator.channelInactive(MessageAggregator.java:417)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at io.netty.handler.codec.http.HttpContentEncoder.channelInactive(HttpContentEncoder.java:277)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:420)
linkerd_1  |    at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:360)
linkerd_1  |    at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:325)
linkerd_1  |    at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:223)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
linkerd_1  |    at com.twitter.finagle.netty4.channel.ChannelStatsHandler.channelInactive(ChannelStatsHandler.scala:115)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
linkerd_1  |    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1329)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
linkerd_1  |    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
linkerd_1  |    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:908)
linkerd_1  |    at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:744)
linkerd_1  |    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
linkerd_1  |    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
linkerd_1  |    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:462)
linkerd_1  |    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
linkerd_1  |    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
linkerd_1  |    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
linkerd_1  |    at com.twitter.finagle.util.BlockingTimeTrackingThreadFactory$$anon$1.run(BlockingTimeTrackingThreadFactory.scala:24)
linkerd_1  |    at java.lang.Thread.run(Thread.java:748)

esbie · August 17, 2017, 7:35pm

I can repro a reader discarded error but with different setup/results: https://github.com/linkerd/linkerd/issues/1594

I’ve update your user permissions if you want to try the upload button again, thanks!

Alex · August 17, 2017, 8:43pm

An interesting difference between https://github.com/linkerd/linkerd/issues/1594 and what you report here is that in @esbie’s setup, we never see 502 responses, only 500s that are legitimately returned from the destination service.

In other words, https://github.com/linkerd/linkerd/issues/1594 describes an issue where the logging is unnecessarily verbose but everything is otherwise working as intended. On the other hand, the issue you’ve reported here where Linkerd returns a 502 sounds like a real bug that we have not yet been able to reproduce.

prdoyle · August 17, 2017, 9:11pm

@esbie - Thanks! Here’s the metrics file…metrics.json (45.7 KB)

prdoyle · August 17, 2017, 9:14pm

@Alex - Would you like me to open a GitHub Issue?

prdoyle · August 19, 2017, 12:34pm

Ok, I made a Github Issue:

william · August 21, 2017, 8:52pm

@prdoyle thanks for filing that.

system · September 20, 2017, 8:53pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.