Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Fixes #16503: Normalize loggers for timing performance on write promises #2703

Merged
merged 1 commit into from
Jan 12, 2020
+278 −343
Merged

Fixes #16503: Normalize loggers for timing performance on write promises #2703

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
69 changes: 34 additions & 35 deletions ...s/rudder/rudder-core/src/main/scala/com/normation/rudder/batch/AsyncDeploymentActor.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,8 @@ import scala.xml.NodeSeq
import com.normation.eventlog.ModificationId
import java.io.File

import com.normation.rudder.domain.logger.PolicyLogger
import com.normation.errors.RudderError
import com.normation.rudder.domain.logger.PolicyGenerationLogger
import com.normation.zio._

sealed trait StartDeploymentMessage
Expand Down Expand Up @@ -116,7 +117,6 @@ final class AsyncDeploymentActor(
deploymentManager =>

val timeFormat = "yyyy-MM-dd HH:mm:ss"
val logger = PolicyLogger

//message from the deployment agent to the manager
private[this] sealed case class DeploymentResult(
Expand Down Expand Up @@ -147,10 +147,10 @@ final class AsyncDeploymentActor(
private[this] def getLastFinishedDeployment: CurrentDeploymentStatus = {
eventLogger.getLastDeployement() match {
case Empty =>
logger.debug("Could not find a last policy update")
PolicyGenerationLogger.debug("Could not find a last policy update")
NoStatus
case m : Failure =>
logger.debug(s"Error when fetching the last policy update, reason: ${m.messageChain}")
PolicyGenerationLogger.debug(s"Error when fetching the last policy update, reason: ${m.messageChain}")
NoStatus
case Full(status) => status
}
Expand Down Expand Up @@ -182,11 +182,11 @@ final class AsyncDeploymentActor(
val file = new File(policyUpdateRunningFlagPath)
try {
file.createNewFile()
logger.debug(s"Flag file '${policyUpdateRunningFlagPath}' created")
PolicyGenerationLogger.debug(s"Flag file '${policyUpdateRunningFlagPath}' created")
} catch {
// Exception while checking the file existence
case e : Exception =>
logger.error(s"An error occurred while creating flag file '${policyUpdateRunningFlagPath}', cause is: ${e.getMessage}")
PolicyGenerationLogger.error(s"An error occurred while creating flag file '${policyUpdateRunningFlagPath}', cause is: ${e.getMessage}")
}
}

Expand All @@ -200,20 +200,20 @@ final class AsyncDeploymentActor(
// delete the file only if it is present
if (file.delete) {
// Deleted, come back to normal
logger.info(s"Flag file '${file.getPath}' successfully removed")
PolicyGenerationLogger.info(s"Flag file '${file.getPath}' successfully removed")
} else {
// File could not be deleted, seek for reason
if (!file.exists()) {
logger.warn(s"Flag file '${file.getPath}' could not be removed as it does not exist anymore")
PolicyGenerationLogger.warn(s"Flag file '${file.getPath}' could not be removed as it does not exist anymore")
} else {
logger.error(s"Flag file '${file.getPath}' could not be removed, you may have to remove it manually, cause is: Permission denied or someone is actually editing the file")
PolicyGenerationLogger.error(s"Flag file '${file.getPath}' could not be removed, you may have to remove it manually, cause is: Permission denied or someone is actually editing the file")
}
}
}
} catch {
// Exception while checking the file existence
case e: Exception =>
logger.error(s"An error occurred while deleting flag file '${file.getPath}', cause is: ${e.getMessage}")
PolicyGenerationLogger.error(s"An error occurred while deleting flag file '${file.getPath}', cause is: ${e.getMessage}")
}
}
}
Expand All @@ -226,21 +226,21 @@ final class AsyncDeploymentActor(
implicit val a = actor
createFlagFile

logger.trace("Policy updater: receive new automatic policy update request message")
PolicyGenerationLogger.trace("Policy updater: receive new automatic policy update request message")

currentDeployerState match {
case IdleDeployer => //ok, start a new deployment
currentDeploymentId += 1
val newState = Processing(currentDeploymentId, DateTime.now)
currentDeployerState = newState
logger.trace("Policy updater: ask to start updating policies")
PolicyGenerationLogger.trace("Policy updater: ask to start updating policies")
val event = eventLogger.repository.saveEventLog(
modId, AutomaticStartDeployement(WithDetails(NodeSeq.Empty))
).either.runNow.toOption
DeployerAgent ! NewDeployment(newState.id, modId, newState.started, actor, event.flatMap(_.id).getOrElse(0))

case p @ Processing(id, startTime) => //ok, add a pending deployment
logger.trace("Policy updater: currently updating policies, add a pending update request")
PolicyGenerationLogger.trace("Policy updater: currently updating policies, add a pending update request")
val event = eventLogger.repository.saveEventLog(
modId, AutomaticStartDeployement(WithDetails(<addPending alreadyPending="false"/>))
).either.runNow.toOption
Expand All @@ -249,14 +249,14 @@ final class AsyncDeploymentActor(
case p: ProcessingAndPendingAuto => //drop message, one is already pending
eventLogger.repository.saveEventLog(
modId, AutomaticStartDeployement(WithDetails(<addPending alreadyPending="true"/>))
).runNowLogError(err => logger.error(s"Error when saving start generation event log: ${err.fullMsg}"))
logger.info("One automatic policy update process is already pending, ignoring new policy update request")
).runNowLogError(err => PolicyGenerationLogger.error(s"Error when saving start generation event log: ${err.fullMsg}"))
PolicyGenerationLogger.info("One automatic policy update process is already pending, ignoring new policy update request")

case p: ProcessingAndPendingManual => //drop message, one is already pending
eventLogger.repository.saveEventLog(
modId, AutomaticStartDeployement(WithDetails(<addPending alreadyPending="true"/>))
).runNowLogError(err => logger.error(s"Error when saving start generation event log: ${err.fullMsg}"))
logger.info("One manual policy update process is already pending, ignoring new policy update request")
).runNowLogError(err => PolicyGenerationLogger.error(s"Error when saving start generation event log: ${err.fullMsg}"))
PolicyGenerationLogger.info("One manual policy update process is already pending, ignoring new policy update request")

}
//update listeners
Expand All @@ -268,20 +268,20 @@ final class AsyncDeploymentActor(
implicit val r = Some(reason)
createFlagFile

logger.trace("Policy updater: receive new manual policy update request message")
PolicyGenerationLogger.trace("Policy updater: receive new manual policy update request message")
currentDeployerState match {
case IdleDeployer => //ok, start a new deployment
currentDeploymentId += 1
val newState = Processing(currentDeploymentId, DateTime.now)
currentDeployerState = newState
logger.trace("Policy updater: ask to start updating policies")
PolicyGenerationLogger.trace("Policy updater: ask to start updating policies")
val event = eventLogger.repository.saveEventLog(
modId, ManualStartDeployement(WithDetails(NodeSeq.Empty))
).either.runNow.toOption
DeployerAgent ! NewDeployment(newState.id, modId, newState.started, actor, event.flatMap(_.id).getOrElse(0))

case p@Processing(id, startTime) => //ok, add a pending deployment
logger.trace("Policy updater: currently updating policies, add a pending update request")
PolicyGenerationLogger.trace("Policy updater: currently updating policies, add a pending update request")
val event = eventLogger.repository.saveEventLog(
modId, ManualStartDeployement(WithDetails(<addPending alreadyPending="false"/>))
).either.runNow.toOption
Expand All @@ -290,15 +290,15 @@ final class AsyncDeploymentActor(
case p:ProcessingAndPendingManual => //drop message, one is already pending
eventLogger.repository.saveEventLog(
modId, ManualStartDeployement(WithDetails(<addPending alreadyPending="true"/>))
).runNowLogError(err => logger.error(s"Error when saving start generation event log: ${err.fullMsg}"))
logger.info("One policy update process is already pending, ignoring new policy update request")
).runNowLogError(err => PolicyGenerationLogger.error(s"Error when saving start generation event log: ${err.fullMsg}"))
PolicyGenerationLogger.info("One policy update process is already pending, ignoring new policy update request")

case p:ProcessingAndPendingAuto => //replace with manual
val event = eventLogger.repository.saveEventLog(
modId, ManualStartDeployement(WithDetails(<addPending alreadyPending="true"/>))
).either.runNow.toOption
currentDeployerState = ProcessingAndPendingManual(DateTime.now, p.current, actor, event.flatMap(_.id).getOrElse(0), reason)
logger.info("One automatic policy update process is already pending, replacing by a manual request")
PolicyGenerationLogger.info("One automatic policy update process is already pending, replacing by a manual request")
}
//update listeners
updateListeners()
Expand All @@ -313,7 +313,7 @@ final class AsyncDeploymentActor(
result match {
case e:EmptyBox =>
val m = s"Policy update error for process '${id}' at ${endTime.toString(timeFormat)}"
logger.error(m, e)
PolicyGenerationLogger.error(m, e)
lastFinishedDeployement = ErrorStatus(id, startTime, endTime, e ?~! m)
eventLogger.repository.saveEventLog(modId, FailedDeployment(EventLogDetails(
modificationId = None
Expand All @@ -322,10 +322,10 @@ final class AsyncDeploymentActor(
, cause = Some(deploymentEventId)
, creationDate = startTime
, reason = None
))).runNowLogError(err => logger.error(s"Error when saving generation event log result: ${err.fullMsg}"))
))).runNowLogError(err => PolicyGenerationLogger.error(s"Error when saving generation event log result: ${err.fullMsg}"))

case Full(nodeIds) =>
logger.info(s"Successful policy update '${id}' [started ${startTime.toString(timeFormat)} - ended ${endTime.toString(timeFormat)}]")
PolicyGenerationLogger.info(s"Successful policy update '${id}' [started ${startTime.toString(timeFormat)} - ended ${endTime.toString(timeFormat)}]")
lastFinishedDeployement = SuccessStatus(id, startTime, endTime, nodeIds)
eventLogger.repository.saveEventLog(modId, SuccessfulDeployment(EventLogDetails(
modificationId = None
Expand All @@ -334,13 +334,13 @@ final class AsyncDeploymentActor(
, cause = Some(deploymentEventId)
, creationDate = startTime
, reason = None
))).runNowLogError(err => logger.error(s"Error when saving generation event log result: ${err.fullMsg}"))
))).runNowLogError(err => PolicyGenerationLogger.error(s"Error when saving generation event log result: ${err.fullMsg}"))
}

