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.

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

Log immediately to file #176

Closed
mb720 opened this issue Jan 26, 2020 · 2 comments · Fixed by #194
Closed

Log immediately to file #176

mb720 opened this issue Jan 26, 2020 · 2 comments · Fixed by #194
Labels
enhancement New feature or request log-action Everything related to LogAction data type package:co-log For: co-log package:co-log-core For: co-log-core

Comments

@mb720
Copy link
Contributor

mb720 commented Jan 26, 2020

Hi!

Based on the tutorial code here and here, I'm attempting to log to a file in my app.

I'm currently facing the issue that I can't get co-log to log to the file while the program is running. The log message ends up in the file only after the program is finished.

Here's my code:

{-# LANGUAGE FlexibleContexts           #-}
{-# LANGUAGE OverloadedStrings          #-}
{-# LANGUAGE PatternSynonyms            #-}
{-# LANGUAGE ScopedTypeVariables        #-}
{-# LANGUAGE DerivingStrategies         #-}
{-# LANGUAGE GeneralizedNewtypeDeriving #-}
{-# LANGUAGE InstanceSigs               #-}
{-# LANGUAGE MultiParamTypeClasses      #-}
{-# LANGUAGE FlexibleInstances          #-}

module Main where

import           Prelude                 hiding ( log )

import           Colog                          ( pattern I
                                                , Message
                                                , LogAction
                                                , withLogTextFile
                                                , WithLog
                                                , HasLog(..)
                                                , cmapM
                                                , upgradeMessageAction
                                                , log
                                                , fmtRichMessageDefault
                                                , defaultFieldMap
                                                , logTextStdout
                                                )

import           Control.Concurrent             ( threadDelay )

import           Control.Monad.IO.Class         ( MonadIO(..) )
import           Control.Monad.Reader           ( MonadReader
                                                , ReaderT(..)
                                                )

data Env m = Env
    { httpsPort :: !Int
    , httpPort :: !Int
    , logAction  :: !(LogAction m Message)
    }

instance HasLog (Env m) Message m where
  getLogAction :: Env m -> LogAction m Message
  getLogAction = logAction
  {-# INLINE getLogAction #-}

  setLogAction :: LogAction m Message -> Env m -> Env m
  setLogAction newLogAction env = env { logAction = newLogAction }
  {-# INLINE setLogAction #-}

runApp :: Env App -> App a -> IO a
runApp env app = runReaderT (unApp app) env

main = withLogTextFile "myApp.log" $ \textFileLogAction ->
  let myLogAction = modifyLogAction textFileLogAction
  in  runApp (simpleEnv myLogAction) simpleApp
where
  simpleApp = do
    log I "The log message"
    liftIO $ threadDelay (5 * 10 ^ 6)

simpleEnv :: LogAction App Message -> Env App
simpleEnv appLogging =
  Env { httpsPort = 8443, httpPort = 8080, logAction = appLogging }

modifyLogAction logAction =
  let combinedLogAction = logTextStdout <> logAction
      messageAction     = cmapM fmtRichMessageDefault combinedLogAction
  in  upgradeMessageAction defaultFieldMap messageAction

newtype App a = App {
      unApp :: ReaderT (Env App) IO a
    } deriving (Functor, Applicative, Monad, MonadIO, MonadReader (Env App))

The log message is printed to standard out right away but only shows up in the log file at the end of the program (after the five seconds delay).

As you might have guessed from the Env, I'd like to use co-log for a web server where it's important to have logs during the web server's execution.

I was wondering if there's some way to configure the log action to log to the file immediately.

Thanks a lot! :-)


My Stack resolver is lts-14.16.

@chshersh chshersh added enhancement New feature or request package:co-log For: co-log package:co-log-core For: co-log-core log-action Everything related to LogAction data type labels Jan 27, 2020
@chshersh
Copy link
Contributor

@mb720 Thanks for opening the issue! I see how this can be inconvenient. I believe one of the solutions to this problem is to use hFlush after logging something. This sounds like a good thing to do by default, so we'll make sure this change will be included in the next co-log release. But for now, what you can do is to copy the following implementation of withLogTextFile and use it instead of the library version:

withLogTextFile :: forall m r . MonadIO m => FilePath -> (LogAction m T.Text -> IO r) -> IO r
withLogTextFile path action = withFile path AppendMode $ action . logTextFlushHandle
  where
    logTextFlushHandle :: Handle -> LogAction m T.Text
    logTextFlushHandle handle = LogAction $ \msg -> liftIO $ do
        TIO.hPutStrLn handle msg
        hFlush handle

@mb720
Copy link
Contributor Author

mb720 commented Jan 27, 2020

Thanks a lot, this worked like a charm after adding these imports:

import qualified Data.Text                     as T
import qualified Data.Text.IO                  as TIO
import           System.IO

Yes, I agree that making this the default is a good idea!

chshersh pushed a commit that referenced this issue Jul 8, 2020
* [#176] Add an action to flush a handle

Problem: during logging one often wants data to reach destination
immediately, but logging actions provided out of the box do not
flush handles they log to.

Solution: we add a new action to `co-log-core`. This action does
not _write_ anything, but flushes the handler. We call it
`logFlush` for consistency with other `log*` actions.
It can be used as `logPrintStderr <> logFlush stderr`.

* fixup! [#191] Export showTime (#192)

* [#176] Automatically flush file handles

Problem: if we use builtin logging actions that log to files,
you will often notice that your messages appear in files with delay
due to buffering. File handles are usually block-buffered and do not
flush on newlines.
We find that behavior confusing to end users and think that it's
better to flush file handles on each log action by default.
Note that the same problem may occur with other handles (e. g. stderr)
as well, but it's less likely because they normally have line
buffering (but it's not guaranteed and is not always the case).

Solution: first of all we checked performance overhead of additional
`hFlush` call. For vanilla `putStrLn` it varies from "more than 4x"
for short messages to negligible for long messages. On average we
roughly assess it as 2x (that really depends on your use case).
Based on that we make the following trade-off:
1. Actions that write to files now also automatically flush output
buffers using `logFlush`. That's more expensive, but without flushing
behavior is quite confusing for the library users.
2. Actions that write to an arbitrary `Handle` or standard handles
do not flush by default to avoid overhead. Usually flushing will
happen automatically because of line bufferring.

* [#176] Clarify lack of flushing in default actions

* fixup! [#176] Automatically flush file handles
@chshersh chshersh added this to the v0.5.0.0: Structured logging milestone Aug 21, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request log-action Everything related to LogAction data type package:co-log For: co-log package:co-log-core For: co-log-core
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants