Replace string-interpolation in log messages with sprintf-style loggi…

…ng (linkerd#1604) Closes linkerd#1592
wendellxoo · Aug 23, 2017 · 797cf84 · 797cf84
1 parent 0d63041
commit 797cf84
Show file tree

Hide file tree

Showing 24 changed files with 69 additions and 67 deletions.
diff --git a/admin/src/main/scala/io/buoyant/admin/Admin.scala b/admin/src/main/scala/io/buoyant/admin/Admin.scala
@@ -128,7 +128,7 @@ class Admin(val address: InetSocketAddress, tlsCfg: Option[TlsServerConfig]) {
     val handlers = baseHandlers ++ appHandlers(app) ++ extHandlers
     val muxer = (handlers ++ indexHandlers(handlers)).foldLeft(new HttpMuxer) {
       case (muxer, Handler(url, service, _)) =>
-        log.debug(s"admin: $url => ${service.getClass.getName}")
+        log.debug("admin: %s => %s", url, service.getClass.getName)
         muxer.withHandler(url, service)
     }
     HeadFilter andThen notFoundView andThen muxer

diff --git a/consul/src/main/scala/io/buoyant/consul/v1/BaseApi.scala b/consul/src/main/scala/io/buoyant/consul/v1/BaseApi.scala
@@ -28,16 +28,16 @@ trait BaseApi extends Closable {
     RetryPolicy.backoff(backoffs) {
       // We will assume 5xx are retryable, everything else is not for now
       case (req, Return(rep)) if rep.status.code >= 500 && rep.status.code < 600 =>
-        log.error(s"Retrying Consul request '${req.method} ${req.uri}' on ${UnexpectedResponse(rep)}")
+        log.error("Retrying Consul request '%s %s' on %s", req.method, req.uri, UnexpectedResponse(rep))
         true
 
       case (req, Throw(Failure(Some(err: ConnectionFailedException)))) if req.getParamNames().contains("index") =>
-        log.error(s"Will not retry blocking index request '${req.method} ${req.uri}' on error: $err")
+        log.error("Will not retry blocking index request '%s %s' on error: %s", req.method, req.uri, err)
         false
       // Don't retry on interruption
       case (_, Throw(e: Failure)) if e.isFlagged(Failure.Interrupted) => false
       case (req, Throw(NonFatal(ex))) =>
-        log.error(s"Retrying Consul request '${req.method} ${req.uri}' on NonFatal error: $ex")
+        log.error("Retrying Consul request '%s %s' on NonFatal error: %s", req.method, req.uri, ex)
         true
     },
     HighResTimer.Default,

diff --git a/finagle/h2/src/main/scala/com/twitter/finagle/buoyant/h2/netty4/DebugHandler.scala b/finagle/h2/src/main/scala/com/twitter/finagle/buoyant/h2/netty4/DebugHandler.scala
@@ -11,37 +11,37 @@ private[h2] class DebugHandler(prefix: String)
   private[this] val log = Logger.get("h2")
 
   override def handlerAdded(ctx: ChannelHandlerContext): Unit = {
-    log.debug(s"$prefix.handlerAdded ${ctx.channel}")
+    log.debug("%s.handlerAdded %s", prefix, ctx.channel)
     super.handlerAdded(ctx)
   }
 
   override def handlerRemoved(ctx: ChannelHandlerContext): Unit = {
-    log.debug(s"$prefix.handlerRemoved ${ctx.channel}")
+    log.debug("%s.handlerRemoved %s", prefix, ctx.channel)
     super.handlerRemoved(ctx)
   }
 
   override def channelActive(ctx: ChannelHandlerContext): Unit = {
-    log.debug(s"$prefix.channelActive ${ctx.channel}")
+    log.debug("%s.channelActive %s", prefix, ctx.channel)
     super.channelActive(ctx)
   }
 
   override def channelInactive(ctx: ChannelHandlerContext): Unit = {
-    log.debug(s"$prefix.channelInactive ${ctx.channel}")
+    log.debug("%s.channelInactive %s", prefix, ctx.channel)
     super.channelInactive(ctx)
   }
 
   override def channelRead(ctx: ChannelHandlerContext, obj: Any): Unit = {
-    log.debug(s"$prefix.channelRead ${ctx.channel} $obj")
+    log.debug("%s.channelRead %s %s", prefix, ctx.channel, obj)
     super.channelRead(ctx, obj)
   }
 
   override def channelReadComplete(ctx: ChannelHandlerContext): Unit = {
-    log.debug(s"$prefix.channelReadComplete ${ctx.channel}")
+    log.debug("%s.channelReadComplete %s", prefix, ctx.channel)
     super.channelReadComplete(ctx)
   }
 
   override def userEventTriggered(ctx: ChannelHandlerContext, ev: Any): Unit = {
-    log.debug(s"$prefix.userEventTriggered ${ctx.channel} $ev")
+    log.debug("%s.userEventTriggered %s %s", prefix, ctx.channel, ev)
     val _ = ctx.fireUserEventTriggered(ev)
   }
 
@@ -67,12 +67,12 @@ private[h2] class DebugHandler(prefix: String)
       case obj => obj.toString
     }
 
-    log.debug(s"$reqid $prefix.write ${ctx.channel} [$objstr]")
+    log.debug("%d %s.write %s [%s]", reqid, prefix, ctx.channel, objstr)
     p.addListener(new ChannelFutureListener {
       override def operationComplete(cf: ChannelFuture): Unit = {
         cf.cause match {
-          case null => log.debug(s"$reqid $prefix.write.complete ${cf.channel} [$objstr] $cf")
-          case e => log.debug(e, s"$reqid $prefix.write.complete ${cf.channel} [$objstr] $cf")
+          case null => log.debug("%d %s.write.complete %s [%s] %s", reqid, prefix, cf.channel, objstr, cf)
+          case e => log.debug(e, "%d %s.write.complete %s [%s] %s", reqid, prefix, cf.channel, objstr, cf)
         }
       }
     })
@@ -81,10 +81,10 @@ private[h2] class DebugHandler(prefix: String)
   }
 
   override def close(ctx: ChannelHandlerContext, p: ChannelPromise): Unit = {
-    log.debug(s"$prefix.close ${ctx.channel}")
+    log.debug("%s.close %s", prefix, ctx.channel)
     p.addListener(new ChannelFutureListener {
       override def operationComplete(cf: ChannelFuture): Unit =
-        log.debug(s"$prefix.close.complete ${ctx.channel} $cf")
+        log.debug("%s.close.complete %s %s", prefix, ctx.channel, cf)
     })
     super.close(ctx, p)
   }

diff --git a/finagle/h2/src/main/scala/com/twitter/finagle/buoyant/h2/netty4/ServerUpgradeHandler.scala b/finagle/h2/src/main/scala/com/twitter/finagle/buoyant/h2/netty4/ServerUpgradeHandler.scala
@@ -62,7 +62,7 @@ class ServerUpgradeHandler(h2Framer: H2FrameCodec) extends ChannelDuplexHandler
 
     // Stop trying to upgrade the protocol.
     ctx.pipeline.remove(this)
-    log.debug(s"h2 server pipeline: installing framer: ${ctx.pipeline}")
+    log.debug("h2 server pipeline: installing framer: %s", ctx.pipeline)
 
     // Pass it on.
     ctx.fireChannelRead(obj); ()

diff --git a/k8s/src/main/scala/io/buoyant/k8s/Watchable.scala b/k8s/src/main/scala/io/buoyant/k8s/Watchable.scala
@@ -42,7 +42,7 @@ private[k8s] abstract class Watchable[O <: KubeObject: TypeReference, W <: Watch
       // Don't retry on interruption
       case (_, Throw(e: Failure)) if e.isFlagged(Failure.Interrupted) => false
       case (_, Throw(NonFatal(ex))) =>
-        log.error(s"retrying k8s request to $path on error $ex")
+        log.error("retrying k8s request to %s on error %s", path, ex)
         true
     },
     HighResTimer.Default,
@@ -129,7 +129,7 @@ private[k8s] abstract class Watchable[O <: KubeObject: TypeReference, W <: Watch
 
           case status =>
             close.set(Closable.nop)
-            log.debug(s"k8s failed to watch resource $path: ${status.code} ${status.reason}")
+            log.debug("k8s failed to watch resource %s: %d %s", path, status.code, status.reason)
             val f = Future.exception(Api.UnexpectedResponse(rsp))
             AsyncStream.fromFuture(f)
         }

diff --git a/k8s/src/main/scala/io/buoyant/k8s/istio/ClusterCache.scala b/k8s/src/main/scala/io/buoyant/k8s/istio/ClusterCache.scala
@@ -14,7 +14,7 @@ class ClusterCache(client: DiscoveryClient) extends Closable {
         case Array(dest, port) =>
           vHost.domains.map(_ -> Cluster(dest, port))
         case _ => // vHost name is invalid
-          log.error(s"Invalid virtual_host name: ${vHost.name}")
+          log.error("Invalid virtual_host name: %s", vHost.name)
           Nil
       }
     }.toMap

