Tracing Verbs Give Unexpected Output

Authoring Inform 6
1

Section 7.4 of the DM4 gives example output for some of the tracing verbs, namely ACTIONS, MESSAGES, and CHANGES. On my system (inform 6.36 Win32 Library 6.12.5) I am getting a lot of extra output before what is documented. This occurs for the verbs actions, changes, messages, and timers. What’s happening here?

>actions
[Action listing on.]

>d
[Setting (Library Extensions).ext_number_1 to 1]
[Setting (Library Extensions).BetweenCalls to 7521]
[Setting (Library Extensions).BetweenCalls to 0]
[Setting (Library Extensions).ext_number_1 to 1]
[Setting (Library Extensions).BetweenCalls to 7521]
[Setting (Library Extensions).BetweenCalls to 0]
[... 11 more times...]
[ Action Go with noun 16 (ground) ]
[Moving yourself to In the clouds]

In the clouds
It is pretty cloudy around here.
[Giving In the clouds visited]
2

The first few lines of output look like the kind that come from the changes debugging verb. These debugging verbs act independently, so, for example, it’s possible to have both changes and actions on at the same time.

Are the lines related to changes appearing even before you first activate the feature?

3

Yes. Although it’s good to know where they’re coming from, this happens even when I’m not debugging changes.

4

I can see that the relevant bits are correctly being set independently in StdLib 6.12.5. I haven’t found where output like

[Setting (Library Extensions).ext_number_1 to 1]

is even coming from, however. A new mystery!

5

This is veneer code which prints changes to object properties. (This is the TrPS() veneer function, which is called from the other functions that set properties. There’s also some “[Giving object attribute]” messages.)

What’s surprising is that this behavior is enabled in debug mode if (debug_flag & 15). That is, it happens when any of the library debug modes (ROUTINES, ACTIONS, TIMERS, or CHANGES) are set. You’d think (and the DM4 says) that these four settings would be independent, but they’re not, and haven’t been for a long time.

I don’t know how that discrepancy got in there.

6

(As far as I can tell, they’ve behaved this way since 6.21 / 6/10, which is when the DM4 was written.)

7

Thank you, zarf. Some day I’ll learn to check the veneer code as functionally part of the library.

The handling of the debug_flag bit values changed significantly between 6/11 and 6.12.5. In 6/11, care was taken to only modify the lower four bits of the value when setting/unsetting the flags. In 6.12, there is a new constant DEBUG_VERBOSE set to $80, so that precaution was dropped. I’m not sure if that’s the direct cause, but it seems like a possibility.

Thanks again for the extra clue. I will look into this more deeply (and hopefully post a fix) unless someone else beats me to it.

8

As zarf says, the veneer code causing this is output has been unchanged for many revisions. As I read it (same as zarf explained it), any of the lower four bits of debug_flag being set (corresponding, from low to high, to DEBUG_MESSAGES, DEBUG_ACTIONS, DEBUG_TIMERS and DEBUG_CHANGES) causes any of the veneer routines that can modify an object property value to emit such a line via a call to RT__TrPS(). That’s not how I thought that functionality worked (I thought it was only from >CHANGES ON), but the last time I actively played with the debugging commands and infix was a while ago, and I was working with Inform 6.31 and StdLib 6/11.

Perhaps it’s just a matter of 6.12 LibraryExtensions object having its properties set for various reasons, then. This subsystem didn’t exist in 6/11 and earlier.

As far as a possible change, you can include a replacement for the relevant veneer routine to limit its output to when DEBUG_CHANGES is set. The code:

Replace RT__TrPS; ! This should be near the start of your source, maybe before any other Include directives

Include "Parser";
Include "VerbLib";
Include "Grammar";

! This placement is working in a test program, but it may be possible to place it as late as the end of source
[ RT__TrPS obj prop val;
    #Ifdef DEBUG;
    if (~~(debug_flag & DEBUG_CHANGES)) rfalse;
    #Endif;
    print "[Setting ",(name) obj, ".", (property) prop, " to ", val, "]^";
];

worked for a quick test. The various veneer routines still call RT__TrPS(), but it does nothing unless the DEBUG_CHANGES bit is set.

9

Many thanks to both of you for your insights; I know almost nothing of how veneer works, so I would have been very stuck! Replacing RT__TRPS in source works, I get the changes output only with >changes on. Thank you otistdog. Should I mark this as solved, or leave it open for now?

10

As the author of the original question, you choose if and when to mark it as solved. Maybe you should wait until you’re satisfied that the replacement routine is fully working and doesn’t need any refinement.

Funny thing – in my marked-up DM4 p. 99 there was already a note to the effect that >ACTIONS ON causes the output of >CHANGES ON in 6.31. (It’s hard to keep track of all of the places where actual code diverges from DM4 guidance. Interestingly, on a re-read I can’t find anywhere that it explicitly says that all debugging verbs are independent from one another… it just seemed a reasonable expectation. Inform 6 has great puzzle design!) Now there are new notes with more detail, so thank you for the question and thanks again to zarf for the pointer on the root cause from the compiler side.

1 Like