How to log call graph in Elm?

Question

Please help, this is driving me absolutely insane!

How do I make Elm log a call graph?

Sounds simple, doesn't it? The Debug.log function should make this quiet easy. But no, try as I might, I just cannot force Elm to log the events in the correct order. I'm losing my mind here...

---

Let's take a trivial function like this:

factorial : Int -> Int
factorial n = if n < 2 then 1 else n * factorial (n-1)

What I want to do is write a custom trace function so I can do something similar to

factorial n = trace ("factorial " + toString n) (if n < 2 ...)

and it will log something like

factorial 3: ENTER
factorial 2: ENTER
factorial 1: ENTER
factorial 1: 1
factorial 2: 2
factorial 3: 6

So you can see it enter each function, and you can see it return from each function (and what value it actually returned).

---

What doesn't work:

• Obvious first attempt is to do something like

  trace : String -> x -> x
  trace label x =
    let
      _ = Debug.log label "ENTER"
      _ = Debug.log label x
    in x
  

  But I don't think that can ever work. Since Elm is strict (?), x was evaluated before you ever even called trace. So all the traces print out backwards.

• Alright, let's make the input a function then:

  trace : String -> (() -> x) -> x
  trace label fx =
    let
      _ = Debug.log label "ENTER"
      x = fx ()
      _ = Debug.log label x
    in x
  

  That really, really looks like it should work perfectly. But somehow, this manages to print the entry and exit together, followed by all of the subordinate calls afterwards, which is obviously wrong.

• I'm particularly disturbed by the fact that

  let
    _ = Debug.log label "ENTER"
    x = fx ()
  in x
  

  prints all the enters forwards, yet the identical expression

  let
    _ = Debug.log label "ENTER"
  in fx ()
  

  prints all the enters backwards. (??!) I guess that's what I get for trying to control order of side-effects in a pure-functional programming language...

• Alright, let's make it a case-block then:

  trace label fx =
    case Debug.log label "ENTER" of
      _ -> case Debug.log label (fx ()) of
        x -> x
  

  Nope, that prints everything backwards. Well that's weird. What if I just swap both of the case expressions? ...Nope, that prints enter+exit together followed by the child calls.

• OK, let's get hard-core. Lambdas FTW!

  trace label fx = Debug.log label ((\ _ -> fx ()) (Debug.log label "ENTER"))
  

  That lots all the exits followed by all the enters. I'll just swap the expressions:

  trace label fx = (\ x -> (\ _ -> x) (Debug.log label "ENTER")) (Debug.log label (fx ()))
  

  No dice. That prints enter+exit for each call groups together again.

• Umm...

Seriously, there must be a way to get this to work! >_< Plz help... :'{

Answer 1

Try this:

trace : String -> (() -> x) -> x
trace label fx =
  let
    _ = Debug.log label "ENTER"  
  in
    let
      x = fx ()
      _ = Debug.log label x
    in 
      x

This appears to give your desired output.

Alternatively, since Debug.log returns its second argument, you could also write the following, which is slightly shorter:

trace : String -> (() -> x) -> x
trace label fx =
  let
    _ = Debug.log label "ENTER"  
  in
    let
      x = fx ()
    in 
      Debug.log label x

Taking a look at the generated code it seems the compiler was reordering the declarations within let blocks. Using a nested let block seems to persuade the compiler to not reorder the declarations.

If the declarations within the let block don't have any dependencies then the compiler is free to reorder them as it doesn't change the value returned by the function. Also, if variables are declared out-of-order within a let block, the compiler will sort them into the correct order. Take for example the following function:

silly : Int -> Int
silly x =
    let
        c = b
        b = a
        a = x
    in
        c * c

The Elm compiler cannot generate the three assignments in the let block in the same order that they are declared: it cannot calculate c without first knowing what b is. Looking at the generated code for this function I can see that the assignments are sorted into order so that the output value is calculated correctly. What would you expect to happen if you put Debug.log calls in the middle of this function?

Answer 2

By using Debug.log, you're trying to do something impure in a pure language. Even if you do get it to a point where it's working, as @Luke Woodward pointed out, I would hesitate relying on that because the log output could very well shift between compiler versions.

Instead, we could build a slimmed down Writer monad to keep a stateful representation of logs in the order they occur.

type Writer w a = Writer (a, List w)

runWriter : Writer w a -> (a, List w)
runWriter (Writer x) = x

pure : a -> Writer w a
pure x = Writer (x, [])

andThen : (a -> Writer w b) -> Writer w a -> Writer w b
andThen f (Writer (x, v)) =
    let (Writer (y, v_)) = f x
    in Writer (y, v ++ v_)

log : String -> a -> Writer String a
log label x = Writer (x, [label ++ ": " ++ Debug.toString x])

You could then sprinkle it in your factorial function, which means the function would now have to return a Writer String Int instead of just an Int:

factorial : Int -> Writer String Int
factorial n = 
    let logic =
            if n < 2 then
                pure 1
            else
                factorial (n-1)
                    |> andThen (\z -> pure (n * z))
    in
    log ("factorial " ++ Debug.toString n) "ENTER"
        |> andThen (\_ -> logic)
        |> andThen (\result -> log ("factorial " ++ Debug.toString n) result)

Though this looks more cumbersome and intrusive (Elm syntax is not as monad-friendly as Haskell), this will give you predictable results every time rather than having to depend upon unreliable side-effects.

The result of running factorial 3 |> runWriter |> Tuple.second is:

[ "factorial 3: \"ENTER\""
, "factorial 2: \"ENTER\""
, "factorial 1: \"ENTER\""
, "factorial 1: 1"
, "factorial 2: 2"
, "factorial 3: 6"
]

Note that this writer is not optimized (it concatenates lists, yuck!) but the idea is tried and true