diff --git a/k8s/src/main/scala/io/buoyant/k8s/istio/MixerClient.scala b/k8s/src/main/scala/io/buoyant/k8s/istio/MixerClient.scala
@@ -125,7 +125,7 @@ case class MixerClient(service: Service[h2.Request, h2.Response]) {
           nanos = Some((duration.inNanoseconds - duration.inLongSeconds * 1000000000L).toInt)
         )
       )
-    log.trace(s"MixerClient.report: $reportRequest")
+    log.trace("MixerClient.report: %s", reportRequest)
     client.report(Stream.value(reportRequest))
   }
 }
diff --git a/k8s/src/main/scala/io/buoyant/k8s/istio/PollingApiClient.scala b/k8s/src/main/scala/io/buoyant/k8s/istio/PollingApiClient.scala
@@ -36,7 +36,7 @@ abstract class PollingApiClient(client: Service[Request, Response]) {
       def doUpdate() = get[T](url).respond {
         case Return(rsp) => update.update(Activity.Ok(rsp))
         case Throw(e) =>
-          log.error(e, s"failed to watch resource: $url")
+          log.error(e, "failed to watch resource: %s", url)
           update.update(Activity.Failed(e))
       }
 

diff --git a/linkerd/core/src/main/scala/io/buoyant/linkerd/MetricsPruningModule.scala b/linkerd/core/src/main/scala/io/buoyant/linkerd/MetricsPruningModule.scala
@@ -28,7 +28,7 @@ object MetricsPruningModule {
           new ServiceFactoryProxy[Req, Rep](next) {
             override def close(deadline: Time): Future[Unit] = {
               self.close(deadline).respond { _ =>
-                log.info(s"Reaping ${label.label}")
+                log.info("Reaping %s", label.label)
                 statsReceiver.prune()
               }
             }

diff --git a/linkerd/core/src/main/scala/io/buoyant/linkerd/telemeter/UsageDataTelemeter.scala b/linkerd/core/src/main/scala/io/buoyant/linkerd/telemeter/UsageDataTelemeter.scala
@@ -201,7 +201,7 @@ class UsageDataTelemeter(
   private[this] val metricsService = httpClient.newService(metricsDst, "usageData")
   private[this] val started = new AtomicBoolean(false)
   private[this] val pid = java.util.UUID.randomUUID().toString
-  log.info(s"connecting to usageData proxy at $metricsDst")
+  log.info("connecting to usageData proxy at %s", metricsDst)
   val client = Client(metricsService, config, pid, orgId)
 
   val adminHandlers = Seq(

diff --git a/linkerd/main/src/main/scala/io/buoyant/linkerd/Main.scala b/linkerd/main/src/main/scala/io/buoyant/linkerd/Main.scala
@@ -66,12 +66,12 @@ object Main extends App {
     linker: Linker
   ): Seq[Closable with Awaitable[Unit]] = {
     val server = linker.admin.serve(this, LinkerdAdmin(config, linker))
-    log.info(s"serving ${linker.admin.scheme} admin on ${server.boundAddress}")
+    log.info("serving %s admin on %s", linker.admin.scheme, server.boundAddress)
 
     config.admin.flatMap(_.httpIdentifierPort) match {
       case Some(p) =>
         val idServer = linker.admin.serveHandler(p.port, LinkerdAdmin.identifierHandler(config, linker))
-        log.info(s"serving http identifier on ${idServer.boundAddress}")
+        log.info("serving http identifier on %s", idServer.boundAddress)
         Seq(server, idServer)
       case None => Seq(server)
     }

diff --git a/linkerd/protocol/h2/src/main/scala/io/buoyant/linkerd/protocol/h2/IstioLogger.scala b/linkerd/protocol/h2/src/main/scala/io/buoyant/linkerd/protocol/h2/IstioLogger.scala
@@ -53,7 +53,7 @@ case class IstioLoggerConfig(
   private[h2] val host = mixerHost.getOrElse(DefaultMixerHost)
   @JsonIgnore
   private[h2] val port = mixerPort.map(_.port).getOrElse(DefaultMixerPort)
-  log.info(s"connecting to Istio Mixer at $host:$port")
+  log.info("connecting to Istio Mixer at %s:%d", host, port)
 
   @JsonIgnore
   private[this] val mixerDst = Name.bound(Address(host, port))

diff --git a/linkerd/protocol/http/src/main/scala/io/buoyant/linkerd/protocol/http/AccessLogger.scala b/linkerd/protocol/http/src/main/scala/io/buoyant/linkerd/protocol/http/AccessLogger.scala
@@ -21,7 +21,8 @@ case class AccessLogger(log: Logger) extends SimpleFilter[Request, Response] {
       val statusCode = rsp.statusCode
       val responseBytes = rsp.contentLength.map(_.toString).getOrElse("-")
       val requestEndTime = new TimeFormat("dd/MM/yyyy:HH:mm:ss Z").format(Time.now)
-      log.info(s"""$hostHeader $remoteHost $identd $user [$requestEndTime] "$reqResource" $statusCode $responseBytes "$referer" "$userAgent"""")
+      log.info("""%s %s %s %s [%s] "%s" %d %s "%s" "%s"""", hostHeader, remoteHost, identd, user, requestEndTime,
+        reqResource, statusCode, responseBytes, referer, userAgent)
     }
   }
 }

diff --git a/linkerd/protocol/http/src/main/scala/io/buoyant/linkerd/protocol/http/IstioLogger.scala b/linkerd/protocol/http/src/main/scala/io/buoyant/linkerd/protocol/http/IstioLogger.scala
@@ -53,7 +53,7 @@ case class IstioLoggerConfig(
   private[http] val host = mixerHost.getOrElse(DefaultMixerHost)
   @JsonIgnore
   private[http] val port = mixerPort.map(_.port).getOrElse(DefaultMixerPort)
-  log.info(s"connecting to Istio Mixer at $host:$port")
+  log.info("connecting to Istio Mixer at %s:%d", host, port)
 
   @JsonIgnore
   private[this] val mixerDst = Name.bound(Address(host, port))

diff --git a/linkerd/protocol/http/src/test/scala/io/buoyant/linkerd/protocol/http/AccessLoggerTest.scala b/linkerd/protocol/http/src/test/scala/io/buoyant/linkerd/protocol/http/AccessLoggerTest.scala
@@ -3,22 +3,23 @@ package io.buoyant.linkerd.protocol.http
 import com.twitter.finagle.Service
 import com.twitter.finagle.http._
 import com.twitter.util.{Future, Promise, Time}
-import com.twitter.logging.Logger
+import com.twitter.logging._
 import io.buoyant.test.Awaits
 import java.util.{logging => javalog}
 import org.scalatest.FunSuite
-import java.lang.{StringBuilder => JStringBuilder}
 
 class AccessLoggerTest extends FunSuite with Awaits {
 
   object StringLogger extends Logger("string", javalog.Logger.getAnonymousLogger()) {
-    val logged = new JStringBuilder(2048)
+    val handler = new StringHandler(new Formatter {
+      override def format(record: javalog.LogRecord): String = formatText(record)
+    }, None)
 
-    override def info(msg: String, items: Any*) {
-      val _ = logged.append(msg)
-    }
+    clearHandlers()
+    addHandler(handler)
+    setLevel(Level.INFO)
 
-    def getLoggedLines(): String = logged.toString()
+    def getLoggedLines(): String = handler.get
   }
 
   test("access logger filter") {

diff --git a/namer/curator/src/main/scala/io/buoyant/namer/curator/CuratorNamer.scala b/namer/curator/src/main/scala/io/buoyant/namer/curator/CuratorNamer.scala
@@ -77,7 +77,7 @@ class CuratorNamer(zkConnect: String, basePath: String, idPrefix: Path) extends
     val serviceCache = serviceDiscovery.map { disco =>
       val cache = disco.serviceCacheBuilder().name(serviceName).build()
       cache.start()
-      log.info(s"Curator service cache started for $serviceName")
+      log.info("Curator service cache started for %s", serviceName)
       cache
     }
 

diff --git a/namerd/core/src/main/scala/io/buoyant/namerd/NamerdConfig.scala b/namerd/core/src/main/scala/io/buoyant/namerd/NamerdConfig.scala
@@ -46,7 +46,7 @@ private[namerd] case class NamerdConfig(
         telem.tracer match {
           case s: NullTracer =>
           case _ =>
-            log.warning(s"Telemeter ${t.getClass.getCanonicalName} defines a tracer but namerd doesn't support tracing")
+            log.warning("Telemeter %s defines a tracer but namerd doesn't support tracing", t.getClass.getCanonicalName)
         }
         telem
     } :+ adminTelemeter

diff --git a/...d/iface/interpreter-thrift/src/main/scala/io/buoyant/namerd/iface/ThriftNamerClient.scala b/...d/iface/interpreter-thrift/src/main/scala/io/buoyant/namerd/iface/ThriftNamerClient.scala
@@ -91,15 +91,15 @@ class ThriftNamerClient(
 
           // XXX we have to handle other errors, right?
           case Throw(e) =>
-            log.error(e, s"""bind ${path.show}""")
+            log.error(e, "bind %s", path.show)
             Trace.recordBinary("namerd.client/bind.exc", e.toString)
             states() = Activity.Failed(e)
         }
       }
 
       loop(TStamp.empty)
       Closable.make { deadline =>
-        log.debug(s"""bind released ${path.show}""")
+        log.debug("bind released %s", path.show)
         stopped = true
         Future.Unit
       }
@@ -196,15 +196,15 @@ class ThriftNamerClient(
             }
 
           case Throw(e) =>
-            log.error(e, s"addr on $idPath")
+            log.error(e, "addr on %s", idPath)
             Trace.recordBinary("namerd.client/addr.exc", e.getMessage)
             addr() = Addr.Failed(e)
         }
       }
 
       loop(TStamp.empty)
       Closable.make { deadline =>
-        log.debug(s"addr released $idPath")
+        log.debug("addr released %s", idPath)
         stopped = true
         Future.Unit
       }
@@ -286,7 +286,7 @@ class ThriftNamerClient(
             loop(stamp1)
 
           case Throw(e@thrift.DelegationFailure(reason)) =>
-            log.error(s"delegation failed: $reason")
+            log.error("delegation failed: %s", reason)
             states() = Activity.Failed(e)
 
           case Throw(e) =>
@@ -325,18 +325,18 @@ class ThriftNamerClient(
             loop(stamp1)
 
           case Throw(e@thrift.DtabFailure(reason)) =>
-            log.error(s"dtab $namespace lookup failed: $reason")
+            log.error("dtab %s lookup failed: %s", namespace, reason)
             states() = Activity.Failed(e)
 
           case Throw(e) =>
-            log.error(e, s"dtab $namespace lookup failed")
+            log.error(e, "dtab %s lookup failed", namespace)
             states() = Activity.Failed(e)
         }
       }
 
       loop(TStamp.empty)
       Closable.make { deadline =>
-        log.debug(s"dtab $namespace released")
+        log.debug("dtab %s released", namespace)
         stopped = true
         Future.Unit
       }

diff --git a/namerd/main/src/main/scala/io/buoyant/namerd/Main.scala b/namerd/main/src/main/scala/io/buoyant/namerd/Main.scala
@@ -17,11 +17,11 @@ object Main extends App {
         val namerd = config.mk()
 
         val admin = namerd.admin.serve(this, NamerdAdmin(config, namerd))
-        log.info(s"serving ${namerd.admin.scheme} on ${admin.boundAddress}")
+        log.info("serving %s on %s", namerd.admin.scheme, admin.boundAddress)
 
         val servers = namerd.interfaces.map { iface =>
           val server = iface.serve()
-          log.info(s"serving ${iface.kind} interface on ${server.boundAddress}")
+          log.info("serving %s interface on %s", iface.kind, server.boundAddress)
           server
         }
         val telemeters = namerd.telemeters.map(_.run())

diff --git a/namerd/storage/zk/src/main/scala/com/twitter/finagle/serverset2/buoyant/ZkDtabStore.scala b/namerd/storage/zk/src/main/scala/com/twitter/finagle/serverset2/buoyant/ZkDtabStore.scala
@@ -54,7 +54,7 @@ class ZkDtabStore(
 
   def create(ns: String, dtab: Dtab): Future[Unit] = {
     val path = s"$zkPrefix/$ns"
-    log.info(s"Attempting to create dtab at $path")
+    log.info("Attempting to create dtab at %s", path)
 
     zkSession.zk.create(
       path,
@@ -71,7 +71,7 @@ class ZkDtabStore(
 
   def delete(ns: String): Future[Unit] = {
     val path = s"$zkPrefix/$ns"
-    log.info(s"Attempting to delete dtab at $path")
+    log.info("Attempting to delete dtab at %s", path)
 
     zkSession.zk.delete(path, None).rescue {
       case KeeperException.NoNode(_) =>
@@ -83,7 +83,7 @@ class ZkDtabStore(
 
   override def update(ns: String, dtab: Dtab, version: Buf): Future[Unit] = {
     val path = s"$zkPrefix/$ns"
-    log.info(s"Attempting to update dtab at $path")
+    log.info("Attempting to update dtab at %s", path)
 
     zkSession.zk.setData(
       path,
@@ -98,7 +98,7 @@ class ZkDtabStore(
 
   def observe(ns: String): Activity[Option[VersionedDtab]] = {
     val path = s"$zkPrefix/$ns"
-    log.info(s"Attempting to observe $path")
+    log.info("Attempting to observe %s", path)
 
     actOf(_.getDataWatch(path)).flatMap { data =>
       data.data match {
@@ -116,7 +116,7 @@ class ZkDtabStore(
 
   override def put(ns: String, dtab: Dtab): Future[Unit] = {
     val path = s"$zkPrefix/$ns"
-    log.info(s"Attempting to put dtab at $path")
+    log.info("Attempting to put dtab at %s", path)
 
     // Send a create and a setData at the same time in hopes that one of them will succeed.
     // If both fail, the user can always retry the put.