-
Notifications
You must be signed in to change notification settings - Fork 14
/
TraceForwarder.lhs
341 lines (299 loc) · 13 KB
/
TraceForwarder.lhs
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
\subsection{Cardano.BM.Backend.TraceForwarder}
\label{module:Cardano.BM.Backend.TraceForwarder}
%if style == newcode
\begin{code}
{-# LANGUAGE CPP #-}
{-# LANGUAGE FlexibleInstances #-}
{-# LANGUAGE LambdaCase #-}
{-# LANGUAGE MultiParamTypeClasses #-}
{-# LANGUAGE ScopedTypeVariables #-}
{-# LANGUAGE TypeFamilies #-}
#if !defined(mingw32_HOST_OS)
#define POSIX
#endif
module Cardano.BM.Backend.TraceForwarder
( TraceForwarder (..)
-- * Plugin
, plugin
) where
import Control.Exception
import Control.Monad (forever, when)
import Control.Concurrent (threadDelay)
import qualified Control.Concurrent.Async as Async
import Control.Concurrent.MVar (MVar, modifyMVar_, newMVar, readMVar)
import Control.Concurrent.STM (atomically)
import qualified Control.Concurrent.STM.TBQueue as TBQ
import Data.Aeson (FromJSON, ToJSON, encode)
import qualified Data.ByteString as BS
import qualified Data.ByteString.Char8 as BSC
import qualified Data.ByteString.Lazy as BL
import Data.IORef (IORef, atomicModifyIORef', newIORef, readIORef)
import Data.Maybe (fromMaybe)
import Data.Text (Text, pack, unpack)
import Data.Text.Encoding (encodeUtf8)
import qualified Data.Text.IO as TIO
import Data.Typeable (Typeable)
import GHC.Natural (Natural)
import qualified Network.Socket as Socket
import System.IO (Handle, IOMode (..), hClose, stderr)
import Text.Read (readMaybe)
import Cardano.BM.Configuration
import Cardano.BM.Data.Backend
import Cardano.BM.Data.Configuration (RemoteAddr(..))
import Cardano.BM.Data.LogItem (LOContent (..), LOMeta (..), LogObject (..))
import Cardano.BM.Data.Severity (Severity (..))
import Cardano.BM.IOManager
import Cardano.BM.Plugin
import qualified Cardano.BM.Snocket as Snocket
import qualified Cardano.BM.Trace as Trace
\end{code}
%endif
|TraceForwarder| is a backend responsible for redirecting logs to a
different process (running a |TraceAcceptor| backend), by means of
either a pipe or a socket.
The |TraceForwarder| is looking up a minimum |Severity| in the options
section of the configuration. This filters out all messages that have not at
least the |Severity|.
The callback 'getStateDigest' is used as a source of |LogObject|s
that should be sent additionally, only once after the connection is
re\-established. The application that uses 'lobemo-backend-trace-forwarder'
plugin provides this callback.
\subsubsection{Plugin definition}
\begin{code}
plugin :: forall a s . (IsEffectuator s a, ToJSON a, FromJSON a)
=> Configuration
-> Trace.Trace IO a
-> s a
-> Text
-> IO [LogObject a]
-> IO (Plugin a)
plugin config _trace _sb tfid getStateDigest = do
opts <- getTextOption config tfid
let minsev = case opts of
Nothing -> Debug
Just sevtext -> fromMaybe Debug (readMaybe $ unpack sevtext)
be :: Cardano.BM.Backend.TraceForwarder.TraceForwarder a <- realize config
dispatcherThr <- spawnDispatcher config (getTF be)
modifyMVar_ (getTF be) $ \initialBE ->
return $ initialBE
{ tfFilter = minsev
, tfDispatcher = Just dispatcherThr
, tfGetStateDigest = getStateDigest
}
return $ BackendPlugin
(MkBackend { bEffectuate = effectuate be, bUnrealize = unrealize be })
(bekind be)
\end{code}
\subsubsection{Structure of TraceForwarder}\label{code:TraceForwarder}\index{TraceForwarder}
Contains the handler to the pipe or to the socket.
\begin{code}
newtype TraceForwarder a = TraceForwarder
{ getTF :: TraceForwarderMVar a }
type TraceForwarderMVar a = MVar (TraceForwarderInternal a)
data TraceForwarderInternal a = TraceForwarderInternal
{ tfQueue :: TBQ.TBQueue (LogObject a)
, tfHandle :: Maybe Handle
, tfRemoteAddr :: RemoteAddr
, tfFilter :: Severity
, tfDispatcher :: Maybe (Async.Async ())
, tfQueueFullCounter :: IORef Int
, tfGetStateDigest :: IO [LogObject a]
}
\end{code}
\subsubsection{TraceForwarder is an effectuator}\index{TraceForwarder!instance of IsEffectuator}
Every |LogObject| before being written to the given handler is converted to
|ByteString| through its |JSON| representation.
\begin{code}
instance (ToJSON a) => IsEffectuator TraceForwarder a where
effectuate tf lo = do
let currentMVar = getTF tf
currentTF <- readMVar currentMVar
-- Severity filter allows to ignore LogObjects with too low severity.
-- However, errors and metrics should be forwarded in any case,
-- regardless their severity.
if isError
then writeMessageToQueue currentTF
else case loContent lo of
LogValue _ _ -> writeMessageToQueue currentTF
_ -> when (severity (loMeta lo) >= tfFilter currentTF) $
writeMessageToQueue currentTF
where
isError = errByConstr || errBySev
where
errByConstr =
case loContent lo of
LogError _ -> True
_ -> False
errBySev = severity (loMeta lo) >= Error
writeMessageToQueue currentTF' = do
let queue = tfQueue currentTF'
noCapacity <- atomically $ TBQ.isFullTBQueue queue
if noCapacity
then do
let counterIORef = tfQueueFullCounter currentTF'
overflowed <- atomicModifyIORef' counterIORef $ \counter ->
if counter >= overflowCriticalNum
then (1, True)
else (counter + 1, False)
when overflowed $ handleOverflow tf
else atomically $ TBQ.writeTBQueue queue lo
handleOverflow _ = TIO.hPutStrLn stderr $ "Notice: TraceForwarder's queue is full, "
<> pack (show overflowCriticalNum)
<> " log items were dropped!"
overflowCriticalNum :: Int
overflowCriticalNum = 200
\end{code}
\subsubsection{|TraceForwarder| implements |Backend| functions}\index{TraceForwarder!instance of IsBackend}
|TraceForwarder| is an |IsBackend|
\begin{code}
instance (FromJSON a, ToJSON a) => IsBackend TraceForwarder a where
type BackendFailure TraceForwarder = TraceForwarderBackendFailure
bekind _ = TraceForwarderBK
realize cfg = getForwardTo cfg >>= \case
Nothing -> fail "Trace forwarder not configured: option 'forwardTo'"
Just addr -> do
queue <- atomically $ TBQ.newTBQueue queueMaxSize
counter <- newIORef 0
tfMVar <- newMVar $ TraceForwarderInternal
{ tfQueue = queue
, tfHandle = Nothing
, tfRemoteAddr = addr
, tfFilter = Debug
, tfDispatcher = Nothing
, tfQueueFullCounter = counter
, tfGetStateDigest = return []
}
return $ TraceForwarder tfMVar
unrealize tf = do
currentTF <- readMVar (getTF tf)
-- Cancel dispatcher thread.
case tfDispatcher currentTF of
Nothing -> return ()
Just thr -> Async.uninterruptibleCancel thr
-- If there's a handle - close it.
closeHandle $ tfHandle currentTF
closeHandle :: Maybe Handle -> IO ()
closeHandle (Just h) = hClose h
closeHandle Nothing = return ()
connectForwarder :: IOManager -> RemoteAddr -> IO Handle
connectForwarder iomgr (RemotePipe pipePath) = do
let sn = Snocket.localSnocket iomgr pipePath
Snocket.localFDToHandle =<< doConnect sn (Snocket.localAddressFromPath pipePath)
connectForwarder iomgr (RemoteSocket host port) = do
let sn = Snocket.socketSnocket iomgr
addrs <- Socket.getAddrInfo Nothing (Just host) (Just port)
case addrs of
[] -> throwIO (TraceForwarderSocketError ("bad socket address: " <> host <> ":" <> port))
a:_ -> doConnect sn (Socket.addrAddress a)
>>= flip Socket.socketToHandle ReadWriteMode
doConnect :: Snocket.Snocket IO fd addr -> addr -> IO fd
doConnect sn remoteAddr = do
sd <- Snocket.openToConnect sn remoteAddr
Snocket.connect sn sd remoteAddr
pure sd
data TraceForwarderBackendFailure
= TraceForwarderConnectionError String
| TraceForwarderSocketError String
deriving (Show, Typeable)
instance Exception TraceForwarderBackendFailure
\end{code}
\subsubsection{Asynchronously reading log items from the queue and sending them to an acceptor.}
\begin{code}
spawnDispatcher :: ToJSON a => Configuration -> TraceForwarderMVar a -> IO (Async.Async ())
spawnDispatcher config tfMVar = do
-- To reduce network traffic it's possible to send log items not one by one,
-- but collect them in the queue and periodically send this list as one ByteString.
forwardDelay <- getForwardDelay config >>= \case
Nothing -> pure defaultDelayInMs
Just delayInMs -> pure delayInMs
Async.async $ processQueue forwardDelay
where
-- If the configuration doesn't specify forward delay, use default one.
defaultDelayInMs :: Word
defaultDelayInMs = 1000
processQueue :: Word -> IO ()
processQueue delayInMs = forever $ do
threadDelay $ fromIntegral delayInMs * 1000
currentTF <- readMVar tfMVar
let getStateDigest = tfGetStateDigest currentTF
itemsList <- atomically $ TBQ.flushTBQueue (tfQueue currentTF)
-- Try to write it to the handle. If there's a problem with connection,
-- this thread will initiate re\-establishing of the connection and
-- will wait until it's established.
sendItems config tfMVar itemsList getStateDigest
-- Try to send log items to the handle.
sendItems :: ToJSON a
=> Configuration
-> TraceForwarderMVar a
-> [LogObject a]
-> IO [LogObject a]
-> IO ()
sendItems _ _ [] _ = return ()
sendItems config tfMVar items@(lo:_) getStateDigest =
tfHandle <$> readMVar tfMVar >>= \case
Nothing -> do
-- There's no handle, initiate the connection.
establishConnection 1 1 tfMVar
-- Connection is re\-established, try to send log item.
-- Since the connection is re\-established, add state digest items as well.
additionalItems <- getStateDigest
let allItems = additionalItems ++ items
sendItems config tfMVar allItems getStateDigest
Just h ->
try (BSC.hPutStrLn h $! encodedHostname) >>= \case
Right _ ->
-- Hostname was written to the handler successfully,
-- try to write serialized list of LogObjects.
try (BSC.hPutStrLn h $! bs) >>= \case
Right _ ->
return () -- Everything is ok, LogObjects were written to the handler.
Left (_e :: IOException) -> do
reConnectIfQueueIsAlmostFull
threadDelay 10000
sendItems config tfMVar items getStateDigest
Left (_e :: IOException) -> do
reConnectIfQueueIsAlmostFull
threadDelay 10000
sendItems config tfMVar items getStateDigest
where
encodedHostname = encodeUtf8 (hostname . loMeta $ lo)
(_, bs) = jsonToBS items
jsonToBS :: ToJSON b => b -> (Int, BS.ByteString)
jsonToBS a =
let bs' = BL.toStrict $ encode a
in (BS.length bs', bs')
-- Handle is bad, it looks like the connection is broken.
-- Check if the queue is almost full.
reConnectIfQueueIsAlmostFull = do
currentTF <- readMVar tfMVar
currentQueueSize <- atomically $ TBQ.lengthTBQueue (tfQueue currentTF)
when (queueIsAlmostFull currentQueueSize) $ do
-- The queue is almost full, it means that log items will be dropped soon.
-- Initiate re-establishing of connection.
closeHandle $ tfHandle currentTF
modifyMVar_ tfMVar $ \be -> return $ be { tfHandle = Nothing }
-- When the queue is almost full (80 percent of its max size)
-- we initiate re-establishing of connection.
queueIsAlmostFull queueSize = queueSize >= round almostFullSize
where
almostFullSize :: Float
almostFullSize = 0.8 * fromIntegral queueMaxSize
queueMaxSize :: Natural
queueMaxSize = 2500
establishConnection :: Int -> Int -> TraceForwarderMVar a -> IO ()
establishConnection delayInSec delayInSec' tfMVar = withIOManager $ \iomgr -> do
addr <- tfRemoteAddr <$> readMVar tfMVar
try (connectForwarder iomgr addr) >>= \case
Right h ->
modifyMVar_ tfMVar $ \be -> return $ be { tfHandle = Just h }
Left (e :: IOException) -> do
-- Cannot establish it, let's try again..
threadDelay $ 1000000 * delayInSec'
if delayInSec' < 60
then
-- Next attempt to re-establish the connection will be perform after Fibonacci-calculated delay.
establishConnection delayInSec' (delayInSec + delayInSec') tfMVar
else
-- Next attempt to re-establish the connection will be perform after fixed delay (1 minute).
establishConnection 1 60 tfMVar
\end{code}