Default Reporter in interactive mode adversely affected by messages printed in tests

[epurdom]

When I use the default reporter in test_dir in interactive model (which I believe is ProgressReporter), the output appears to be adversely impacted by messages that are printed by the functions in my tests. As a result, I can't identify which file/context in my package resulted in errors, I only get the cummulative result of the number of errors across all of the files. The location of the file with the error is not given. If I change the argument to SummaryReporter, then the messages interrupt the flow, but the information is all shown. [I'm guessing it's the messages, but I don't actually know]

I show the results at the end of this message for the two Reporters on my package clusterExperiment on Bioconductor (which in its devel version is currently hitting errors). By the SummaryReporter version, which gives all of the information, you can see that the first error is hit in my context mergeClusters, but the default reporter doesn't indicate any of that (and jumps from the clusterMany context to the last one subsampleClustering). Indeed, from a large amount of experience running on this package, I know it always stops any useful printout in this same place regardless of where the error is (unless the error is before this context/file). I'm not entirely sure what is the expected format of the different reporters (I'm not sure where this is documented), but this seems problematic behavior and is quite different experience from the output I get from the default reporter when running it on other packages.

(I know I should just suppress the messages in my test code, but I never think about it except when I'm under pressure to fix a mistake and don't want to mess with anything that might introduce errors!)

Here's the output from the default reporter (test_dir("tests/testthat/")):

⠙ |  32       | Assays                                                                Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): PCA.
Found more than one class "Annotated" in cache; using the first, from namespace 'S4Vectors'
Also defined by ‘RNeXML’
⠸ |  34       | Assays                                                                Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): PCA.
Found more than one class "Annotated" in cache; using the first, from namespace 'S4Vectors'
Also defined by ‘RNeXML’
⠼ |  35       | Assays                                                                Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): var.
⠦ |  37       | Assays                                                                Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): var.
⠹ | 173       | clusterMany                                                           3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
⠙ | 182       | clusterMany                                                           3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
⠏ | 210       | clusterMany                                                           3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
done.
⠇ | 219       | clusterMany                                                           3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
✔ |   4       | subsampleClustering [0.2 s]                                           

══ Results ═══════════════════════════════════════════════════════════════════════════
Duration: 994.9 s

[ FAIL 6 | WARN 2 | SKIP 0 | PASS 1618 ]
Error: Test failures

Result from SummaryReporter (test_dir("tests/testthat/", reporter=SummaryReporter))

> out<-test_dir("tests/testthat/", reporter=SummaryReporter)
Found more than one class "Annotated" in cache; using the first, from namespace 'S4Vectors'
Also defined by ‘RNeXML’
assays: 
Assays: .................................Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): PCA.
Found more than one class "Annotated" in cache; using the first, from namespace 'S4Vectors'
Also defined by ‘RNeXML’
.Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): PCA.
Found more than one class "Annotated" in cache; using the first, from namespace 'S4Vectors'
Also defined by ‘RNeXML’
..Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): var.
.Note: Not all of the methods requested in 'reduceMethod' have been calculated. Will calculate all the methods requested (any pre-existing values -- filtering statistics or dimensionality reductions -- with these names will be recalculated and overwritten): var.
..
ClusterFunction: 
Constructor: .........................................
clusterMany: 
clusterMany: .............................................................................................................................................................................3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
done.
.........3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
done.
............................3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
done.
.........3 parameter combinations, 0 use sequential method, 0 use subsampling method
Running Clustering on Parameter Combinations...
done.
...................
clusterSingle: 
clusterSingle: ....................................................................................................................................................................................................................................................................
constructor: 
Constructor: ..................................................................................................................................................................................................................................................................
dendrogram: 
Dendrogram: ..................................................................................................................
dimReduce: 
Dimensionality Reduction: .........................................................................................................................................
getBestFeatures: 
getBestFeatures: .............................................................WW.........................
heatmaps: 
Heatmap functions: ..............................................................................
mainClustering: ..................
makeConsensus: 
makeConsensus: .....................................................................
mergeClusters: 
mergeClusters: ......................................1.......................23..........................................4...............5.........................
otherPlots: 
Non-heatmap related plot functions: .............................................................................................
RSEC: 
RSEC: .....................................
rsecFluidigm: 
RsecFluidigm: ...6
subsampleClustering: 
subsampleClustering: ....

══ Warnings ══════════════════════════════════════════════════════════════════════════
1. `plotContrastHeatmap` works (test-getBestFeatures.R:170:2) - NAs introduced by coercion

2. `plotContrastHeatmap` works (test-getBestFeatures.R:172:2) - NAs introduced by coercion

══ Failed ════════════════════════════════════════════════════════════════════════════
── 1. Failure (test-mergeClusters.R:96:3): saving merge info works ───────────────────
primaryCluster(cl1) not equal to c(4, 1, 1, 5, 1, 2, 5, 1, 1, 3, 3, 3, 6, 6, 4, 2, 2, 2).
12/18 mismatches (average diff: 2.17)
[1]  1 - 4 == -3
[3]  2 - 1 ==  1
[4]  1 - 5 == -4
[5]  3 - 1 ==  2
[6]  4 - 2 ==  2
[10] 4 - 3 ==  1
[11] 4 - 3 ==  1
[12] 6 - 3 ==  3
[13] 3 - 6 == -3
...

── 2. Failure (test-mergeClusters.R:165:3): saving merge info works ──────────────────
clustMerged4@merge_nodeMerge[, "mergeClusterId"] not equal to c(NA, NA, 1, 3, NA).
4/5 mismatches (average diff: 2)
[2]  3 - NA == NA
[3] NA -  1 == NA
[4]  1 -  3 == -2
[5]  2 - NA == NA

── 3. Failure (test-mergeClusters.R:166:3): saving merge info works ──────────────────
clustMerged4@merge_nodeMerge[, "isMerged"] not equal to c(FALSE, FALSE, TRUE, TRUE, TRUE).
2 element mismatches

── 4. Failure (test-mergeClusters.R:298:3): logFC works ──────────────────────────────
length(unique(mergedList$clustering)) not equal to 5.
1/1 mismatches
[1] 4 - 5 == -1

── 5. Failure (test-mergeClusters.R:349:3): logFC works ──────────────────────────────
length(unique(primaryCluster(clustMerged))) not equal to 5.
1/1 mismatches
[1] 4 - 5 == -1

── 6. Error (test-rsecFluidigm.R:17:5): saved rsecFluidigm is still valid object ─────
Error: could not find function "checkRsecFluidigmObject"
Backtrace:
 1. testthat::expect_silent(checkRsecFluidigmObject(rsecFluidigmNew)) test-rsecFluidigm.R:17:4
 2. testthat:::quasi_capture(enquo(object), NULL, evaluate_promise)
 8. rlang::eval_bare(quo_get_expr(.quo), quo_get_env(.quo))

══ DONE ══════════════════════════════════════════════════════════════════════════════
Error: Test failures

[hadley]

Yeah, unfortunately our advice is to eliminate these messages so the behaviour of ProgressReporter is not something that we're planning on changing.