Trace Id in the log files does not work as expected
Stavros Kontopoulos
I downloaded the console from here:
http://downloads.typesafe.com/typesafe-console-developer/1.3.1/typesafe-console-developer-1.3.1.zip
I use maven with the sample project to build the project and i get this:.
[INFO] Checking for multiple versions of scala
[WARNING] Expected all dependencies to require Scala version: 2.10.1
[WARNING] com.typesafe.atmos:sample:1.3.1 requires scala version: 2.10.1
[WARNING] com.typesafe.atmos:atmos-event_2.10:1.3.1 requires scala version: 2.10.2
[WARNING] Multiple versions of scala libraries detected!
Then i saw a previous post here for scala 2.10.2 https://docs.google.com/viewer?a=v&pid=forums&srcid=MDE0OTQzNzQ4MzA2ODA3Mjg0NjQBMTgxNzQyMTk2MTc3Mjk1MzE5ODUBUG1FeU5IU0hUbWdKATQBAXYy
and changed pom to the support 2.10.2.
The problem is that i get empty traceId in the atmos.log (and in the console):
2013-11-18 11:51:47,392 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/PrintActor] [SimpleApp-akka.actor.default-dispatcher-7] [] : Msg is:Test msg from Ping Actor!
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
application.conf:
akka {
loglevel = INFO
loggers = ["akka.event.Logging$DefaultLogger", "akka.event.slf4j.Slf4jLogger"]
}
atmos {
trace {
enabled = true # enable tracing
node = MySampleNode # give this node a name
traceable {
"/user/pingActor" = on # trace the ping actor
}
sampling {
"/user/pingActor" = 1 # sample every trace for ping actor
}
}
}
logback.xml:
<?xml version="1.0" encoding="UTF-8"?>
<!-- For assistance related to logback-translator or configuration -->
<!-- files in general, please contact the logback user mailing list -->
<!-- at http://www.qos.ch/mailman/listinfo/logback-user -->
<!-- -->
<!-- For professional support please see -->
<!-- http://www.qos.ch/shop/products/professionalSupport -->
<!-- -->
<configuration scan="false" debug="true">
<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{ISO8601} %-5level [%logger{36}] [%X{akkaSource}] [%X{sourceThread}] [%X{traceId}] : %m%n</pattern>
</encoder>
</appender>
<appender name="R" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>logs/atmos.log</File>
<encoder>
<pattern>%date{ISO8601} %-5level [%logger{36}] [%X{akkaSource}] [%X{sourceThread}] [%X{traceId}] : %m%n</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>logs/atmos.log.%d{yyyy-MM-dd-HH}</fileNamePattern>
</rollingPolicy>
</appender>
<logger name="org.eclipse.jetty.util.log" level="INFO"/>
<!-- Play2: Off these ones as they are annoying, and anyway we manage configuration ourself -->
<logger name="com.avaje.ebean.config.PropertyMapLoader" level="OFF" />
<logger name="com.avaje.ebeaninternal.server.core.XmlConfigLoader" level="OFF" />
<logger name="com.avaje.ebeaninternal.server.lib.BackgroundThread" level="OFF" />
<root level="DEBUG">
<appender-ref ref="stdout"/>
<appender-ref ref="R"/>
</root>
</configuration>
sample.scala i used:
package com.typesafe.atmos.sample
import akka.actor._
import akka.actor.ExtendedActorSystem
import scala.concurrent.duration._
import akka.event.Logging
object Sample extends App {
val system = ActorSystem("SimpleApp")
val printActor = system.actorOf(Props[PrintActor], "PrintActor")
val pingActor = system.actorOf(Props(new PingActor(printActor)), "pingActor")
implicit val exec = system.dispatcher
system.eventStream.setLogLevel(Logging.DebugLevel)
system.scheduler.schedule(0 seconds, 1 seconds, pingActor, Ping)
}
case object Ping
case class Print(x: String)
class PingActor(pactor: ActorRef) extends Actor {
def receive = {
case Ping => println("Pinged at: " + System.currentTimeMillis)
pactor ! Print("Test msg from Ping Actor!")
}
}
class PrintActor extends Actor with ActorLogging {
def receive = {
case Print(x) => log.info("Msg is:" + x)
case _ =>
}
}
I am using log.info to see stuff in the files.
If i use the default sample.scala :
package com.typesafe.atmos.sample
import akka.actor._
import scala.concurrent.duration._
object Sample extends App {
val system = ActorSystem("SimpleApp")
val pingActor = system.actorOf(Props[PingActor], "pingActor")
implicit val exec = system.dispatcher
system.scheduler.schedule(0 seconds, 1 seconds, pingActor, Ping)
}
case object Ping
class PingActor extends Actor {
def receive = {
case Ping => println("Pinged at: " + System.currentTimeMillis)
}
}
Console output is not correct...logback encoding is ignored...
[WARN] [11/18/2013 11:56:53.816] [atmos-atmos-trace-dispatcher-8] [akka://atmos/
user/2_SystemMetricsMonitor] Couldn't monitor [systemLoadAverage]. Due to [This
method has not been implemented on this platform]
[WARN] [11/18/2013 11:56:54.325] [atmos-atmos-trace-dispatcher-8] [akka://atmos/
user/2_SystemMetricsMonitor] Couldn't monitor [loadAverage]. Due to [This method
has not been implemented on this platform]
Pinged at: 1384768614537
Pinged at: 1384768615525
Pinged at: 1384768616535
Pinged at: 1384768617535
Pinged at: 1384768618534
Pinged at: 1384768619536
Pinged at: 1384768620595
Pinged at: 1384768621536
Any ideas?
Regards,
Stavros K.
h3nk3
I am not sure I understand you problem.
Can you please explain what you expect to see?
From your description above I can read that you expect a "traceId". Do you refer to the traceIds we use in the Console?
If so, these traceIds are something we use internally in the Console to keep track of what trace events that should be grouped together.
It is not something we expose apart from in the deviation view and direct calls to the REST API.
Thanks,
Henrik
Peter Vlugter
To get the traceId in Logback's MDC you need to use the logger provided by Atmos.
The logger class to configure is:
akka {
loggers = ["com.typesafe.atmos.trace.Slf4jTraceContextLogger"]
}
The documentation on logging:
http://resources.typesafe.com/docs/console/manual/configuration.html#logging
Cheers,
Peter
> You received this message because you are subscribed to the Google Groups "Typesafe Console User List" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to typesafe-conso...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
Stavros Kontopoulos
I get this line in my log file:
2013-11-25 01:34:09,063 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/PrintActor] [SimpleApp-akka.actor.default-dispatcher-3] [] : Msg is:Test msg from Ping Actor!
In logback.xml by default there is this line:
<pattern>%date{ISO8601} %-5level [%logger{36}] [%X{akkaSource}] [%X{sourceThread}] [%X{traceId}] : %m%n</pattern>
I expect a trace value to identify flow of execution between actors... when i log messages with the same traceid...
Stavros Kontopoulos
but i just I tried the correct logger (for akka 2,2,x) still i get empty values... both at the console and the log file...:(
2013-11-25 01:34:09,063 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/PrintActor] [SimpleApp-akka.actor.default-dispatcher-3] [] : Msg is:Test msg from Ping Actor!
I also tried event-handlers = ["com.typesafe.atmos.trace.Slf4jTraceContextEventHandler"] which comes with the sample app
from the console zip file (for akka 2.1.x).
Any ideas?
Peter Vlugter
If the logger is explicitly marked traceable it should work. In the atmos.trace.traceable section of the config, try adding:
"/system/log*" = on
- Peter
Stavros Kontopoulos
I used it in the application config:
atmos {
trace {
traceable {
"/system/log*" = on
"/user/pingActor" = on # trace the ping actor
}
}
}
2013-11-25 11:55:36,161 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/PrintActor] [SimpleApp-akka.actor.default-dispatcher-4] [00000000-0000-0000-0000-000000000000] : Msg is:Test msg from Ping Actor!
I will try to create different actor message flows to get a non zero trace-id, i guess this is possible right?
Right now in the program logic i have one actor pinging as in the sample and it sends a message to the PrintActor to log it...
Thank you!
Stavros Kontopoulos
this time i modified the code like this , i am trying to get trace id other than zero...:
package com.typesafe.atmos.sample
import akka.actor._
import akka.actor.ExtendedActorSystem
import scala.concurrent.duration._
import akka.event.Logging
object Sample extends App {
val system = ActorSystem("SimpleApp")
val printActor2 = system.actorOf(Props[PrintActor], "printActor2")
val pingActor1 = system.actorOf(Props(new PingActor(printActor1)), "pingActor1")
val pingActor2 = system.actorOf(Props(new PingActor(printActor2)), "pingActor2")
implicit val exec = system.dispatcher
system.eventStream.setLogLevel(Logging.DebugLevel)
system.scheduler.schedule(0 seconds, 1 seconds, pingActor2, Ping)
}
case object Ping
case class Print(x: String)
class PingActor(pactor: ActorRef) extends Actor {
def receive = {
case Ping => println("Pinged at: " + System.currentTimeMillis)
pactor ! Print("Test msg from Ping Actor!")
}
}
class PrintActor extends Actor with ActorLogging {
def receive = {
case Print(x) => log.info("Msg is:" + x)
case _ =>
}
}
akka {
loglevel = INFO
loggers = ["com.typesafe.atmos.trace.Slf4jTraceContextLogger"]
}
atmos {
trace {
enabled = true # enable tracing
node = MySampleNode # give this node a name
traceable {
"/user/pingActor1" = on # trace the ping actor
"/user/pingActor2" = on # trace the ping actor
"/user/printActor1" = on # trace the ping actor
"/user/printActor2" = on # trace the ping actor
}
sampling {
"/user/pingActor1" = 1 # sample every trace for ping actor
"/user/pingActor2" = 1 # sample every trace for ping actor
"/user/printActor1" = 1 # sample every trace for ping actor
"/user/printActor2" = 1 # sample every trace for ping actor
}
}
}
---------------------------------------------------------------------------------
I have two different flows....
Pinged at: 1385377513218
2013-11-25 13:05:13,221 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-8] [750e7e21-55c1-11e3-bbb8-b8ac6fcba277] : Msg is:Test msg from Ping Actor!
Pinged at: 13853775132282013-11-25 13:05:13,231 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor2] [SimpleApp-akka.actor.default-dispatcher-2] [751004c1-55c1-11e3-bbb8-b8ac6fcba277] : Msg is:Test msg from Ping Actor!
I works great!
Cheers,
Stavros
Peter Vlugter
On 26/11/2013, at 12:07 am, Stavros Kontopoulos <st.kont...@gmail.com> wrote:
> ---------------------------------------------------------------------------------
> I have two different flows....
>
> Pinged at: 1385377513218
> 2013-11-25 13:05:13,221 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor1] [SimpleApp-akka.actor.default-dispatcher-8] [750e7e21-55c1-11e3-bbb8-b8ac6fcba277] : Msg is:Test msg from Ping Actor!
> Pinged at: 13853775132282013-11-25 13:05:13,231 INFO [com.typesafe.atmos.sample.PrintActor] [akka://SimpleApp/user/printActor2] [SimpleApp-akka.actor.default-dispatcher-2] [751004c1-55c1-11e3-bbb8-b8ac6fcba277] : Msg is:Test msg from Ping Actor!
>
> I works great!
And if you want to view the trace tree associated with a trace id (in a json format), it's available at:
http://localhost:8660/monitoring/trace/tree/<trace-id>
Cheers,
Peter