Skip to content
This repository was archived by the owner on Aug 18, 2020. It is now read-only.

Commit f15d462

Browse files
CodiePPerikd
authored andcommitted
[CBR-211] log rotation checks for size and age of files
Signed-off-by: Alexander Diemand <[email protected]>
1 parent ecbbdcf commit f15d462

File tree

7 files changed

+299
-69
lines changed

7 files changed

+299
-69
lines changed

pkgs/default.nix

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17323,6 +17323,7 @@ license = stdenv.lib.licenses.mit;
1732317323
mkDerivation
1732417324
, aeson
1732517325
, async
17326+
, auto-update
1732617327
, base
1732717328
, bytestring
1732817329
, canonical-json
@@ -17385,6 +17386,7 @@ configureFlags = [
1738517386
];
1738617387
libraryHaskellDepends = [
1738717388
aeson
17389+
auto-update
1738817390
base
1738917391
canonical-json
1739017392
cborg

util/cardano-sl-util.cabal

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,8 +56,10 @@ library
5656
other-modules:
5757
Pos.Util.CompileInfoGit
5858
Pos.Util.Log.Scribes
59+
Pos.Util.Log.Rotator
5960

6061
build-depends: aeson
62+
, auto-update
6163
, base
6264
, canonical-json
6365
, cborg

util/src/Pos/Util/Log.hs

Lines changed: 22 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -3,15 +3,15 @@
33
module Pos.Util.Log
44
(
55
-- * Logging
6-
Severity(..)
6+
Severity (..)
77
, LogContext
88
, LogContextT
99
, LoggingHandler
1010
-- * Compatibility
11-
, CanLog(..)
11+
, CanLog (..)
1212
, WithLogger
1313
-- * Configuration
14-
, LoggerConfig(..)
14+
, LoggerConfig (..)
1515
, parseLoggerConfig
1616
, retrieveLogFiles
1717
-- * Startup
@@ -37,7 +37,6 @@ import Universum
3737

3838
import Control.Lens (each)
3939

40-
4140
import qualified Data.Text as T
4241
import Data.Text.Lazy.Builder
4342

@@ -116,28 +115,39 @@ setupLogging lc = do
116115
liftIO $ Internal.registerBackends lh scribes
117116
return lh
118117
where
118+
-- returns a list of: (name, Scribe, finalizer)
119119
meta :: LoggingHandler -> LoggerConfig -> IO [(T.Text, K.Scribe)]
120120
meta _lh _lc = do
121121
-- setup scribes according to configuration
122122
let lhs = _lc ^. lcLoggerTree ^. ltHandlers ^.. each
123123
basepath = _lc ^. lcBasePath
124+
-- default rotation parameters: max. 24 hours, max. 10 files kept, max. size 5 MB
125+
rotation = fromMaybe (RotationParameters {_rpMaxAgeHours=24,_rpKeepFilesNum=10,_rpLogLimitBytes=5*1000*1000})
126+
(_lc ^. lcRotation)
124127
forM lhs (\lh -> case (lh ^. lhBackend) of
125128
FileJsonBE -> do
126-
putStrLn ("creating JSON backend ..." :: Text)
129+
let bp = fromMaybe "." basepath
130+
fp = fromMaybe "node.json" $ lh ^. lhFpath
131+
fdesc = Internal.mkFileDescription bp fp
132+
nm = lh ^. lhName
127133
scribe <- mkJsonFileScribe
128-
(fromMaybe "." basepath)
129-
(fromMaybe "<unk>" $ lh ^. lhFpath)
134+
rotation
135+
fdesc
130136
(Internal.sev2klog $ fromMaybe Debug $ lh ^. lhMinSeverity)
131137
K.V0
132-
return (lh ^. lhName, scribe)
138+
return (nm, scribe)
133139
FileTextBE -> do
134-
scribe <- mkFileScribe
135-
(fromMaybe "." basepath)
136-
(fromMaybe "<unk>" $ lh ^. lhFpath)
140+
let bp = fromMaybe "." basepath
141+
fp = (fromMaybe "node.log" $ lh ^. lhFpath)
142+
fdesc = Internal.mkFileDescription bp fp
143+
nm = lh ^. lhName
144+
scribe <- mkTextFileScribe
145+
rotation
146+
fdesc
137147
True
138148
(Internal.sev2klog $ fromMaybe Debug $ lh ^. lhMinSeverity)
139149
K.V0
140-
return (lh ^. lhName, scribe)
150+
return (nm, scribe)
141151
StdoutBE -> do
142152
scribe <- mkStdoutScribe
143153
(Internal.sev2klog $ fromMaybe Debug $ lh ^. lhMinSeverity)
@@ -155,7 +165,6 @@ setupLogging lc = do
155165
return (lh ^. lhName, scribe)
156166
)
157167

158-
159168
{-| provide logging in IO
160169
161170
* example

util/src/Pos/Util/Log/Internal.hs

Lines changed: 35 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
{-# LANGUAGE RecordWildCards #-}
2+
23
-- | internal definitions for "Pos.Util.Log"
4+
35
module Pos.Util.Log.Internal
46
( newConfig
57
, registerBackends
@@ -13,15 +15,21 @@ module Pos.Util.Log.Internal
1315
, incrementLinesLogged
1416
, modifyLinesLogged
1517
, LoggingHandler -- only export name
18+
, FileDescription (..)
19+
, mkFileDescription
1620
) where
1721

22+
import Control.AutoUpdate (UpdateSettings (..), defaultUpdateSettings,
23+
mkAutoUpdate)
1824
import Control.Concurrent.MVar (modifyMVar_, newMVar, withMVar)
1925

2026
import qualified Data.Text as T
2127
import Data.Time (UTCTime, getCurrentTime)
28+
import System.FilePath (splitFileName, (</>))
2229
import Universum hiding (newMVar)
2330

2431
import qualified Katip as K
32+
import qualified Katip.Core as KC
2533

2634
import Pos.Util.Log.LoggerConfig (LoggerConfig (..))
2735
import Pos.Util.Log.Severity
@@ -42,6 +50,20 @@ s2kname s = K.Namespace [s]
4250
s2knames :: [Text] -> K.Namespace
4351
s2knames s = K.Namespace s
4452

53+
-- | log files have a prefix and a name
54+
data FileDescription = FileDescription {
55+
prefixpath :: FilePath,
56+
filename :: FilePath }
57+
deriving (Show)
58+
59+
mkFileDescription :: FilePath -> FilePath -> FileDescription
60+
mkFileDescription bp fp =
61+
-- if fp contains a filename in a directory path
62+
-- move this path to the prefix and only keep the name
63+
let (extbp, fname) = splitFileName fp
64+
in
65+
FileDescription { prefixpath = bp </> extbp
66+
, filename = fname }
4567

4668
-- | Our internal state
4769
data LoggingHandlerInternal = LoggingHandlerInternal
@@ -89,13 +111,23 @@ registerBackends :: LoggingHandler -> [(T.Text, K.Scribe)] -> IO ()
89111
registerBackends lh scribes = do
90112
LoggingHandlerInternal cfg _ counter <- takeMVar (getLSI lh)
91113
le0 <- K.initLogEnv (s2kname "cardano-sl") "production"
92-
let le1 = updateEnv le0 getCurrentTime
114+
-- use 'getCurrentTime' to get a more precise timestamp
115+
-- as katip uses per default some internal buffered time variable
116+
timer <- mkAutoUpdate defaultUpdateSettings { updateAction = getCurrentTime, updateFreq = 10000 }
117+
let le1 = updateEnv le0 timer
93118
le <- register scribes le1
94119
putMVar (getLSI lh) $ LoggingHandlerInternal cfg (Just le) counter
95120
where
96121
register :: [(T.Text, K.Scribe)] -> K.LogEnv -> IO K.LogEnv
97122
register [] le = return le
98123
register ((n, s):scs) le =
99-
register scs =<< K.registerScribe n s K.defaultScribeSettings le
124+
register scs =<< K.registerScribe n s scribeSettings le
100125
updateEnv :: K.LogEnv -> IO UTCTime -> K.LogEnv
101-
updateEnv le f = le { K._logEnvTimer = f }
126+
-- request a new time 'getCurrentTime' at most 100 times a second
127+
updateEnv le timer =
128+
le { K._logEnvTimer = timer, K._logEnvHost = "hostname" }
129+
130+
scribeSettings :: KC.ScribeSettings
131+
scribeSettings = KC.ScribeSettings bufferSize
132+
where
133+
bufferSize = 5000 -- size of the queue (in log items)

util/src/Pos/Util/Log/LoggerConfig.hs

Lines changed: 12 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -20,8 +20,9 @@ module Pos.Util.Log.LoggerConfig
2020
, lcBasePath
2121
, ltHandlers
2222
, ltMinSeverity
23-
, rpKeepFiles
24-
, rpLogLimit
23+
, rpKeepFilesNum
24+
, rpLogLimitBytes
25+
, rpMaxAgeHours
2526
, lhBackend
2627
, lhName
2728
, lhFpath
@@ -58,15 +59,17 @@ deriving instance FromJSON BackendKind
5859
-- | @'RotationParameters'@ one of the two categories used in the
5960
-- logging config, specifying the log rotation parameters
6061
data RotationParameters = RotationParameters
61-
{ _rpLogLimit :: !Word64 -- ^ max size of file in bytes
62-
, _rpKeepFiles :: !Word -- ^ number of files to keep
62+
{ _rpLogLimitBytes :: !Word64 -- ^ max size of file in bytes
63+
, _rpMaxAgeHours :: !Word -- ^ hours
64+
, _rpKeepFilesNum :: !Word -- ^ number of files to keep
6365
} deriving (Generic, Show, Eq)
6466

6567
instance ToJSON RotationParameters
6668
instance FromJSON RotationParameters where
6769
parseJSON = withObject "rotation params" $ \o -> do
68-
_rpLogLimit <- o .: "logLimit"
69-
_rpKeepFiles <- o .: "keepFiles"
70+
_rpLogLimitBytes <- o .: "logLimit"
71+
_rpMaxAgeHours <- o .:? "maxAge" .!= 24
72+
_rpKeepFilesNum <- o .: "keepFiles"
7073
return RotationParameters{..}
7174

7275
makeLenses ''RotationParameters
@@ -193,8 +196,9 @@ instance Semigroup LoggerConfig where
193196
}
194197
instance Monoid LoggerConfig where
195198
mempty = LoggerConfig { _lcRotation = Just RotationParameters {
196-
_rpLogLimit = 10 * 1024 * 1024,
197-
_rpKeepFiles = 10 }
199+
_rpLogLimitBytes = 5 * 1024 * 1024,
200+
_rpKeepFilesNum = 10,
201+
_rpMaxAgeHours = 24 }
198202
, _lcLoggerTree = mempty
199203
, _lcBasePath = Nothing
200204
}

util/src/Pos/Util/Log/Rotator.hs

Lines changed: 146 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,146 @@
1+
{-# LANGUAGE RecordWildCards #-}
2+
3+
-- | monitor log files for max age and max size
4+
5+
module Pos.Util.Log.Rotator
6+
( cleanupRotator
7+
, evalRotator
8+
, initializeRotator
9+
) where
10+
11+
import Universum
12+
13+
import Control.Exception.Safe (Exception (..), catchIO)
14+
15+
import qualified Data.List.NonEmpty as NE
16+
import Data.Time (UTCTime, addUTCTime, diffUTCTime, getCurrentTime,
17+
parseTimeM)
18+
import Data.Time.Format (defaultTimeLocale, formatTime)
19+
20+
import Pos.Util.Log.Internal (FileDescription (..))
21+
import Pos.Util.Log.LoggerConfig
22+
23+
import System.Directory (listDirectory, removeFile)
24+
import System.FilePath ((</>))
25+
import System.IO (BufferMode (LineBuffering), Handle,
26+
IOMode (WriteMode), hFileSize, hSetBuffering, stdout)
27+
28+
29+
-- | format of a timestamp
30+
tsformat :: String
31+
tsformat = "%Y%m%d%H%M%S"
32+
33+
-- | get file path to a log file with current time
34+
nameLogFile :: FileDescription -> IO FilePath
35+
nameLogFile FileDescription{..} = do
36+
now <- getCurrentTime
37+
let tsnow = formatTime defaultTimeLocale tsformat now
38+
return $ prefixpath </> filename ++ "-" ++ tsnow
39+
40+
-- | open a new log file
41+
evalRotator :: RotationParameters -> FileDescription -> IO (Handle, Integer, UTCTime)
42+
evalRotator rotation fdesc = do
43+
let maxAge = toInteger $ rotation ^. rpMaxAgeHours
44+
maxSize = toInteger $ rotation ^. rpLogLimitBytes
45+
46+
-- open new log file
47+
fpath <- nameLogFile fdesc
48+
hdl <- catchIO (openFile fpath WriteMode) $
49+
\e -> do
50+
prtoutException fpath e
51+
return stdout -- fallback to standard output in case of exception
52+
hSetBuffering hdl LineBuffering
53+
54+
-- compute next rotation time
55+
now <- getCurrentTime
56+
let rottime = addUTCTime (fromInteger $ maxAge * 3600) now
57+
58+
return (hdl, maxSize, rottime)
59+
60+
prtoutException :: Exception e => FilePath -> e -> IO ()
61+
prtoutException fp e = do
62+
putStrLn $ "error while opening log @ " ++ fp
63+
putStrLn $ "exception: " ++ displayException e
64+
65+
-- | list filenames in prefix dir which match 'filename'
66+
listLogFiles :: FileDescription -> IO (Maybe (NonEmpty FilePath))
67+
listLogFiles FileDescription{..} = do
68+
-- find files in bp which begin with fp
69+
files <- listDirectory $ prefixpath
70+
return $ nonEmpty $ sort $ filter fpredicate files
71+
where
72+
tslen = 14 -- length of a timestamp
73+
fplen = length filename
74+
fpredicate path = take fplen path == filename
75+
&& take 1 (drop fplen path) == "-"
76+
&& length (drop (fplen + 1) path) == tslen
77+
78+
-- | latest log file in prefix dir which matches 'filename'
79+
latestLogFile :: FileDescription -> IO (Maybe FilePath)
80+
latestLogFile fdesc =
81+
listLogFiles fdesc >>= \fs -> return $ latestLogFile' fs
82+
where
83+
latestLogFile' :: Maybe (NonEmpty FilePath) -> Maybe FilePath
84+
latestLogFile' Nothing = Nothing
85+
latestLogFile' (Just flist) = Just $ last flist
86+
87+
-- | initialize log file at startup
88+
-- may append to existing file
89+
initializeRotator :: RotationParameters -> FileDescription -> IO (Handle, Integer, UTCTime)
90+
initializeRotator rotation fdesc = do
91+
let maxAge = toInteger $ rotation ^. rpMaxAgeHours
92+
maxSize = toInteger $ rotation ^. rpLogLimitBytes
93+
94+
latest <- latestLogFile fdesc
95+
case latest of
96+
Nothing -> -- no file to append, return new
97+
evalRotator rotation fdesc
98+
Just fname -> do
99+
-- check date
100+
now <- getCurrentTime
101+
tsfp <- parseTimeM True defaultTimeLocale tsformat $ drop (fplen + 1) fname
102+
if (round $ diffUTCTime now tsfp) > (3600 * maxAge)
103+
then do -- file is too old, return new
104+
evalRotator rotation fdesc
105+
else do
106+
hdl <- catchIO (openFile (prefixpath fdesc </> fname) AppendMode) $
107+
\e -> do
108+
prtoutException fname e
109+
return stdout -- fallback to standard output in case of exception
110+
hSetBuffering hdl LineBuffering
111+
cursize <- hFileSize hdl
112+
let rottime = addUTCTime (fromInteger $ maxAge * 3600) now
113+
return (hdl, (maxSize - cursize), rottime)
114+
where
115+
fplen = length $ filename fdesc
116+
117+
-- | remove old files; count them and only keep n (from config)
118+
cleanupRotator :: RotationParameters -> FileDescription -> IO ()
119+
cleanupRotator rotation fdesc = do
120+
let keepN0 = fromIntegral (rotation ^. rpKeepFilesNum) :: Int
121+
keepN = max 1 $ min keepN0 99
122+
listLogFiles fdesc >>= removeOldFiles keepN
123+
where
124+
removeOldFiles :: Int -> Maybe (NonEmpty FilePath) -> IO ()
125+
removeOldFiles _ Nothing = return ()
126+
removeOldFiles n (Just flist) = do
127+
putStrLn $ "dropping " ++ (show n) ++ " from " ++ (show flist)
128+
removeFiles $ reverse $ NE.drop n $ NE.reverse flist
129+
removeFiles [] = return ()
130+
removeFiles (fp : fps) = do
131+
let bp = prefixpath fdesc
132+
filepath = bp </> fp
133+
putStrLn $ "removing file " ++ filepath
134+
removeFile filepath -- destructive
135+
removeFiles fps
136+
137+
{-
138+
139+
testing:
140+
141+
lc0 <- parseLoggerConfig "../log-configs/testing.yaml"
142+
lc <- setLogPrefix (Just "/tmp/testlog/") lc0
143+
lh <- setupLogging lc
144+
145+
usingLoggerName lh "testing" $ do { forM_ [1..299] (\n -> logDebug $ T.pack $ "hello world " ++ (show n)) }
146+
-}

0 commit comments

Comments
 (0)