//look if there is another process to start and update current deployer status
currentDeployerState match {
case IdleDeployer => //should never happen
logger.debug("Found an IdleDeployer state for policy updater agent but it just gave me a result. What happened ?")
PolicyGenerationLogger.debug("Found an IdleDeployer state for policy updater agent but it just gave me a result. What happened ?")

case p:Processing => //ok, come back to IdleDeployer
currentDeployerState = IdleDeployer
Expand All @@ -361,33 +361,32 @@ final class AsyncDeploymentActor(
//
//Unexpected messages
//
case x => logger.debug("Policy updater does not know how to process message: '%s'".format(x))
case x => PolicyGenerationLogger.debug("Policy updater does not know how to process message: '%s'".format(x))
}

/**
* The internal agent that will actually do the deployment
* Long time running process, I/O consuming.
*/
private[this] object DeployerAgent extends LiftActor {
val logger = PolicyLogger

override protected def messageHandler = {
//
// Start a new deployment
//
case NewDeployment(id, modId, startTime, actor, eventId) =>
logger.trace("Policy updater Agent: start to update policies")
PolicyGenerationLogger.trace("Policy updater Agent: start to update policies")
try {
val result = deploymentService.deploy()

result match {
case Full(_) => // nothing to report
case m: Failure =>
logger.error(s"Error when updating policy, reason was: ${m.messageChain}")
PolicyGenerationLogger.error(s"Error when updating policy, reason was: ${m.messageChain}")
m.rootExceptionCause.foreach { ex =>
logger.error("Root exception was: " + ex.getMessage)
PolicyGenerationLogger.error(s"Root exception was: ${RudderError.formatException(ex)}")
}
case Empty => logger.error("Error when updating policy (no reason given)")
case Empty => PolicyGenerationLogger.error("Error when updating policy (no reason given)")
}

deploymentManager ! DeploymentResult(id, modId, startTime,DateTime.now, result, actor, eventId)
Expand All @@ -400,7 +399,7 @@ final class AsyncDeploymentActor(
//
case x =>
val msg = s"Policy updater agent does not know how to process message: '${x}'"
logger.error(msg)
PolicyGenerationLogger.error(msg)
deploymentManager ! DeploymentResult(-1, ModificationId.dummy, DateTime.now, DateTime.now, Failure(msg), RudderEventActor, 0)
}
}
Expand Down
42 changes: 38 additions & 4 deletions ...der/rudder-core/src/main/scala/com/normation/rudder/domain/logger/ApplicationLogger.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -97,10 +97,44 @@ object JsDirectiveParamLoggerPure extends NamedZioLogger {
}


object GenerationLoggerPure extends NamedZioLogger {
def loggerName = "policy-generation"
}

object TechniqueReaderLoggerPure extends NamedZioLogger {
def loggerName = "techniques.reader"
}

/**
* Logger about change request and other workflow thing.
*/
object ChangeRequestLogger extends Logger {
override protected def _logger = LoggerFactory.getLogger("changeRequest")
}

/**
* Logger used for historization of object names by `HistorizationService`
*/
object HistorizationLogger extends Logger {
override protected def _logger = LoggerFactory.getLogger("historization")
}

object GitArchiveLoggerPure extends NamedZioLogger {
override def loggerName: String = "git-policy-archive"
}

object GitArchiveLogger extends Logger {
override protected def _logger = LoggerFactory.getLogger("git-policy-archive")
}

object ComplianceLogger extends Logger {
override protected def _logger = LoggerFactory.getLogger("compliance")
}

object ReportLogger extends Logger {
override protected def _logger = LoggerFactory.getLogger("report")
}

object ReportLoggerPure extends NamedZioLogger {
override def loggerName: String = "report"

object Changes extends NamedZioLogger {
override def loggerName: String = "report.changes"
}
}
48 changes: 0 additions & 48 deletions ...r/rudder-core/src/main/scala/com/normation/rudder/domain/logger/ChangeRequestLogger.scala
View file
Open in desktop

This file was deleted.

0 ...domain/logger/ComplianceDebugLogger.scala → ...domain/logger/DebugComplianceLogger.scala
View file
Open in desktop
File renamed without changes.
12 changes: 6 additions & 6 deletions .../nodeconfig/NodeConfigurationLogger.scala → ...logger/DebugNodeConfigurationLogger.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,26 +35,25 @@
*************************************************************************************
*/

package com.normation.rudder.services.policies.nodeconfig
package com.normation.rudder.domain.logger

import java.io.File
import java.io.PrintWriter

import com.normation.inventory.domain.NodeId
import com.normation.rudder.services.policies.NodeConfiguration
import com.normation.utils.Control.sequence
import java.io.File
import java.io.PrintWriter
import net.liftweb.common._
import net.liftweb.json.NoTypeHints
import net.liftweb.json.Serialization
import net.liftweb.json.Serialization.writePretty
import org.joda.time.DateTime
import org.slf4j.LoggerFactory
import com.normation.rudder.services.policies.NodeConfiguration


trait NodeConfigurationLogger {

def log(nodeConfiguration: Seq[NodeConfiguration]): Box[Set[NodeId]]

def isDebugEnabled: Boolean
}

/**
Expand All @@ -69,6 +68,7 @@ class NodeConfigurationLoggerImpl(
) extends NodeConfigurationLogger {

val logger = LoggerFactory.getLogger("rudder.debug.nodeconfiguration")
def isDebugEnabled: Boolean = logger.isDebugEnabled

{
val p = new File(path)
Expand Down
Loading