feeder stalls due to scala.MatchError

45 views
Skip to first unread message

Rahul Maddimsetty

unread,
Oct 24, 2014, 5:33:42 PM10/24/14
to iago-...@googlegroups.com
I've just gotten started using Iago as a library to load test services at Foursquare. At present I'm trying to run a single server and feeder on localhost against a victim serverset in zookeeper at 1000 RPS.

I've managed to get reasonably short runs to complete successfully but I just started to notice the feeder stall on longer runs after a few hundred thousand requests have been sent. The victims are holding up to the load just fine. When I look in the feeder log, I see this exception:

ERR [20141024-20:44:35.377] feeder: scala.MatchError: ServiceName(client) (of class com.twitter.finagle.tracing.Annotation$ServiceName)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.zipkin.thrift.RawZipkinTracer.record(RawZipkinTracer.scala:147)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.zipkin.thrift.SamplingTracer.record(ZipkinTracer.scala:85)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.Trace$$anonfun$uncheckedRecord$1.apply(Trace.scala:234)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.Trace$$anonfun$uncheckedRecord$1.apply(Trace.scala:234)

ERR [20141024-20:44:35.377] feeder:     at scala.collection.immutable.List.foreach(List.scala:318)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.Trace$.uncheckedRecord(Trace.scala:234)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.Trace$.record(Trace.scala:280)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.Trace$.recordServiceName(Trace.scala:304)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.TracingFilter$$anonfun$apply$1.apply(TracingFilter.scala:38)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.TracingFilter$$anonfun$apply$1.apply(TracingFilter.scala:35)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.Trace$.unwind(Trace.scala:210)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.tracing.TracingFilter.apply(TracingFilter.scala:35)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.Filter$$anon$2.apply(Filter.scala:69)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.FactoryToService$$anonfun$apply$4.apply(Service.scala:199)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.finagle.FactoryToService$$anonfun$apply$4.apply(Service.scala:198)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:784)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:783)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise$Transformer.liftedTree1$1(Promise.scala:93)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise$Transformer.k(Promise.scala:93)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise$Transformer.apply(Promise.scala:102)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise$Transformer.apply(Promise.scala:84)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise$$anon$3.run(Promise.scala:627)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:175)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:146)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:201)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:79)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise.continue(Promise.scala:625)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise$Responder$class.transform(Promise.scala:162)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Promise.transform(Promise.scala:286)

ERR [20141024-20:44:35.377] feeder:     at com.twitter.util.Future.flatMap(Future.scala:783)

ERR [20141024-20:44:35.377] feeder:     (...more...)


From this point on, the feeder log is flooded with identical TimeoutExceptions:

ERR [20141024-20:44:40.382] feeder: Error sending request: com.twitter.util.TimeoutException

ERR [20141024-20:44:40.382] feeder: com.twitter.util.TimeoutException: 5.seconds

ERR [20141024-20:44:40.382] feeder:     at com.twitter.util.Promise.ready(Promise.scala:501)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.util.Promise.result(Promise.scala:506)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.util.Promise$Chained.result(Promise.scala:182)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.util.Await$$anonfun$result$1.apply(Awaitable.scala:85)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.concurrent.LocalScheduler.blocking(Scheduler.scala:208)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.concurrent.Scheduler$.blocking(Scheduler.scala:85)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.util.Await$.result(Awaitable.scala:85)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.util.Future.get(Future.scala:656)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.parrot.util.RemoteParrot.waitFor(RemoteParrot.scala:160)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.parrot.util.RemoteParrot.sendRequest(RemoteParrot.scala:98)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.parrot.feeder.FeedConsumer.sendRequest(FeedConsumer.scala:82)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.parrot.feeder.FeedConsumer.send(FeedConsumer.scala:59)

ERR [20141024-20:44:40.382] feeder:     at com.twitter.parrot.feeder.FeedConsumer.run(FeedConsumer.scala:46)

ERR [20141024-20:44:41.221] feeder: Exception polling parrot[localhost:9999] - 5.seconds

I'm not really sure what's going on. Googling this has only brought up the Finagle changelog that suggests something related might be fixed in 6.12.0: http://twitter.github.io/finagle/guide/changelog.html 

Any help would be much appreciated. Thanks.

Rahul.

Rahul Maddimsetty

unread,
Oct 24, 2014, 5:47:13 PM10/24/14
to iago-...@googlegroups.com
Update: It appears the RPS is less relevant here than how long the test has been running. I just ran into this with RPS=100 after 42000 requests.

Rahul.

James Waldrop

unread,
Oct 24, 2014, 6:03:02 PM10/24/14
to iago-...@googlegroups.com
First question -- are you trying to capture Zipkin traces originating at the client?

--

---
You received this message because you are subscribed to the Google Groups "Iago Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to iago-users+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Rahul Maddimsetty

unread,
Oct 24, 2014, 8:09:39 PM10/24/14
to iago-...@googlegroups.com
Hi James,

