From fbf25ed06bf87af2d139ae58f208d9bb5b299e03 Mon Sep 17 00:00:00 2001 From: vlad Date: Wed, 12 Apr 2017 16:54:02 -0700 Subject: PDW-598 Getting rid of log wrapper --- src/main/scala/xyz/driver/core/app.scala | 19 +++-- src/main/scala/xyz/driver/core/logging.scala | 110 +------------------------- src/main/scala/xyz/driver/core/messages.scala | 2 +- src/main/scala/xyz/driver/core/rest.scala | 25 +++--- src/main/scala/xyz/driver/core/stats.scala | 39 --------- src/main/scala/xyz/driver/core/time.scala | 3 + 6 files changed, 25 insertions(+), 173 deletions(-) (limited to 'src/main/scala/xyz/driver') diff --git a/src/main/scala/xyz/driver/core/app.scala b/src/main/scala/xyz/driver/core/app.scala index 361fb74..9fab320 100644 --- a/src/main/scala/xyz/driver/core/app.scala +++ b/src/main/scala/xyz/driver/core/app.scala @@ -13,11 +13,11 @@ import akka.http.scaladsl.server.RouteResult._ import akka.http.scaladsl.server.{ExceptionHandler, Route, RouteConcatenation} import akka.stream.ActorMaterializer import com.typesafe.config.Config +import com.typesafe.scalalogging.Logger import io.swagger.models.Scheme import org.slf4j.{LoggerFactory, MDC} import spray.json.DefaultJsonProtocol import xyz.driver.core -import xyz.driver.core.logging.{Logger, TypesafeScalaLogger} import xyz.driver.core.rest.{ContextHeaders, Swagger} import xyz.driver.core.stats.SystemStats import xyz.driver.core.time.Time @@ -33,8 +33,7 @@ object app { gitHash: String, modules: Seq[Module], time: TimeProvider = new SystemTimeProvider(), - log: Logger = new TypesafeScalaLogger( - com.typesafe.scalalogging.Logger(LoggerFactory.getLogger(classOf[DriverApp]))), + log: Logger = Logger(LoggerFactory.getLogger(classOf[DriverApp])), config: Config = core.config.loadDefaultConfig, interface: String = "::0", baseUrl: String = "localhost:8080", @@ -77,7 +76,7 @@ object app { MDC.put("ip", ip.toOption.map(_.getHostAddress).getOrElse("unknown")) def requestLogging: Future[Unit] = Future { - log.audit( + log.info( s"""Received request {"method":"${ctx.request.method.value}","url": "${ctx.request.uri}"}""") } @@ -107,26 +106,26 @@ object app { case is: IllegalStateException => ctx => MDC.put("trackingId", rest.extractTrackingId(ctx.request)) - log.error(s"Request is not allowed to ${ctx.request.method} ${ctx.request.uri}", is) + log.warn(s"Request is not allowed to ${ctx.request.method} ${ctx.request.uri}", is) complete(HttpResponse(BadRequest, entity = is.getMessage))(ctx) case cm: ConcurrentModificationException => ctx => MDC.put("trackingId", rest.extractTrackingId(ctx.request)) - log.error(s"Concurrent modification of the resource ${ctx.request.method} ${ctx.request.uri}", cm) + log.warn(s"Concurrent modification of the resource ${ctx.request.method} ${ctx.request.uri}", cm) complete( HttpResponse(Conflict, entity = "Resource was changed concurrently, try requesting a newer version"))(ctx) case sex: SQLException => ctx => MDC.put("trackingId", rest.extractTrackingId(ctx.request)) - log.error(s"Database exception for the resource ${ctx.request.method} ${ctx.request.uri}", sex) + log.warn(s"Database exception for the resource ${ctx.request.method} ${ctx.request.uri}", sex) complete(HttpResponse(InternalServerError, entity = "Data access error"))(ctx) case t: Throwable => ctx => MDC.put("trackingId", rest.extractTrackingId(ctx.request)) - log.error(s"Request to ${ctx.request.method} ${ctx.request.uri} could not be handled normally", t) + log.warn(s"Request to ${ctx.request.method} ${ctx.request.uri} could not be handled normally", t) complete(HttpResponse(InternalServerError, entity = t.getMessage))(ctx) } @@ -190,7 +189,7 @@ object app { service.activate() } catch { case t: Throwable => - log.fatal(s"Service ${service.name} failed to activate", t) + log.error(s"Service ${service.name} failed to activate", t) Console.print(" Failed! (check log)") } Console.print(" Done\n") @@ -209,7 +208,7 @@ object app { service.deactivate() } catch { case t: Throwable => - log.fatal(s"Service ${service.name} failed to deactivate", t) + log.error(s"Service ${service.name} failed to deactivate", t) Console.print(" Failed! (check log)") } Console.print(s"Service ${service.name} is shut down\n") diff --git a/src/main/scala/xyz/driver/core/logging.scala b/src/main/scala/xyz/driver/core/logging.scala index c8fb6ae..9a5805d 100644 --- a/src/main/scala/xyz/driver/core/logging.scala +++ b/src/main/scala/xyz/driver/core/logging.scala @@ -6,117 +6,11 @@ import java.util.Date import ch.qos.logback.classic.spi.ILoggingEvent import ch.qos.logback.core.LayoutBase import org.apache.commons.lang3.StringUtils -import org.slf4j.Marker +import org.slf4j.helpers.NOPLogger object logging { - trait Logger { - - def fatal(message: String): Unit - def fatal(message: String, cause: Throwable): Unit - def fatal(message: String, args: AnyRef*): Unit - def fatal(marker: Marker, message: String): Unit - def fatal(marker: Marker, message: String, cause: Throwable): Unit - def fatal(marker: Marker, message: String, args: AnyRef*): Unit - - def error(message: String): Unit - def error(message: String, cause: Throwable): Unit - def error(message: String, args: AnyRef*): Unit - def error(marker: Marker, message: String): Unit - def error(marker: Marker, message: String, cause: Throwable): Unit - def error(marker: Marker, message: String, args: AnyRef*): Unit - - def audit(message: String): Unit - def audit(message: String, cause: Throwable): Unit - def audit(message: String, args: AnyRef*): Unit - def audit(marker: Marker, message: String): Unit - def audit(marker: Marker, message: String, cause: Throwable): Unit - def audit(marker: Marker, message: String, args: AnyRef*): Unit - - def debug(message: String): Unit - def debug(message: String, cause: Throwable): Unit - def debug(message: String, args: AnyRef*): Unit - def debug(marker: Marker, message: String): Unit - def debug(marker: Marker, message: String, cause: Throwable): Unit - def debug(marker: Marker, message: String, args: AnyRef*): Unit - } - - /** - * Logger implementation which uses `com.typesafe.scalalogging.Logger` on the back. - * It redefines the meaning of logging levels to fit to the Driver infrastructure design, - * and as using error and warn, debug and trace was always confusing and mostly done wrong. - * - * @param scalaLogging com.typesafe.scalalogging.Logger which logging will be delegated to - */ - class TypesafeScalaLogger(scalaLogging: com.typesafe.scalalogging.Logger) extends Logger { - - def fatal(message: String): Unit = scalaLogging.error("FATAL " + message) - def fatal(message: String, cause: Throwable): Unit = scalaLogging.error("FATAL " + message, cause) - def fatal(message: String, args: AnyRef*): Unit = scalaLogging.error("FATAL " + message, args) - def fatal(marker: Marker, message: String): Unit = scalaLogging.error(marker, "FATAL " + message) - def fatal(marker: Marker, message: String, cause: Throwable): Unit = - scalaLogging.error(marker, "FATAL " + message, cause) - def fatal(marker: Marker, message: String, args: AnyRef*): Unit = - scalaLogging.error(marker, "FATAL " + message, args) - - def error(message: String): Unit = scalaLogging.warn("ERROR " + message) - def error(message: String, cause: Throwable): Unit = scalaLogging.warn("ERROR " + message, cause) - def error(message: String, args: AnyRef*): Unit = scalaLogging.warn("ERROR " + message, args) - def error(marker: Marker, message: String): Unit = scalaLogging.warn(marker, "ERROR " + message) - def error(marker: Marker, message: String, cause: Throwable): Unit = - scalaLogging.warn(marker, "ERROR " + message, cause) - def error(marker: Marker, message: String, args: AnyRef*): Unit = - scalaLogging.warn(marker, "ERROR " + message, args) - - def audit(message: String): Unit = scalaLogging.info("AUDIT " + message) - def audit(message: String, cause: Throwable): Unit = scalaLogging.info("AUDIT " + message, cause) - def audit(message: String, args: AnyRef*): Unit = scalaLogging.info("AUDIT " + message, args) - def audit(marker: Marker, message: String): Unit = scalaLogging.info(marker, "AUDIT " + message) - def audit(marker: Marker, message: String, cause: Throwable): Unit = - scalaLogging.info(marker, "AUDIT " + message, cause) - def audit(marker: Marker, message: String, args: AnyRef*): Unit = - scalaLogging.info(marker, "AUDIT " + message, args) - - def debug(message: String): Unit = scalaLogging.debug("DEBUG " + message) - def debug(message: String, cause: Throwable): Unit = scalaLogging.debug("DEBUG " + message, cause) - def debug(message: String, args: AnyRef*): Unit = scalaLogging.debug("DEBUG " + message, args) - def debug(marker: Marker, message: String): Unit = scalaLogging.debug(marker, "DEBUG " + message) - def debug(marker: Marker, message: String, cause: Throwable): Unit = - scalaLogging.debug(marker, "DEBUG " + message, cause) - def debug(marker: Marker, message: String, args: AnyRef*): Unit = - scalaLogging.debug(marker, "DEBUG " + message, args) - } - - object NoLogger extends Logger { - - def fatal(message: String): Unit = {} - def fatal(message: String, cause: Throwable): Unit = {} - def fatal(message: String, args: AnyRef*): Unit = {} - def fatal(marker: Marker, message: String): Unit = {} - def fatal(marker: Marker, message: String, cause: Throwable): Unit = {} - def fatal(marker: Marker, message: String, args: AnyRef*): Unit = {} - - def error(message: String): Unit = {} - def error(message: String, cause: Throwable): Unit = {} - def error(message: String, args: AnyRef*): Unit = {} - def error(marker: Marker, message: String): Unit = {} - def error(marker: Marker, message: String, cause: Throwable): Unit = {} - def error(marker: Marker, message: String, args: AnyRef*): Unit = {} - - def audit(message: String): Unit = {} - def audit(message: String, cause: Throwable): Unit = {} - def audit(message: String, args: AnyRef*): Unit = {} - def audit(marker: Marker, message: String): Unit = {} - def audit(marker: Marker, message: String, cause: Throwable): Unit = {} - def audit(marker: Marker, message: String, args: AnyRef*): Unit = {} - - def debug(message: String): Unit = {} - def debug(message: String, cause: Throwable): Unit = {} - def debug(message: String, args: AnyRef*): Unit = {} - def debug(marker: Marker, message: String): Unit = {} - def debug(marker: Marker, message: String, cause: Throwable): Unit = {} - def debug(marker: Marker, message: String, args: AnyRef*): Unit = {} - } + val NoLogger = com.typesafe.scalalogging.Logger(NOPLogger.NOP_LOGGER) class DriverLayout extends LayoutBase[ILoggingEvent] { import scala.collection.JavaConverters._ diff --git a/src/main/scala/xyz/driver/core/messages.scala b/src/main/scala/xyz/driver/core/messages.scala index b5ae704..6b1bc7e 100644 --- a/src/main/scala/xyz/driver/core/messages.scala +++ b/src/main/scala/xyz/driver/core/messages.scala @@ -3,7 +3,7 @@ package xyz.driver.core import java.util.Locale import com.typesafe.config.{Config, ConfigException} -import xyz.driver.core.logging.Logger +import com.typesafe.scalalogging.Logger /** * Scala internationalization (i18n) support diff --git a/src/main/scala/xyz/driver/core/rest.scala b/src/main/scala/xyz/driver/core/rest.scala index dc18375..0c24738 100644 --- a/src/main/scala/xyz/driver/core/rest.scala +++ b/src/main/scala/xyz/driver/core/rest.scala @@ -6,6 +6,7 @@ import akka.http.scaladsl.model._ import akka.http.scaladsl.model.headers.{HttpChallenges, RawHeader} import akka.http.scaladsl.server.AuthenticationFailedRejection.CredentialsRejected import akka.http.scaladsl.server.Directive0 +import com.typesafe.scalalogging.Logger import akka.http.scaladsl.unmarshalling.Unmarshal import akka.http.scaladsl.unmarshalling.Unmarshaller import akka.stream.ActorMaterializer @@ -16,9 +17,6 @@ import com.github.swagger.akka.{HasActorSystem, SwaggerHttpService} import com.typesafe.config.Config import io.swagger.models.Scheme import xyz.driver.core.auth._ -import xyz.driver.core.logging.Logger -import xyz.driver.core.stats.Stats -import xyz.driver.core.time.TimeRange import xyz.driver.core.time.provider.TimeProvider import scala.concurrent.{ExecutionContext, Future} @@ -169,16 +167,16 @@ package rest { else { val challenge = HttpChallenges.basic(s"User does not have the required permissions: ${permissions.mkString(", ")}") - log.error(s"User $user does not have the required permissions: ${permissions.mkString(", ")}") + log.warn(s"User $user does not have the required permissions: ${permissions.mkString(", ")}") reject(AuthenticationFailedRejection(CredentialsRejected, challenge)) } case Success(None) => - log.error(s"Wasn't able to find authenticated user for the token provided to verify ${permissions.mkString(", ")}") + log.warn(s"Wasn't able to find authenticated user for the token provided to verify ${permissions.mkString(", ")}") reject(ValidationRejection(s"Wasn't able to find authenticated user for the token provided")) case Failure(t) => - log.error(s"Wasn't able to verify token for authenticated user to verify ${permissions.mkString(", ")}", t) + log.warn(s"Wasn't able to verify token for authenticated user to verify ${permissions.mkString(", ")}", t) reject(ValidationRejection(s"Wasn't able to verify token for authenticated user", Some(t))) } } @@ -252,7 +250,6 @@ package rest { class HttpRestServiceTransport(actorSystem: ActorSystem, executionContext: ExecutionContext, log: Logger, - stats: Stats, time: TimeProvider) extends ServiceTransport { @@ -269,21 +266,19 @@ package rest { RawHeader(h._1, h._2): HttpHeader }: _*) - log.audit(s"Sending request to ${request.method} ${request.uri}") + log.info(s"Sending request to ${request.method} ${request.uri}") val response = Http()(actorSystem).singleRequest(request)(materializer) response.onComplete { case Success(r) => - val responseTime = time.currentTime() - log.audit(s"Response from ${request.uri} to request $requestStub is successful: $r") - stats.recordStats(Seq("request", request.uri.toString, "success"), TimeRange(requestTime, responseTime), 1) + val responseLatency = requestTime.durationTo(time.currentTime()) + log.info(s"Response from ${request.uri} to request $requestStub is successful in $responseLatency ms: $r") case Failure(t: Throwable) => - val responseTime = time.currentTime() - log.audit(s"Failed to receive response from ${request.method} ${request.uri}", t) - log.error(s"Failed to receive response from ${request.method} ${request.uri}", t) - stats.recordStats(Seq("request", request.uri.toString, "fail"), TimeRange(requestTime, responseTime), 1) + val responseLatency = requestTime.durationTo(time.currentTime()) + log.info(s"Failed to receive response from ${request.method} ${request.uri} in $responseLatency ms", t) + log.warn(s"Failed to receive response from ${request.method} ${request.uri} in $responseLatency ms", t) }(executionContext) response diff --git a/src/main/scala/xyz/driver/core/stats.scala b/src/main/scala/xyz/driver/core/stats.scala index 5759012..dbcf6e4 100644 --- a/src/main/scala/xyz/driver/core/stats.scala +++ b/src/main/scala/xyz/driver/core/stats.scala @@ -4,47 +4,8 @@ import java.io.File import java.lang.management.ManagementFactory import java.lang.reflect.Modifier -import xyz.driver.core.logging.Logger -import xyz.driver.core.time.{Time, TimeRange} - object stats { - type StatsKey = String - type StatsKeys = Seq[StatsKey] - - trait Stats { - - def recordStats(keys: StatsKeys, interval: TimeRange, value: BigDecimal): Unit - - def recordStats(keys: StatsKeys, interval: TimeRange, value: Int): Unit = - recordStats(keys, interval, BigDecimal(value)) - - def recordStats(key: StatsKey, interval: TimeRange, value: BigDecimal): Unit = - recordStats(Vector(key), interval, value) - - def recordStats(key: StatsKey, interval: TimeRange, value: Int): Unit = - recordStats(Vector(key), interval, BigDecimal(value)) - - def recordStats(keys: StatsKeys, time: Time, value: BigDecimal): Unit = - recordStats(keys, TimeRange(time, time), value) - - def recordStats(keys: StatsKeys, time: Time, value: Int): Unit = - recordStats(keys, TimeRange(time, time), BigDecimal(value)) - - def recordStats(key: StatsKey, time: Time, value: BigDecimal): Unit = - recordStats(Vector(key), TimeRange(time, time), value) - - def recordStats(key: StatsKey, time: Time, value: Int): Unit = - recordStats(Vector(key), TimeRange(time, time), BigDecimal(value)) - } - - class LogStats(log: Logger) extends Stats { - def recordStats(keys: StatsKeys, interval: TimeRange, value: BigDecimal): Unit = { - val valueString = value.bigDecimal.toPlainString - log.audit(s"${keys.mkString(".")}(${interval.start.millis}-${interval.end.millis})=$valueString") - } - } - final case class MemoryStats(free: Long, total: Long, max: Long) final case class GarbageCollectorStats(totalGarbageCollections: Long, garbageCollectionTime: Long) diff --git a/src/main/scala/xyz/driver/core/time.scala b/src/main/scala/xyz/driver/core/time.scala index ed5eb11..63a6fa4 100644 --- a/src/main/scala/xyz/driver/core/time.scala +++ b/src/main/scala/xyz/driver/core/time.scala @@ -2,6 +2,7 @@ package xyz.driver.core import java.text.SimpleDateFormat import java.util._ +import java.util.concurrent.TimeUnit import scala.concurrent.duration._ @@ -27,6 +28,8 @@ object time { def advanceBy(duration: Duration): Time = Time(millis + duration.toMillis) + def durationTo(anotherTime: Time): Duration = Duration.apply(anotherTime.millis - millis, TimeUnit.MILLISECONDS) + def toDate(timezone: TimeZone): date.Date = { val cal = Calendar.getInstance(timezone) cal.setTimeInMillis(millis) -- cgit v1.2.3