"Shellish" behaviour on Mac OS X 10.8 and GHC 7.6.3

[adinapoli]

Hello guys,

in the past (I'm the guy of the "Testimonials" link) I've used Shelly without problems (Linux and GHC 7.4, I'm pretty sure), but now on Mac OS X 10.8 and GHC 7.6.3 I'm experiencing the old Shellish behaviour, namely the output is visible only after the command has been completed. To demostrate this (at least on my particular environment) I've whipped up this small program:

{-# LANGUAGE OverloadedStrings #-}
import Shelly
import Data.Text as T
import Data.Monoid

cabal :: [Text] -> Sh Text
cabal = run "cabal"

sandboxCreation :: Sh Text
sandboxCreation = undefined

main :: IO ()
main = shellyNoDir . verbosely $ do
    echo $ toTextArg "This will be printed immediately"
    initResult <- cabal ["update"]
    sandboxCreation
    echo "Finished! Now let's hack some Haskell!"

What happens is that the echo is printed immediately, whilst the program remain "stuck" on cabal update for a while, and then it print in "burst":

Downloading the latest package list from hackage.haskell.org
Main.hs:
Ran commands:
echo 'This will be printed immediately'
echo 'cabal update'
cabal update

Exception: Prelude.undefined

My first thought was that something changed codewise since I've used Shelly, or it's the platform/ghc version to do the difference.
Any idea?

Thanks!
A.

[gregwebs]

This behavior is seen in cabal-meta which uses shelly: yesodweb/cabal-meta#20

It works on Linux for me, so I am puzzled as to what went wrong. I will have a Windows computer in a few days that I can also test out.

[adinapoli]

Interesting, apparently it seems a Mac OS X thing. I have a Linux box on Amazon, I will give it a spin there to see if I can reproduce the error.

[adinapoli]

I was able to reproduce the problem on the Linux box too. Even more interesting is, I've tried on Mac OS X with GHC 7.4: same problem. I'm wondering then where the problem might lie.

[adinapoli]

Ok, after an afternoon of hacking I think I've restricted the area were the problem is, even though it doesn't explain why you are not able to replicate the problem or why the problem has popped up all of sudden. Anyway, if we look here:

https://github.com/yesodweb/Shelly.hs/blob/master/Shelly.hs#L230

And we put a Debug.Trace.debugIO to track if the code gets reached it actually is, and the tracing msg is printed before we get "stuck" waiting for more output. At first I though the problem was too much laziness inside the call to read text from the handler, which should return and consume the output as soon as it's available. Thinking more carefully I don't think it might be necessary laziness, because if I try to call a Debug after the line reading I should force the evaluation:

      Debug.traceIO "waiting"
      line <- TIO.hGetLine readHandle
      Debug.traceIO "got " ++ show line
      TIO.hPutStrLn writeHandle line >> go (foldLine acc line)

But again, whilst "waiting" is printed straight away, got" is printed after the command terminates. This make me think we remain stuck on the hGetLine, maybe we might have concurrency issues on the readHandle? I would say no, reading how handles are implemented: http://stackoverflow.com/questions/5136375/haskell-concurrency-and-handles
Anyway, I'll take another look tomorrow, but I hope my insight might be somewhat useful!

[adinapoli]

My suspect were true, it was something handle-related, and might be also related to the way different OS handles processes and pipes. This is a quick hack to demonstrate how to make the library display the output as we progress (tested just on the above program). We need to change the way we create the stdout handle in CreateProcess from CreatePipe to Inherit, to reuse the "global" stdout. Then we get back a Nothing from the createProcess as StdStream because we use the stdout. So basically we read from stdout and write to stdout, but from different processes, instead of having a pipe. My gut suggest this is wrong, but it's an hack which might give us some insight.
Here is the reference to the new relevant bits:

https://gist.github.com/adinapoli/5582382#file-gistfile1-hs-L270
https://gist.github.com/adinapoli/5582382#file-gistfile1-hs-L274

HTH to debug the issue further!
A.

[adinapoli]

Another update (sorry for these stream-of-consciousness-like comments): interestingly, the problem is extended to standard input too. To test it, try to create a Shelly program which call "cabal init". On my machine, it was waiting for the first user input and then it hung waiting for the second input (package version). The solution to make it work properly was to get rid of CreatePipe from std_in too. My gut feeling is that:

a) We are not handling correctly the corner case of creating this pipe. Maybe we need to say something like "if it's the first process Inherit, otherwise create a pipe", or something like that

b) Pass our on Handle around, calling UseHandle: http://hackage.haskell.org/packages/archive/process/latest/doc/html/System-Process.html#t:StdStream

c) The CreatePipe implementation has a bug and we might enquire for more info on the topic.

[gregwebs]

Won't inheriting break down in a multi-threaded environment? Thanks for keeping on this. I am going to try finishing the conversion to strict Text first.

[adinapoli]

Well, I actually don't know yet, but one thing is sure: with the current CreateProcess (aka using CreatePipe) we'll always see this weird behaviour.

As regards strict Text, I was planning to get rid of the callback and using maybe a conduit to sink our stdout messages, which we can fetch later on :)

[adinapoli]