I'm not doing anything specifically to enable or disable zipkin traces anywhere and it doesn't seem like that's configurable anyway. Looking at all the places in code where we do enable zipkin tracing, the only code I'm hitting is in ThriftServer.scala and RemoteParrot.scala (I'm using ThriftTransport passing it a Service directly, not using the ThriftTransportFactory to build up a client).

I could remove those lines and rebuild if necessary but I was wondering if there's a way to fix this without resorting to that yet.

Rahul.

Tom Howland

unread,
Oct 30, 2014, 3:14:32 PM10/30/14
to ra...@foursquare.com, iago-...@googlegroups.com
Was this ever resolved?

I wonder if updating the finagle dependencies will help.

Rahul Maddimsetty

unread,
Nov 4, 2014, 12:09:50 PM11/4/14
to Tom Howland, iago-...@googlegroups.com
Thanks for the follow up, Tom. Sorry, I was on vacation so only got back to this yesterday.

I've tried updating the Finagle version to 6.16.0 (which is what we're currently on at Foursquare) and the match errors go away. However, I no longer get back any responses if the victim is a zookeeper serverset. If I hardcode host:port, the run completes but I see this at the very end of the feeder logs (I remember it used to cleanly shutdown specifying a reason, i.e. max requests [as it is in this case] or duration or EOF):

INF [20141104-16:45:15.940] feeder: FeedConsumer.sendRequest: wrote batch of size 1000 to localhost:9999 rps=0.00000 depth=2868.00 status=Some(Running) lines=1000

ERR [20141104-16:45:20.945] util: Error shutting down Parrot: com.twitter.util.TimeoutException

ERR [20141104-16:45:20.945] util: com.twitter.util.TimeoutException: 5.seconds

ERR [20141104-16:45:20.945] util:     at com.twitter.util.Promise.ready(Promise.scala:501)

ERR [20141104-16:45:20.945] util:     at com.twitter.util.Promise.result(Promise.scala:506)

ERR [20141104-16:45:20.945] util:     at com.twitter.util.Promise$Chained.result(Promise.scala:182)

ERR [20141104-16:45:20.945] util:     at com.twitter.util.Await$$anonfun$result$1.apply(Awaitable.scala:85)

ERR [20141104-16:45:20.945] util:     at com.twitter.concurrent.LocalScheduler.blocking(Scheduler.scala:208)

ERR [20141104-16:45:20.945] util:     at com.twitter.concurrent.Scheduler$.blocking(Scheduler.scala:85)

ERR [20141104-16:45:20.945] util:     at com.twitter.util.Await$.result(Awaitable.scala:85)

ERR [20141104-16:45:20.945] util:     at com.twitter.util.Future.get(Future.scala:656)

ERR [20141104-16:45:20.945] util:     at com.twitter.parrot.util.RemoteParrot.waitFor(RemoteParrot.scala:160)

ERR [20141104-16:45:20.945] util:     at com.twitter.parrot.util.RemoteParrot.shutdown(RemoteParrot.scala:120)

ERR [20141104-16:45:20.945] util:     at com.twitter.parrot.util.ParrotClusterImpl$$anonfun$shutdown$4.apply(ParrotCluster.scala:323)

ERR [20141104-16:45:20.945] util:     at com.twitter.parrot.util.ParrotClusterImpl$$anonfun$shutdown$4.apply(ParrotCluster.scala:321)

ERR [20141104-16:45:20.945] util:     at scala.collection.immutable.Set$Set1.foreach(Set.scala:74)

ERR [20141104-16:45:20.945] util:     at com.twitter.parrot.util.ParrotClusterImpl.shutdown(ParrotCluster.scala:321)

ERR [20141104-16:45:20.945] util:     at com.twitter.parrot.feeder.ParrotFeeder.shutdown(ParrotFeeder.scala:91)

ERR [20141104-16:45:20.945] util:     at com.twitter.parrot.feeder.ParrotFeeder$$anonfun$start$1.apply$mcV$sp(ParrotFeeder.scala:78)

ERR [20141104-16:45:20.945] util:     at com.twitter.ostrich.admin.BackgroundProcess$$anon$1.run(BackgroundProcess.scala:34)

INF [20141104-16:45:20.948] admin: TimeSeriesCollector exiting by request.

INF [20141104-16:45:20.948] admin: TimeSeriesCollector exiting.

INF [20141104-16:45:20.949] stats: LatchedStatsListener exiting by request.

INF [20141104-16:45:20.949] stats: LatchedStatsListener exiting.

INF [20141104-16:45:20.951] stats: JsonStatsLogger exiting by request.

INF [20141104-16:45:20.952] stats: JsonStatsLogger exiting.

ERR [20141104-16:45:21.321] feeder: Exception polling parrot[localhost:9999] - 5.seconds

Any idea what's going on? I could disregard the errors and hardcode a host:port list in the short term but I'd really like to have this working properly with zookeeper at some point. I'm going to continue to investigate but figured I should update this thread anyway.

Rahul.

Rahul Maddimsetty

unread,
Nov 4, 2014, 1:56:36 PM11/4/14
to Tom Howland, iago-...@googlegroups.com
Also, I should've mentioned, this is the error I see repeated in the server logs when I use zookeeper after bumping up the finagle dependencies to version 6.16.0:

ERR [20141104-18:30:04.975] server: unexpected error: com.twitter.finagle.CancelledConnectionException: com.twitter.finagle.ServiceClosedException

They appear all at once just before the server shuts down.

Rahul.

Reply all
Reply to author
Forward
0 new messages