Search code examples
rpipe

Order of messages to console within functions when piped

To keep track about the processing of some functions I would like to print messages in the Console when a function starts and when it is done.

I am a big fan of tidyverse and the pipe operator %>%. But I just found out that the messages at the start of the function are printed in the wrong order while the messages at the end have the correct order.

Does anybody know why or how to solve this?

Here is some code:

library(tidyverse)
testdata <- data.frame(a=c(3,5,7,1,2),b=c(2,5,6,3,9))

foo_1 <- function(DF){
  message("Hello 1")
  Obj <- DF %>% 
    mutate(Test_1=a*b)
  message("Bye 1")
  return(Obj)
} 

foo_2 <- function(DF){
  message("Hello 2")
  
  Obj <- DF %>% 
    mutate(Test_2=Test_1*2)
  message("Bye 2")
  return(Obj)
}

foo_3 <- function(DF){
  message("Hello 3")
  Obj <- DF %>% 
    mutate(Test_3=Test_2/a)
  
  message("Bye 3")
  return(Obj)
}

testdata %>% 
  foo_1() %>% 
  foo_2() %>% 
  foo_3()

The result printed in the console is:

Hello 3
Hello 2
Hello 1
Bye 1
Bye 2
Bye 3
  a b Test_1 Test_2 Test_3
1 3 2      6     12      4
2 5 5     25     50     10
3 7 6     42     84     12
4 1 3      3      6      6
5 2 9     18     36     18

What I would expect is the following order of messages:

Hello 1
Bye 1
Hello 2
Bye 2
Hello 3
Bye 3
  a b Test_1 Test_2 Test_3
1 3 2      6     12      4
2 5 5     25     50     10
3 7 6     42     84     12
4 1 3      3      6      6
5 2 9     18     36     18
Solution

  • 1) flush.console Use flush.console to force the display of the messages queued at that point.

    testdata %>% 
  foo_1() %>% 
  { flush.console(); foo_2(.) } %>% 
  { flush.console(); foo_3(.) }

    giving this output:

    Hello 1
Bye 1
Hello 2
Bye 2
Hello 3
Bye 3
  a b Test_1 Test_2 Test_3
1 3 2      6     12      4
2 5 5     25     50     10
3 7 6     42     84     12
4 1 3      3      6      6
5 2 9     18     36     18

    2) Bizarro pipe Another approach is to use the Bizarro pipe, which is just clever base syntax which looks pipe-like, instead.

    testdata ->.;
  foo_1(.) ->.;
  foo_2(.) ->.;
  foo_3(.)

    giving:

    Hello 1
Bye 1
Hello 2
Bye 2
Hello 3
Bye 3
  a b Test_1 Test_2 Test_3
1 3 2      6     12      4
2 5 5     25     50     10
3 7 6     42     84     12
4 1 3      3      6      6
5 2 9     18     36     18

    3) force force the evaluation of arguments in the three fuctions.

    foo_1 <- function(DF){
  force(DF) #######
  message("Hello 1")
  Obj <- DF %>% 
    mutate(Test_1=a*b)
  message("Bye 1")
  return(Obj)
} 

foo_2 <- function(DF){
  force(DF) #######
  message("Hello 2")
  Obj <- DF %>% 
    mutate(Test_2=Test_1*2)
  message("Bye 2")
  return(Obj)
}

foo_3 <- function(DF){
  force(DF) #######
  message("Hello 3")
  Obj <- DF %>% 
    mutate(Test_3=Test_2/a)
  
  message("Bye 3")
  return(Obj)
}

testdata %>% 
  foo_1 %>%
  foo_2 %>%
  foo_3

    giving:

    Hello 1
Bye 1
Hello 2
Bye 2
Hello 3
Bye 3
  a b Test_1 Test_2 Test_3
1 3 2      6     12      4
2 5 5     25     50     10
3 7 6     42     84     12
4 1 3      3      6      6
5 2 9     18     36     18

    4) pipe_eager_lexical Lionel, the magrittr developer, pointed out to me that magrittr has an eager pipe but does not assign it to a %..% operator; however, we can readily do that.

    library(magrittr)

`%>e%` <- pipe_eager_lexical  # eager pipe

testdata %>e% 
  foo_1() %>e% 
  foo_2() %>e% 
  foo_3()

    giving:

    Hello 1
Bye 1
Hello 2
Bye 2
Hello 3
Bye 3
  a b Test_1 Test_2 Test_3
1 3 2      6     12      4
2 5 5     25     50     10
3 7 6     42     84     12
4 1 3      3      6      6
5 2 9     18     36     18