-
Notifications
You must be signed in to change notification settings - Fork 44
JSON logging cleanup #3881
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.
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
JSON logging cleanup #3881
Changes from all commits
0d280f0
f406df9
6153007
790d638
8be7db1
902e6c4
f59f7c7
502105f
e17ae96
db0ecf5
a6aabe8
3bf79a0
6e8a3da
acbf129
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -1,3 +1,4 @@ | ||
{-# LANGUAGE QuasiQuotes #-} | ||
{-# LANGUAGE TemplateHaskell #-} | ||
|
||
module Booster.CLOptions ( | ||
|
@@ -6,6 +7,7 @@ module Booster.CLOptions ( | |
LogFormat (..), | ||
clOptionsParser, | ||
adjustLogLevels, | ||
levelToContext, | ||
versionInfoParser, | ||
) where | ||
|
||
|
@@ -22,9 +24,11 @@ import Text.Casing (fromHumps, fromKebab, toKebab, toPascal) | |
import Text.Read (readMaybe) | ||
|
||
import Booster.GlobalState (EquationOptions (..)) | ||
import Booster.Log.Context (ContextFilter, readContextFilter) | ||
import Booster.Log.Context (ContextFilter, ctxt, readContextFilter) | ||
import Booster.SMT.Interface (SMTOptions (..), defaultSMTOptions) | ||
import Booster.SMT.LowLevelCodec qualified as SMT (parseSExpr) | ||
import Data.Map (Map) | ||
import Data.Map qualified as Map | ||
|
||
data CLOptions = CLOptions | ||
{ definitionFile :: FilePath | ||
|
@@ -35,7 +39,7 @@ data CLOptions = CLOptions | |
, logTimeStamps :: Bool | ||
, logFormat :: LogFormat | ||
, logContexts :: [ContextFilter] | ||
, simplificationLogFile :: Maybe FilePath | ||
, logFile :: Maybe FilePath | ||
, smtOptions :: Maybe SMTOptions | ||
, equationOptions :: EquationOptions | ||
, -- developer options below | ||
|
@@ -116,10 +120,10 @@ clOptionsParser = | |
) | ||
<*> optional | ||
( strOption | ||
( metavar "JSON_LOG_FILE" | ||
<> long "simplification-log-file" | ||
( metavar "LOG_FILE" | ||
<> long "log-file" | ||
<> help | ||
"Log file for the JSON simplification logs" | ||
"Log file to output the logs into" | ||
goodlyrottenapple marked this conversation as resolved.
Show resolved
Hide resolved
|
||
) | ||
) | ||
<*> parseSMTOptions | ||
|
@@ -171,14 +175,50 @@ allowedLogLevels = | |
, ("RewriteKore", "Log all rewriting in kore-rpc fall-backs") | ||
, ("RewriteSuccess", "Log successful rewrites (booster and kore-rpc)") | ||
, ("Simplify", "Log all simplification/evaluation in booster") | ||
, ("SimplifyJson", "Log simplification/evaluation in booster as JSON") | ||
, ("SimplifyKore", "Log all simplification in kore-rpc") | ||
, ("SimplifySuccess", "Log successful simplifications (booster and kore-rpc)") | ||
, ("Depth", "Log the current depth of the state") | ||
, ("SMT", "Log the SMT-solver interactions") | ||
, ("ErrorDetails", "Log error conditions with extensive details") | ||
] | ||
|
||
levelToContext :: Map Text [ContextFilter] | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. here are some of the common log filter we may want. Let me know if you think we should add any other ones |
||
levelToContext = | ||
Map.fromList | ||
[ | ||
( "Simplify" | ||
, | ||
[ [ctxt| booster|kore>function*|simplification*,success|failure|abort|detail |] | ||
, [ctxt| booster|kore>function*|simplification*,match,failure|abort |] | ||
] | ||
) | ||
, | ||
( "SimplifySuccess" | ||
, | ||
[ [ctxt| booster|kore>function*|simplification*,success|detail |] | ||
] | ||
) | ||
, | ||
( "Rewrite" | ||
, | ||
[ [ctxt| booster|kore>rewrite*,success|failure|abort|detail |] | ||
, [ctxt| booster|kore>rewrite*,match,failure|abort |] | ||
] | ||
) | ||
, | ||
( "RewriteSuccess" | ||
, | ||
[ [ctxt| booster|kore>rewrite*,success|detail |] | ||
] | ||
) | ||
, | ||
( "SMT" | ||
, | ||
[ [ctxt| booster|kore>smt |] | ||
] | ||
) | ||
] | ||
|
||
-- Partition provided log levels into standard and custom ones, and | ||
-- select the lowest standard level. Default to 'LevelInfo' if no | ||
-- standard log level was given. | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -28,7 +28,6 @@ module Booster.Pattern.ApplyEquations ( | |
evaluateConstraints, | ||
) where | ||
|
||
import Control.Applicative (Alternative (..)) | ||
import Control.Monad | ||
import Control.Monad.Extra (fromMaybeM, whenJust) | ||
import Control.Monad.IO.Class (MonadIO (..)) | ||
|
@@ -45,7 +44,6 @@ import Control.Monad.Trans.Except | |
import Control.Monad.Trans.Reader (ReaderT (..), ask, asks, withReaderT) | ||
import Control.Monad.Trans.State | ||
import Data.Aeson (object, (.=)) | ||
import Data.Aeson.Text (encodeToLazyText) | ||
import Data.Bifunctor (bimap) | ||
import Data.ByteString.Char8 qualified as BS | ||
import Data.Coerce (coerce) | ||
|
@@ -62,7 +60,6 @@ import Data.Set qualified as Set | |
import Data.Text (Text, pack) | ||
import Data.Text qualified as Text | ||
import Data.Text.Encoding qualified as Text | ||
import Data.Text.Lazy qualified as Text (toStrict) | ||
import GHC.TypeLits (KnownSymbol) | ||
import Prettyprinter | ||
|
||
|
@@ -82,7 +79,6 @@ import Booster.Prettyprinter (renderDefault, renderOneLineText) | |
import Booster.SMT.Interface qualified as SMT | ||
import Booster.Syntax.Json.Externalise (externaliseTerm) | ||
import Booster.Util (Bound (..)) | ||
import Kore.JsonRpc.Types.Log qualified as KoreRpcLog | ||
import Kore.Util (showHashHex) | ||
|
||
newtype EquationT io a | ||
|
@@ -254,52 +250,6 @@ isMatchFailure _ = False | |
isSuccess EquationApplied{} = True | ||
isSuccess _ = False | ||
|
||
{- | Attempt to get an equation's unique id, falling back to it's label or eventually to UNKNOWN. | ||
The fallbacks are useful in case of cached equation applications or the ones done via LLVM, | ||
as neither of these categories have unique IDs. | ||
-} | ||
equationRuleIdWithFallbacks :: EquationMetadata -> Text | ||
equationRuleIdWithFallbacks metadata = | ||
fromMaybe "UNKNOWN" (fmap getUniqueId metadata.ruleId <|> metadata.label) | ||
|
||
equationTraceToLogEntry :: EquationTrace Term -> KoreRpcLog.LogEntry | ||
equationTraceToLogEntry = \case | ||
EquationApplied _subjectTerm metadata _rewritten -> | ||
KoreRpcLog.Simplification | ||
{ originalTerm | ||
, originalTermIndex | ||
, origin | ||
, result = | ||
KoreRpcLog.Success Nothing Nothing _ruleId | ||
} | ||
where | ||
originalTerm = Nothing | ||
originalTermIndex = Nothing | ||
origin = KoreRpcLog.Booster | ||
_ruleId = equationRuleIdWithFallbacks metadata | ||
EquationNotApplied _subjectTerm metadata failure -> | ||
KoreRpcLog.Simplification | ||
{ originalTerm | ||
, originalTermIndex | ||
, origin | ||
, result = KoreRpcLog.Failure (failureDescription failure) (Just _ruleId) | ||
} | ||
where | ||
originalTerm = Nothing | ||
originalTermIndex = Nothing | ||
origin = KoreRpcLog.Booster | ||
_ruleId = equationRuleIdWithFallbacks metadata | ||
|
||
failureDescription :: ApplyEquationFailure -> Text.Text | ||
failureDescription = \case | ||
FailedMatch{} -> "Failed match" | ||
IndeterminateMatch -> "IndeterminateMatch" | ||
IndeterminateCondition{} -> "IndeterminateCondition" | ||
ConditionFalse{} -> "ConditionFalse" | ||
EnsuresFalse{} -> "EnsuresFalse" | ||
RuleNotPreservingDefinedness -> "RuleNotPreservingDefinedness" | ||
MatchConstraintViolated{} -> "MatchConstraintViolated" | ||
|
||
startState :: SimplifierCache -> EquationState | ||
startState cache = | ||
EquationState | ||
|
@@ -426,9 +376,7 @@ iterateEquations :: | |
Term -> | ||
EquationT io Term | ||
iterateEquations direction preference startTerm = do | ||
result <- pushRecursion startTerm >>= checkCounter >> go startTerm <* popRecursion | ||
when (startTerm /= result) $ withContext "success" $ withTermContext result $ pure () | ||
pure result | ||
pushRecursion startTerm >>= checkCounter >> go startTerm <* popRecursion | ||
where | ||
checkCounter counter = do | ||
config <- getConfig | ||
|
@@ -832,13 +780,15 @@ applyEquations theory handler term = do | |
processEquations [] = | ||
pure term -- nothing to do, term stays the same | ||
processEquations (eq : rest) = do | ||
res <- applyEquation term eq | ||
res <- withRuleContext eq $ applyEquation term eq | ||
emitEquationTrace term eq.attributes.location eq.attributes.ruleLabel eq.attributes.uniqueId res | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Now that There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I was going to leave that for another pr, because we actually still log via the old logger interface within this function. Until we migrate our tools to contextual logging these may still be necessary? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Sounds good, let's keep it for now. |
||
handler | ||
(\t -> setChanged >> pure t) | ||
( \t -> setChanged >> (withContext (LogContext eq) $ withContext "success" $ withTermContext t $ pure t) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I like this change. I think it fixes a bug in logging that I've found but haven't got to report yet. |
||
) | ||
(processEquations rest) | ||
( withContext "abort" $ | ||
logMessage ("Aborting simplification/function evaluation" :: Text) >> pure term | ||
( withContext (LogContext eq) $ | ||
withContext "abort" $ | ||
logMessage ("Aborting simplification/function evaluation" :: Text) >> pure term | ||
) | ||
res | ||
|
||
|
@@ -861,9 +811,6 @@ emitEquationTrace t loc lbl uid res = do | |
Failure failure -> EquationNotApplied t (EquationMetadata loc lbl uid) failure | ||
prettyItem = pack . renderDefault . pretty $ newTraceItem | ||
logOther (LevelOther "Simplify") prettyItem | ||
logOther | ||
(LevelOther "SimplifyJson") | ||
(Text.toStrict . encodeToLazyText $ equationTraceToLogEntry newTraceItem) | ||
case res of | ||
Success{} -> logOther (LevelOther "SimplifySuccess") prettyItem | ||
_ -> pure () | ||
|
@@ -875,7 +822,7 @@ applyEquation :: | |
Term -> | ||
RewriteRule tag -> | ||
EquationT io ApplyEquationResult | ||
applyEquation term rule = withRuleContext rule $ fmap (either Failure Success) $ runExceptT $ do | ||
applyEquation term rule = fmap (either Failure Success) $ runExceptT $ do | ||
-- ensured by internalisation: no existentials in equations | ||
unless (null rule.existentials) $ do | ||
withContext "abort" $ | ||
|
This file was deleted.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
😎 🆒