You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@openwhisk.apache.org by je...@apache.org on 2018/01/18 09:42:48 UTC
[incubator-openwhisk] branch master updated: Change log level
dynamically (updated) (#3174)
This is an automated email from the ASF dual-hosted git repository.
jeremiaswerner pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-openwhisk.git
The following commit(s) were added to refs/heads/master by this push:
new 925500c Change log level dynamically (updated) (#3174)
925500c is described below
commit 925500cf8d34bb75bebd077ea057af236eba0b01
Author: Martin Henke <ma...@web.de>
AuthorDate: Thu Jan 18 10:42:45 2018 +0100
Change log level dynamically (updated) (#3174)
* Add header for extra logging
Signed-off-by: Martin Henke <ma...@de.ibm.com>
---
ansible/group_vars/all | 1 +
ansible/roles/nginx/templates/nginx.conf.j2 | 16 ++++++++
.../src/main/scala/whisk/common/Logging.scala | 6 ++-
.../main/scala/whisk/common/TransactionId.scala | 27 ++++++++------
.../main/scala/whisk/http/BasicHttpService.scala | 26 +++++++++----
docs/logging.md | 43 ++++++++++++++++++++++
.../scala/whisk/core/entity/test/SchemaTests.scala | 40 +++++++++++++++++++-
7 files changed, 137 insertions(+), 22 deletions(-)
diff --git a/ansible/group_vars/all b/ansible/group_vars/all
index 31c462e..7cb1155 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 2212102..7d56f92 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 e63c824..873bcef 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 7f422ac..bdf9255 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 7fe5147..914c199 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 0000000..7846a4e
--- /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 ffe78cd..18bea38 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 {
--
To stop receiving notification emails like this one, please contact
['"commits@openwhisk.apache.org" <co...@openwhisk.apache.org>'].