Adding Trace produces error messages

Question

This is very strange. As I was trying to debug this problem, I noticed when I add Trace then I get lots of internal errors generated. This also happens the first time after the kernel is started. So, with new fresh kernel, typing

vars = {a, b, c, d};
x = Times @@ vars;
$Assumptions = x > 0;
Trace[Simplify[1 == Sqrt[x] Sqrt[1/x]], TraceInternal -> True]

Gives

But that is not all. Now with fresh kernel again, just adding one more variable to the list above, to make it 5 variables now, instead of 4, i.e. like this

vars = {a, b, c, d, e};
x = Times @@ vars;
$Assumptions = x > 0;
Trace[Simplify[1 == Sqrt[x] Sqrt[1/x]], TraceInternal -> True]

Now there is no error ! (make sure the kernel is fresh one before).

So it only happens when there are 4 variables in the list. Not 3 and not 5 and not 6. Only 4 !

Why does it fail when there are only 4 variables in the list? What is so special about the number 4?

Answer 1

Short Version

The ultimate cause of this problem is an evaluation leak that occurs when an expression of the form MakeBoxes[StringForm[...]] is evaluated.

Longer Version

MakeBoxes has the attribute HoldAllComplete. This allows it to create the box representation of any expression without evaluating it. For example:

MakeBoxes[1 + 1]
(* RowBox[{"1", "+", "1"}] *)

MakeBoxes[Print[1]]
(* RowBox[{"Print", "[", "1", "]"}] *)

Apparently, StringForm gets special treatment by MakeBoxes:

MakeBoxes[StringForm["Hello, ``", "World"]]
(*
   InterpretationBox["\"Hello, World\"",
     StringForm["Hello, ``","World"], Editable -> False]]
*)

Notice how the StringForm[...] expression has been evaluated to produce the label for the InterpretationBox, in addition to the unevaluated expression that serves as the content of that box.

This is all well and good when the StringForm expression stands alone, but what about when it is an expression awaiting the values of local variables, like this:

MakeBoxes[StringForm[x, y]]
(*
   During evaluation of In[20]:= StringForm::string: String expected at position 1
   in StringForm[x,y]. >>

   RowBox[{StringForm,[,RowBox[{x,,,y}],]}]
*)

Here we see a message very much like the one exhibited in the question. A simple RowBox is still generated, despite the message.

Isn't it invalid to have a free-standing StringForm expression like that? Yes, but we must remember that MakeBoxes is invoked recursively on all of its subexpressions. So we get an unexpected message when we try to generate boxes for a perfectly valid definition like this:

MakeBoxes[zot[x_, y_] := StringForm[x, y]]

(*
   During evaluation of In[26]:= StringForm::string: String expected at position 1
   in StringForm[x,y]. >>

   RowBox[{RowBox[{"zot", "[", RowBox[{"x_", ",", "y_"}], "]"}], ":=", 
     RowBox[{"StringForm", "[", RowBox[{"x", ",", "y"}], "]"}]}]
*)

The StringForm did not start out to be an invalid free-standing expression, but the recursive action of MakeBoxes made it so.

More Gory Details

How do we know that StringForm is to blame?

If we evaluate the expressions from the question with the debugger turned on and message breaks enabled, we see this stack trace:

We can see that StringForm triggered the first error, and we can see all of the behaviour described above in the preceding stack frames.

Why does the error only occur the first time the expression is evaluated?

The first time that the expression is evaluated, a great many packages are auto-loaded. Normally, this loading process is not shown by Trace. But because the example in the question uses TraceInternal, all of these internal activities are shown in the trace.

The first message is generated when MakeBoxes is called upon an auto-loaded definition that looks like this (in outline):

Parallel`Debug`Private`tracePrint[...] /; MemberQ[...] := 
  CheckAbort[
    Print[..., StringForm[Parallel`Debug`Private`sf, Parallel`Debug`Private`args]]
  , Abort[]
  ]

In subsequent evaluations, these auto-loads do not occur so neither does the problem. Also, if we turn off TraceInternal, then the problem does not occur on even the first evaluation since none of the auto-load expressions appear in the trace.

Are all the messages due to this one problem?

No. Some of the messages are knock-on effects of this first message. Others are due to further occurrences of StringForm. And yet others appear to be due to similar evaluation leaks in other components.

Why does the problem only appear when there are four variables instead of three?

I'm not sure, but I have a guess. Observe the size of the trace output for each of the following variable counts:

1 variable: 2.9 meg
2 variables: 65 meg (error occurs)
3 variables: 1.5 meg
4 variables: 64 meg (error occurs)
5 variables: 7.0 meg
6 variables: 7.5 meg
12 variables: 10.6 meg

Note correlation of error occurrence with the spike in the output size for quadratic and quartic equations. I speculate that Simplify uses much more elaborate techniques for equations of this kind. Perhaps part of that elaboration involves loading special libraries... and at least one of those extra libraries ends up loading the troublesome Parallel`Debug definition. Or it may be simply that the enormous size of the trace output crosses a magic array size threshold, triggering the parallel computation machinery.