Shelly dies silently when used inside inotify event handler

[rzetterberg]

Brief description

• ghc 7.6.3
• shelly 1.5.4.1
• linux 3.12-1 x86_64

I have written a small application as a exercise to show changes made to audit logs. Basically the program uses inotify to check when /var/log/audit/audit.log changes and runs a handler which uses shelly to run the ausearch tool to extract recent audits from that log.

What happens is that when ausearch is run using run nothing happens and all commands after are not executed.

I have tried:

• Running shelly as verbose
• Echo result from the run function
• Echo stderr from the lastStderr function

Whatever I do, nothing happens after the ausearch command is executed.

I have included what output I'm expecting, the output I'm getting inside the inotify handler and the output I'm getting inside main loop.

At the bottom of this issue there's an example that reproduce the error complete with cabal file and source.

I'm new to shelly, inotify and systems programming so I have probably made a mistake in how I should use these libraries.

Thanks in advance!

Expected output

This is what I see if I run the command directly in bash:

rzetterberg@mycomputer:~/armorwatcher$ sudo ausearch --start recent -r
type=USER_START msg=audit(XXX): pid=X uid=X auid=X ses=X  msg='op=PAM:session_open acct="X" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/X res=success'

.... All the other audits .....

I'm using sudo because the audit log has these permissions:

rzetterberg@mycomputer:~$ sudo ls -la /var/log/audit/audit.log
-rw------- 1 root root 2803865 Jun 15 17:31 /var/log/audit/audit.log

Actual output

This is how I'm executing my haskell program:

rzetterberg@mycomputer:~/armorwatcher$ sudo dist/build/armorwatcher-app/armorwatcher-app

This is what I see when the command is executed via shelly inside the inotify handler:

Audit changed, searching log
ausearch --start recent -r

This is what I see if I run the same shelly snippet in my main loop:

Audit changed, searching log
ausearch --start recent -r
armorwatcher-app: 
Ran commands: 
echo 'Audit changed, searching log'
echo 'ausearch --start recent -r'
ausearch --start recent -r
which ausearch

Exception: error running: ausearch --start recent -r
exit status: 1
stderr: 

Minimal working example

This example was run using GHC 7.6.3 inside a cabal sandbox. Here are Main.hs and cabal file used to produce the sandbox and building the application.

cabal file

name:                armorwatcher
version:             0.1.0.0
license-file:        LICENSE
author:              Richard Zetterberg
maintainer:          richard.zetterberg@styleofweb.se
category:            System
build-type:          Simple
cabal-version:       >=1.18

executable armorwatcher-app
    main-is:         Main.hs

    ghc-options:     
        -Werror -Wall -threaded

    build-depends:
        base >=4.6 && <4.7,
        hinotify >=0.3 && <0.4,
        shelly >=1.5 && <1.6,
        unix >=2.7 && <2.8

    default-language:
        Haskell2010

Main.hs

{-# LANGUAGE OverloadedStrings #-}

module Main where

import           Control.Monad (forever, void)
import           Control.Concurrent (threadDelay)
import           System.INotify (INotify, EventVariety(..), Event(..), WatchDescriptor)
import qualified System.INotify as INotify
import           System.Posix.Signals (Handler(..), sigINT)
import qualified System.Posix.Signals as Signals
import           Shelly

------------------------------------------------------------------------

main :: IO ()
main = do
    let watchee = "/var/log/audit/audit.log"

    putStrLn $ "Setting up watching of " ++ watchee

    inst       <- INotify.initINotify
    descriptor <- INotify.addWatch inst [Modify] watchee auditChanged

    let handler = Catch $ interruptApp inst descriptor

    void $ Signals.installHandler sigINT handler Nothing

    putStrLn "Setup complete, waiting for changes"

    forever $ threadDelay maxBound

auditChanged :: Event -> IO ()
auditChanged (Modified _ _) = shelly $ verbosely $ do
    echo "Audit changed, searching log"
    audits <- run "ausearch" ["--start", "recent", "-r"] 
    echo "Log searched"
    echo audits
auditChanged _ = return ()

interruptApp :: INotify -> WatchDescriptor -> IO ()
interruptApp inst descriptor = do
    INotify.removeWatch descriptor
    INotify.killINotify inst

    putStrLn "Watching removed, quitting!"

[gregwebs]

This is why I mentioned to @kolmodin that always trapping all exceptions in hinotify and ignoring them is not a good solution. So the error message is produced by the exception thrown by shelly and hinotify discards that. A quick fix for you would be to put an exception handler around shelly that catches the exception and prints it out.

I am closing this issue since it should be raise with hinotify

[rzetterberg]

@gregwebs, thanks for explaining and providing a solution!