TraceId does not work as expected in a message flow
38 views
Skip to first unread message
Stavros Kontopoulos
Jan 14, 2014, 8:25:42 AM1/14/14
to typesafe...@googlegroups.com
Hi,
I am currently evaluating the echo project and the typesafe console capabilities and today i got stuck with this issue:
I modified the sample application coming with typesafe console and i just tested two different chains of actor message flows. In other words in the first scenario a number of actors are created named as serialActors and they just pass a message acting like a domino.
In the second scenario i have the same approach where the so called PingActor receives a message and sends it to the PrintActor.
For the first scenario only one flow is created. I would expect all log calls during that flow to have the same trace id, but unfortunately this is not the case.
In the second scenario everything works normally. I create 5 different flows and all relevant log messages have the same traceid.
Any ideas? I don't find any differences in the logic of both scenarios they should work the same, something wrong with the configuration or the aspectj intercepting actor messaging and assigning trace context in typesafe console?
The application:
package com.typesafe.atmos.sample
import akka.actor._
import akka.event.Logging
import scala.concurrent.Future
import scala.util.{Failure, Success}
import scala.concurrent.stm.Ref
object Sample extends App {
val counter: Ref[Int] = Ref[Int](1)
val system = ActorSystem("SimpleApp")
val printActor1 = system.actorOf(Props[PrintActor], "printActor1")
val pingActor1 = system.actorOf(Props(new PingActor(printActor1)), "pingActor1")
val maxSerials = 5
(1 to maxSerials).map {
x => system.actorOf(Props(new SerialActor(x)), "serialActor" + x)
}
system.actorSelection("/user/serialActor1") ! SerialMessage
implicit val exec = system.dispatcher
system.eventStream.setLogLevel(Logging.DebugLevel)
(1 to 5) map {
x => system.actorSelection("/user/pingActor1") ! Counter(counterValue())
}
def counterValue(): Int = {
val ret = counter.single.getAndTransform(x => x + 1)
ret
}
}
case object Ping
case class Print(x: String)
case class Counter(x: Int)
case object SerialMessage
class PingActor(pactor: ActorRef) extends Actor with ActorLogging {
import context.dispatcher
def receive = {
case Counter(x) => println("Pinged at: " + System.currentTimeMillis)
pactor ! Print("Test msg from Ping Actor! " + x)
log.info("MSG received")
val logme = Logging.getLogger(this.context.system, this)
val f = Future {
logme.info("in the future... id:" + x)
2 + 2
}
f.onComplete {
case Success(result) ⇒ logme.info("Future complete:..."+ result.toString + " id:" + x)
case Failure(failure) ⇒ logme.error(failure.toString + " id:" + x)
}
}
}
class SerialActor(x: Int) extends Actor with ActorLogging {
def receive = {
case SerialMessage =>
log.info("Actor:" + x)
if (x < Sample.maxSerials) {
val next = x + 1
context.actorSelection("/user/serialActor" + next) ! SerialMessage
}
}
}
class PrintActor extends Actor with ActorLogging {
def receive = {
case Print(x) => log.info("Msg is:" + x)
case _ =>
}
}
The application.conf :
akka {
loglevel = INFO
loggers = ["com.typesafe.atmos.trace.Slf4jTraceContextLogger"]
}
atmos {
trace {
enabled = true # enable tracing
node = MySampleNode # give this node a name
traceable {
"/system/log*" = on
"/user/pingActor1" = on # trace the ping actor
"/user/printActor1" = on # trace the ping actor
"/user/serialActor*" = on # trace the serial actors
}
sampling {
"/user/pingActor1" = 1 # sample every trace for ping actor
"/user/printActor1" = 1 # sample every trace for ping actor
"/user/serialActor*" = 1 # trace the serial actors
}
}
}
The log output:
2014-01-14 15:18:59,553 INFO [c.t.a.trace.Slf4jTraceContextLogger] [] [] [6da33431-7d1e-11e3-abac-b8ac6fcba277] : Slf4jTraceContextLogger started
2014-01-14 15:18:59,688 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6dd9fba1-7d1e-11e3-abac-b8ac6fcba277] : Actor:1
2014-01-14 15:18:59,692 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor2] [SimpleApp-akka.actor.default-dispatcher-6] [6ddabef1-7d1e-11e3-abac-b8ac6fcba277] : Actor:2
2014-01-14 15:18:59,693 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor3] [SimpleApp-akka.actor.default-dispatcher-8] [6ddabef7-7d1e-11e3-abac-b8ac6fcba277] : Actor:3
2014-01-14 15:18:59,693 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor4] [SimpleApp-akka.actor.default-dispatcher-2] [6ddae602-7d1e-11e3-abac-b8ac6fcba277] : Actor:4
2014-01-14 15:18:59,694 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor5] [SimpleApp-akka.actor.default-dispatcher-3] [6ddae608-7d1e-11e3-abac-b8ac6fcba277] : Actor:5
2014-01-14 15:18:59,806 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,806 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 1
2014-01-14 15:18:59,831 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-4] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:1
2014-01-14 15:18:59,839 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,840 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-4] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 2
2014-01-14 15:18:59,842 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,843 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,844 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:1
2014-01-14 15:18:59,845 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,845 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 3
2014-01-14 15:18:59,846 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 4
2014-01-14 15:18:59,847 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 5
2014-01-14 15:18:59,847 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:4
2014-01-14 15:18:59,848 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:4
2014-01-14 15:18:59,849 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:5
2014-01-14 15:18:59,849 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:5
2014-01-14 15:18:59,851 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:3
2014-01-14 15:18:59,852 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:3
2014-01-14 15:18:59,853 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:2
2014-01-14 15:18:59,853 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:2
The 2nd to 5th log enties refer to the serial actors and although one actor sends a message to the next the trace id is different.
In the second scenario when i pick a traceid value like: 6ded3587-7d1e-11e3-abac-b8ac6fcba277 is see it correlates with 4 different log entries which comply with the program logic.
I cannot figure out whats the issue here....
I am currently evaluating the echo project and the typesafe console capabilities and today i got stuck with this issue:
I modified the sample application coming with typesafe console and i just tested two different chains of actor message flows. In other words in the first scenario a number of actors are created named as serialActors and they just pass a message acting like a domino.
In the second scenario i have the same approach where the so called PingActor receives a message and sends it to the PrintActor.
For the first scenario only one flow is created. I would expect all log calls during that flow to have the same trace id, but unfortunately this is not the case.
In the second scenario everything works normally. I create 5 different flows and all relevant log messages have the same traceid.
Any ideas? I don't find any differences in the logic of both scenarios they should work the same, something wrong with the configuration or the aspectj intercepting actor messaging and assigning trace context in typesafe console?
The application:
package com.typesafe.atmos.sample
import akka.actor._
import akka.event.Logging
import scala.concurrent.Future
import scala.util.{Failure, Success}
import scala.concurrent.stm.Ref
object Sample extends App {
val counter: Ref[Int] = Ref[Int](1)
val system = ActorSystem("SimpleApp")
val printActor1 = system.actorOf(Props[PrintActor], "printActor1")
val pingActor1 = system.actorOf(Props(new PingActor(printActor1)), "pingActor1")
val maxSerials = 5
(1 to maxSerials).map {
x => system.actorOf(Props(new SerialActor(x)), "serialActor" + x)
}
system.actorSelection("/user/serialActor1") ! SerialMessage
implicit val exec = system.dispatcher
system.eventStream.setLogLevel(Logging.DebugLevel)
(1 to 5) map {
x => system.actorSelection("/user/pingActor1") ! Counter(counterValue())
}
def counterValue(): Int = {
val ret = counter.single.getAndTransform(x => x + 1)
ret
}
}
case object Ping
case class Print(x: String)
case class Counter(x: Int)
case object SerialMessage
class PingActor(pactor: ActorRef) extends Actor with ActorLogging {
import context.dispatcher
def receive = {
case Counter(x) => println("Pinged at: " + System.currentTimeMillis)
pactor ! Print("Test msg from Ping Actor! " + x)
log.info("MSG received")
val logme = Logging.getLogger(this.context.system, this)
val f = Future {
logme.info("in the future... id:" + x)
2 + 2
}
f.onComplete {
case Success(result) ⇒ logme.info("Future complete:..."+ result.toString + " id:" + x)
case Failure(failure) ⇒ logme.error(failure.toString + " id:" + x)
}
}
}
class SerialActor(x: Int) extends Actor with ActorLogging {
def receive = {
case SerialMessage =>
log.info("Actor:" + x)
if (x < Sample.maxSerials) {
val next = x + 1
context.actorSelection("/user/serialActor" + next) ! SerialMessage
}
}
}
class PrintActor extends Actor with ActorLogging {
def receive = {
case Print(x) => log.info("Msg is:" + x)
case _ =>
}
}
The application.conf :
akka {
loglevel = INFO
loggers = ["com.typesafe.atmos.trace.Slf4jTraceContextLogger"]
}
atmos {
trace {
enabled = true # enable tracing
node = MySampleNode # give this node a name
traceable {
"/system/log*" = on
"/user/pingActor1" = on # trace the ping actor
"/user/printActor1" = on # trace the ping actor
"/user/serialActor*" = on # trace the serial actors
}
sampling {
"/user/pingActor1" = 1 # sample every trace for ping actor
"/user/printActor1" = 1 # sample every trace for ping actor
"/user/serialActor*" = 1 # trace the serial actors
}
}
}
The log output:
2014-01-14 15:18:59,553 INFO [c.t.a.trace.Slf4jTraceContextLogger] [] [] [6da33431-7d1e-11e3-abac-b8ac6fcba277] : Slf4jTraceContextLogger started
2014-01-14 15:18:59,688 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6dd9fba1-7d1e-11e3-abac-b8ac6fcba277] : Actor:1
2014-01-14 15:18:59,692 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor2] [SimpleApp-akka.actor.default-dispatcher-6] [6ddabef1-7d1e-11e3-abac-b8ac6fcba277] : Actor:2
2014-01-14 15:18:59,693 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor3] [SimpleApp-akka.actor.default-dispatcher-8] [6ddabef7-7d1e-11e3-abac-b8ac6fcba277] : Actor:3
2014-01-14 15:18:59,693 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor4] [SimpleApp-akka.actor.default-dispatcher-2] [6ddae602-7d1e-11e3-abac-b8ac6fcba277] : Actor:4
2014-01-14 15:18:59,694 INFO [c.typesafe.atmos.sample.SerialActor] [akka://SimpleApp/user/serialActor5] [SimpleApp-akka.actor.default-dispatcher-3] [6ddae608-7d1e-11e3-abac-b8ac6fcba277] : Actor:5
2014-01-14 15:18:59,806 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,806 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 1
2014-01-14 15:18:59,831 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-4] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:1
2014-01-14 15:18:59,839 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,840 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-4] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 2
2014-01-14 15:18:59,842 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,843 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,844 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3581-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:1
2014-01-14 15:18:59,845 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : MSG received
2014-01-14 15:18:59,845 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 3
2014-01-14 15:18:59,846 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 4
2014-01-14 15:18:59,847 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : Msg is:Test msg from Ping Actor! 5
2014-01-14 15:18:59,847 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:4
2014-01-14 15:18:59,848 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c91-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:4
2014-01-14 15:18:59,849 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:5
2014-01-14 15:18:59,849 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-2] [6ded5c93-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:5
2014-01-14 15:18:59,851 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:3
2014-01-14 15:18:59,852 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-5] [6ded3587-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:3
2014-01-14 15:18:59,853 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : in the future... id:2
2014-01-14 15:18:59,853 INFO [com.typesafe.atmos.sample.PingActor] [akka://SimpleApp/user/pingActor1] [SimpleApp-akka.actor.default-dispatcher-7] [6ded3585-7d1e-11e3-abac-b8ac6fcba277] : Future complete:...4 id:2
The 2nd to 5th log enties refer to the serial actors and although one actor sends a message to the next the trace id is different.
In the second scenario when i pick a traceid value like: 6ded3587-7d1e-11e3-abac-b8ac6fcba277 is see it correlates with 4 different log entries which comply with the program logic.
I cannot figure out whats the issue here....
Message has been deleted
Stavros Kontopoulos
Jan 19, 2014, 7:16:18 AM1/19/14
to typesafe...@googlegroups.com
Any ideas?
Reply all
Reply to author
Forward
0 new messages