Btw, I've found a bug with my patch (using Inherit): the text is displayed, but using the stdout to both read and write is simply not possible (stdout is created by the system ad a WriteMode pipe). This implies that, even though we see the output as it gets generated, we can't fold it, because as soon as we try to read something inside printFoldHandleLines we get the exception reminding us we can't read from this pipe. The behaviour can be triggered with this spec:

{-# LANGUAGE OverloadedStrings #-}
{-# LANGUAGE ExtendedDefaultRules #-}
module RunSpec (runSpec) where

import Test.HUnit hiding (path)
import Test.Hspec
#if defined(__GLASGOW_HASKELL__) && __GLASGOW_HASKELL__ < 706
import Prelude hiding ( FilePath, catch )
#else
import Prelude hiding ( FilePath )
#endif
import Shelly

runSpec :: Spec
runSpec = do
    describe "run should" $ do
      it "return the full stdout" $ do
        res <- shelly $ escaping False $ run "ls" ["*.hs"]
        res @?= "Setup.hs\n"

I need more time to figure out a solution which will both show the output AND concatenate it correctly. Reverting the createProcess to use pipes makes the test pass, but expose again the reported bug of the delayed output.

[gregwebs]

There should be a way to dup a handle. Friday starts the Haskell hackathon: I will have time to figure things out then.

[adinapoli]

Nice stuff, let's keep each other posted :)

[adinapoli]

Any improvement on this? I'm kinda stuck, so I was hoping in some enlightenment of yours :)

[gregwebs]

sorry, broke my arm 2 weeks ago when this issue was left off. but I have time to look at things this weekend now.

[adinapoli]

Oh, sorry for that :S hope you're right now :)
take care!

A.

[gregwebs]

I just pushed a branch 1.0-alpha with your changes (thanks!) except the switch to inherit. It also includes the new runHandles function. Time to look at this bug now.

[gregwebs]

I added a drain test onto the 1.0-alpha branch. I am not reproducing the problem, can you change the test as needed to reproduce the problem on your end?

[adinapoli]

Sure, I'll do! Just for curiosity, can you post your GHC version and your Machine distros and Kernel?
Last time I've tried Shelly on a Linux machine and had it work, was on a real-time patched kernel, so I just want to not leave anything to chance :)

[adinapoli]

Ok, if you merge my branch "shelly-1.0" and try to run "testall" you'll see that the program crashes when trying to use the run function now. Not sure if is the result of a wrong merge of mine, or a side effect of the new runHandler:

https://github.com/adinapoli/Shelly.hs/tree/shelly-1.0

Do you mind giving it a shot?
Thanks!
A.

[gregwebs]

Inherit is not a solution to this problem and is instead creating new bugs or maybe you have a merge issue. RunSpec works fine for me on 1.0-alpha so I don't think it is a useful test.. Please use the 1.0-alpha branch which has all your changes except for Inherit. I still do not have a test case demonstrating the original problem: if you can modify the drain test to reproduce it that would be very helpful.

[gregwebs]

ghc 7.6.3 (but previously I was using 7.4)

uname -a

Linux gweber-VirtualBox 3.8.0-22-generic #33-Ubuntu SMP Thu May 16 15:17:14 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

I am on Ubuntu 13.04 but was previously using 12

[adinapoli]

Sorry Greg, but I think you overlooked the fact I'm indeed using your branch, I've just merged your branch into mine preferring your edits in case of conflicts. The fact I'm using CreatePipe is witnessed here:

https://github.com/adinapoli/Shelly.hs/blob/shelly-1.0/src/Shelly.hs#L278

Why you say RunSpec is not a meaningful test? It test that whenever we run an external command, we are correctly writing all the output into a Sh Text monad, but apparently this is not the case. So either I had a bad merge or we are getting two different results on two different machines.

[adinapoli]

Bear also in mind you have assigned (I think) a wrong versioning:

https://github.com/yesodweb/Shelly.hs/blob/1.0-alpha/shelly.cabal#L3

Due to the fact 0.1.0.0 < 0.15 (is it?) it will never be installed by "cabal install". Shouldn't it be
"1.0.0.0"?

[adinapoli]

Perfect, it was a bad merge, now RunSpec passes. I will commit soon on my branch, which not only includes your 1.0-alpha, but correct the aforementioned version quirk :)

Edit: it's in in case you wanna merge it: https://github.com/adinapoli/Shelly.hs/tree/shelly-1.0

[adinapoli]

@gregwebs out of curiosity, have you ever got to the bottom of this?

[gregwebs]

no. I use Linux so I haven't seen it. If you can give me a test case that reproduces this on Mac I can try to solve it.

[adinapoli]

Good news, on the latest Shelly I wasn't able to reproduce it.
I don't know exactly what changed, but it seems to have fixed things.
You are free to close this, I'll reopen if ever I will experience the problem again :)

[gregwebs]

Thanks for the report! My guess is that your GHC version or line encoding setting may have changed.

[adinapoli]

The version is the same, I'm on Maverick now though.
It could be that some package Shelly depends upon was bumped, it you rewind the thread discussion I traced back the problem at the way processes were spawned, perhaps something changed internally in the meantime!

[andreasabel]

Seems like this problem resolved itself. Maybe it was in some dependency or in GHC.
The first GHC that works e.e. with macOS 10.14 is 7.8.