You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@openwhisk.apache.org by GitBox <gi...@apache.org> on 2018/01/18 09:42:50 UTC
[GitHub] jeremiaswerner closed pull request #3174: Change log level dynamically (updated)
jeremiaswerner closed pull request #3174: Change log level dynamically (updated)
URL: https://github.com/apache/incubator-openwhisk/pull/3174
This is a PR merged from a forked repository.
As GitHub hides the original diff on merge, it is displayed below for
the sake of provenance:
As this is a foreign pull request (from a fork), the diff is supplied
below (as it won't show otherwise due to GitHub magic):
diff --git a/ansible/group_vars/all b/ansible/group_vars/all
index 31c462e265..7cb11556f6 100644
--- a/ansible/group_vars/all
+++ b/ansible/group_vars/all
@@ -161,6 +161,7 @@ nginx:
verify_client: "{{ nginx_ssl_verify_client | default('off') }}"
wpn:
router: "{{ nginx_wpn_router | default('1') }}"
+ special_users: "{{ nginx_special_users | default('[]') }}"
# These are the variables to define all database relevant settings.
# The authKeys are the users, that are initially created to use OpenWhisk.
diff --git a/ansible/roles/nginx/templates/nginx.conf.j2 b/ansible/roles/nginx/templates/nginx.conf.j2
index 2212102bc8..7d56f92eca 100644
--- a/ansible/roles/nginx/templates/nginx.conf.j2
+++ b/ansible/roles/nginx/templates/nginx.conf.j2
@@ -37,6 +37,20 @@ http {
keepalive 512;
}
+ map "$remote_user" $special_user {
+ default not_special;
+{% for user in nginx.special_users %}
+ "{{ user }}" special;
+{% endfor %}
+ }
+
+ map "$special_user:$http_x_ow_extra_logging" $extra_logging {
+ default "off";
+ "special:off" off;
+ "special:on" on;
+ "special:" on;
+ }
+
server {
listen 443 default ssl;
@@ -65,6 +79,7 @@ http {
if ($namespace) {
rewrite /(.*) /api/v1/web/${namespace}/$1 break;
}
+ proxy_set_header X-OW-EXTRA-LOGGING $extra_logging;
proxy_pass http://controllers;
proxy_read_timeout 75s; # 70+5 additional seconds to allow controller to terminate request
}
@@ -74,6 +89,7 @@ http {
if ($namespace) {
rewrite ^ /api/v1/web/${namespace}/public/index.html break;
}
+ proxy_set_header X-OW-EXTRA-LOGGING $extra_logging;
proxy_pass http://controllers;
proxy_read_timeout 75s; # 70+5 additional seconds to allow controller to terminate request
}
diff --git a/common/scala/src/main/scala/whisk/common/Logging.scala b/common/scala/src/main/scala/whisk/common/Logging.scala
index e63c824f30..873bcef81b 100644
--- a/common/scala/src/main/scala/whisk/common/Logging.scala
+++ b/common/scala/src/main/scala/whisk/common/Logging.scala
@@ -37,7 +37,11 @@ trait Logging {
* @param message Message to write to the log
*/
def debug(from: AnyRef, message: String)(implicit id: TransactionId = TransactionId.unknown) = {
- emit(DebugLevel, id, from, message)
+ if (id.meta.extraLogging) {
+ emit(InfoLevel, id, from, message)
+ } else {
+ emit(DebugLevel, id, from, message)
+ }
}
/**
diff --git a/common/scala/src/main/scala/whisk/common/TransactionId.scala b/common/scala/src/main/scala/whisk/common/TransactionId.scala
index 7f422ac8f6..bdf9255521 100644
--- a/common/scala/src/main/scala/whisk/common/TransactionId.scala
+++ b/common/scala/src/main/scala/whisk/common/TransactionId.scala
@@ -24,13 +24,9 @@ import java.util.concurrent.atomic.AtomicInteger
import scala.math.BigDecimal.int2bigDecimal
import scala.util.Try
-
import akka.event.Logging.{InfoLevel, WarningLevel}
import akka.event.Logging.LogLevel
-import spray.json.JsArray
-import spray.json.JsNumber
-import spray.json.JsValue
-import spray.json.RootJsonFormat
+import spray.json._
import whisk.core.ConfigKeys
@@ -202,7 +198,7 @@ case class StartMarker(val start: Instant, startMarker: LogMarkerToken)
* negative for system operation and zero when originator is not known
* @param start the timestamp when the request processing commenced
*/
-protected case class TransactionMetadata(val id: Long, val start: Instant)
+protected case class TransactionMetadata(val id: Long, val start: Instant, val extraLogging: Boolean = false)
object TransactionId {
@@ -221,21 +217,28 @@ object TransactionId {
val controller = TransactionId(-130) // Controller startup
val dbBatcher = TransactionId(-140) // Database batcher
- def apply(tid: BigDecimal): TransactionId = {
+ def apply(tid: BigDecimal, extraLogging: Boolean = false): TransactionId = {
Try {
val now = Instant.now(Clock.systemUTC())
- TransactionId(TransactionMetadata(tid.toLong, now))
+ TransactionId(TransactionMetadata(tid.toLong, now, extraLogging))
} getOrElse unknown
}
implicit val serdes = new RootJsonFormat[TransactionId] {
- def write(t: TransactionId) = JsArray(JsNumber(t.meta.id), JsNumber(t.meta.start.toEpochMilli))
+ def write(t: TransactionId) = {
+ if (t.meta.extraLogging)
+ JsArray(JsNumber(t.meta.id), JsNumber(t.meta.start.toEpochMilli), JsBoolean(t.meta.extraLogging))
+ else
+ JsArray(JsNumber(t.meta.id), JsNumber(t.meta.start.toEpochMilli))
+ }
def read(value: JsValue) =
Try {
value match {
case JsArray(Vector(JsNumber(id), JsNumber(start))) =>
- TransactionId(TransactionMetadata(id.longValue, Instant.ofEpochMilli(start.longValue)))
+ TransactionId(TransactionMetadata(id.longValue, Instant.ofEpochMilli(start.longValue), false))
+ case JsArray(Vector(JsNumber(id), JsNumber(start), JsBoolean(extraLogging))) =>
+ TransactionId(TransactionMetadata(id.longValue, Instant.ofEpochMilli(start.longValue), extraLogging))
}
} getOrElse unknown
}
@@ -254,7 +257,7 @@ trait TransactionCounter {
// seed the counter so transids do not overlap: instanceOrdinal + n * stride, start at n = 1
private lazy val cnt = new AtomicInteger(instanceOrdinal + stride)
- def transid(): TransactionId = {
- TransactionId(cnt.addAndGet(stride))
+ def transid(extraLogging: Boolean = false): TransactionId = {
+ TransactionId(cnt.addAndGet(stride), extraLogging)
}
}
diff --git a/common/scala/src/main/scala/whisk/http/BasicHttpService.scala b/common/scala/src/main/scala/whisk/http/BasicHttpService.scala
index 798bb1eff8..2aab603fc7 100644
--- a/common/scala/src/main/scala/whisk/http/BasicHttpService.scala
+++ b/common/scala/src/main/scala/whisk/http/BasicHttpService.scala
@@ -27,8 +27,7 @@ import akka.http.scaladsl.model._
import akka.http.scaladsl.model.HttpRequest
import akka.http.scaladsl.server._
import akka.http.scaladsl.server.RouteResult.Rejected
-import akka.http.scaladsl.server.directives.DebuggingDirectives
-import akka.http.scaladsl.server.directives.LogEntry
+import akka.http.scaladsl.server.directives._
import akka.stream.ActorMaterializer
import spray.json._
import whisk.common.LogMarker
@@ -44,6 +43,8 @@ import whisk.common.MetricEmitter
*/
trait BasicHttpService extends Directives with TransactionCounter {
+ val OW_EXTRA_LOGGING_HEADER = "X-OW-EXTRA-LOGGING"
+
/**
* Gets the routes implemented by the HTTP service.
*
@@ -77,10 +78,12 @@ trait BasicHttpService extends Directives with TransactionCounter {
assignId { implicit transid =>
DebuggingDirectives.logRequest(logRequestInfo _) {
DebuggingDirectives.logRequestResult(logResponseInfo _) {
- handleRejections(BasicHttpService.customRejectionHandler) {
- prioritizeRejections {
- toStrictEntity(30.seconds) {
- routes
+ BasicDirectives.mapRequest(_.removeHeader(OW_EXTRA_LOGGING_HEADER)) {
+ handleRejections(BasicHttpService.customRejectionHandler) {
+ prioritizeRejections {
+ toStrictEntity(30.seconds) {
+ routes
+ }
}
}
}
@@ -90,7 +93,16 @@ trait BasicHttpService extends Directives with TransactionCounter {
}
/** Assigns transaction id to every request. */
- protected val assignId = extract(_ => transid())
+ protected def assignId = HeaderDirectives.optionalHeaderValueByName(OW_EXTRA_LOGGING_HEADER) flatMap { headerValue =>
+ val extraLogging = headerValue match {
+ // extract headers from HTTP request that indicates if additional logging should be enabled for this transaction.
+ // Passing "on" as header content will enable additional logging for this transaction,
+ // passing any other value will leave it as configured in the logging configuration
+ case Some(value) => value.toLowerCase == "on"
+ case None => false
+ }
+ extract(_ => transid(extraLogging))
+ }
/** Generates log entry for every request. */
protected def logRequestInfo(req: HttpRequest)(implicit tid: TransactionId): LogEntry = {
diff --git a/docs/logging.md b/docs/logging.md
new file mode 100644
index 0000000000..7846a4eae3
--- /dev/null
+++ b/docs/logging.md
@@ -0,0 +1,43 @@
+# Logging in OpenWhisk
+
+## Default Logging Provider
+
+OpenWhisk uses Logback as default logging provider via slf4j.
+
+Logback can be configured in the configuration file [logback.xml](../common/scala/src/main/resources/logback.xml).
+
+Besides other things this configuration file defines the default log level for OpenWhisk.
+Akka Logging inherits the log level defined here.
+
+## Enable debug-level logging for selected namespaces
+
+For performance reasons it is recommended to leave the default log level on INFO level. For debugging purposes one can enable DEBUG level logging for selected namespaces
+(aka special users). A list of namespace ids can be configured using the `nginx_special_users` property in the `group_vars/all` file of an environment.
+
+Example:
+
+```
+nginx_special_users:
+- 9cfe57b0-7fc1-4cf4-90b6-d7e9ea91271f
+- 08f65e83-2d12-5b7c-b625-23df81c749a9
+```
+
+## Using JMX to adapt the loglevel at run-time
+
+One can alter the log level of a single component (Controller or Invoker) on the fly using JMX.
+
+### Example for using [jmxterm](ttp://wiki.cyclopsgroup.org/jmxterm/) to alter the log level
+
+1. Create a command file for jmxterm
+```
+open <targethost>:<jmx port> -u <jmx username> -p <jmx password>
+run -b ch.qos.logback.classic:Name=default,Type=ch.qos.logback.classic.jmx.JMXConfigurator getLoggerLevel ROOT
+run -b ch.qos.logback.classic:Name=default,Type=ch.qos.logback.classic.jmx.JMXConfigurator setLoggerLevel ROOT DEBUG
+run -b ch.qos.logback.classic:Name=default,Type=ch.qos.logback.classic.jmx.JMXConfigurator getLoggerLevel ROOT
+close
+```
+
+2. Issue the command with the created file like this:
+```
+java -jar jmxterm-1.0.0-uber.jar -n silent < filename
+```
diff --git a/tests/src/test/scala/whisk/core/entity/test/SchemaTests.scala b/tests/src/test/scala/whisk/core/entity/test/SchemaTests.scala
index ffe78cd0d2..18bea38ce5 100644
--- a/tests/src/test/scala/whisk/core/entity/test/SchemaTests.scala
+++ b/tests/src/test/scala/whisk/core/entity/test/SchemaTests.scala
@@ -19,8 +19,6 @@ package whisk.core.entity.test
import java.util.Base64
-import scala.BigInt
-import scala.Vector
import scala.concurrent.duration.DurationInt
import scala.language.postfixOps
import scala.language.reflectiveCalls
@@ -33,6 +31,7 @@ import org.scalatest.Matchers
import org.scalatest.junit.JUnitRunner
import spray.json._
import spray.json.DefaultJsonProtocol._
+import whisk.common.TransactionId
import whisk.core.controller.test.WhiskAuthHelpers
import whisk.core.entitlement.Privilege
import whisk.core.entity.ExecManifest.{ImageName, RuntimeManifest}
@@ -70,6 +69,43 @@ class SchemaTests extends FlatSpec with BeforeAndAfter with ExecHelpers with Mat
a[DeserializationException] should be thrownBy Privilege.serdes.read("???".toJson)
}
+ behavior of "TransactionId"
+
+ it should "serdes a transaction id without extraLogging parameter" in {
+ val txIdWithoutParameter = TransactionId(4711)
+
+ // test serialization
+ val serializedTxIdWithoutParameter = TransactionId.serdes.write(txIdWithoutParameter)
+ serializedTxIdWithoutParameter match {
+ case JsArray(Vector(JsNumber(id), JsNumber(_))) =>
+ assert(id == txIdWithoutParameter.meta.id)
+ case _ => withClue(serializedTxIdWithoutParameter) { assert(false) }
+ }
+
+ // test deserialization
+ val deserializedTxIdWithoutParameter = TransactionId.serdes.read(serializedTxIdWithoutParameter)
+ deserializedTxIdWithoutParameter.meta.id should equal(txIdWithoutParameter.meta.id)
+ deserializedTxIdWithoutParameter.meta.extraLogging should equal(false)
+ }
+
+ it should "serdes a transaction id with extraLogging parameter" in {
+ val txIdWithParameter = TransactionId(4711, true)
+
+ // test serialization
+ val serializedTxIdWithParameter = TransactionId.serdes.write(txIdWithParameter)
+ serializedTxIdWithParameter match {
+ case JsArray(Vector(JsNumber(id), JsNumber(_), JsBoolean(extraLogging))) =>
+ assert(id == txIdWithParameter.meta.id)
+ assert(extraLogging)
+ case _ => withClue(serializedTxIdWithParameter) { assert(false) }
+ }
+
+ // test deserialization
+ val deserializedTxIdWithParameter = TransactionId.serdes.read(serializedTxIdWithParameter)
+ deserializedTxIdWithParameter.meta.id should equal(txIdWithParameter.meta.id)
+ assert(deserializedTxIdWithParameter.meta.extraLogging)
+ }
+
behavior of "Identity"
it should "serdes an identity" in {
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services