Tracing

Summary   : How to use the trace facility to debug scripts
Author    : Peter Koch
Created   : 2005-08-17
Revisions :
Based on  : Facile Forms 1.4.1,  Joomla 1.0.8
Applies to: Facile Forms 1.4.1 ... 1.4.4, Joomla 1.0.0 ... 1.0.8, Mambo 4.5.1 ... 4.5.3

Debugging pieces has often been a pain, because the PHP error messages are of little help by just telling the failure was somewhere in in eval'd code along with the line number of the form processor, which is absolutely useless in this case. So it was up to you to trace down in what piece that error might have happened by unpublishing elements one after the other, or inserting test output statements within the pieces here and there.

The tracing facility introduced with 1.4.1 overcomes this problem now. It dumps a trace about the program flow within the pieces and functions, and in case of errors or warnings you will exactly know in what piece or function it is. You can also enter your own debug information into that trace for example to display status messages or variable values of interest.

A nice thing is that the trace can be shown in a separate popup-window, so the form itself does not get screwed up by warnings or debug output and is still functional (at least so long no fatal error happens). In case of error or warnings, a simple click on the last known location will bring you there immediately. You will wonder how you could ever be without this.

Contents 1 Usage 1.1 Syntax 1.2 Mode 1.3 Disable 1.4 Priority 1.5 Scope 1.6 Topics 1.7 Examples 2 User defined trace entries

Usage

The trace facility can be controlled in every piece (or embedded code) by inserting a directive at the very beginning. The directive must start with a comment opening, immediately followed by the tag +trace without any spaces between the comment and trace tags.

Syntax

//+trace [Mode] [Disable] [Priority] [Scope] [Topics]

or

/*+trace [Mode] [Disable] [Priority] [Scope] [Topics] */

Mode

Mode setting works only in the first directive, in all subsequent directives attempts to change mode are ignored.

popup

Trace output is collected in a buffer and displayed in a popup window. This completely keeps the trace out of the page source and also prevents some error levels (1) from getting written into the form. This is the default mode if none is listed in the first directive.

append

Trace output is collected in a buffer and appended after the form in the page source. This will mostly not harm the form itself, but the trace may appear below the form elements. Errors and warnings captured are the same as in popup mode. You can use this as an alternative if you for any reason cannot, or do not want to use popup.

direct

Direct mode immediately writes the trace into the browser document. This would normally screw up your form and produce additional browser and javascript errors. Therefore the form content is escaped in direct mode, and shown as HTML source with the trace messages between it.

You need to use direct mode to debug certain type of errors (2) which cannot be captured due to PHP limitations. Instead of letting facile forms handle it, PHP will show its normal error message and immediately exit. If you for example get a parse error in eval'd code, just switch to direct mode and use the browsers search function to locate Parse error to see what the failing piece is and from where the program was coming.

A second case where to use direct mode are submit pieces: Switch to direct mode in your begin submit piece, and use exit or die statements to stop execution before explicit redirections in your code, or before the implicit redirection back to view mode which takes place after the end submit piece.

(1) Error levels captured by facile forms error handler:

E_WARNING E_NOTICE E_USER_ERROR E_USER_WARNING E_USER_NOTICE

(2) Error levels not captured by facile forms error handler:

E_ERROR E_PARSE E_CORE_ERROR E_CORE_WARNING E_COMPILE_ERROR E_COMPILE_WARNING

Disable

Disable works only in the first trace directive, in all subsequent directives attempts to disable tracing are ignored.

disable

Disables tracing of any information. Choose this for well tested forms to get maximum performance. Since tracing is disabled completely, there is no internal information about last known positions in case of warnings and errors.

By default tracing is enabled.

Priority

Priority allows to permanently have trace directives in your form and library pieces, but still override them from higher priorities. There are 5 levels of priority:

minimum low normal high maximum

Directives of a certain priority can only be overridden by subsequent pieces if they have same or higher priority. The default priority is normal if none is listed in the directive.

The standard library has for example a /*+trace none directive which is normal priority, so it is excluded from trace unless the priority is high or max before calling it.

Scope

global

The settings are valid for this piece, all pieces loaded by this one (callees), and they will also stay in effect after execution of this piece for all subsequent pieces (successors).

local

The settings are valid while in this piece and for all callees. The previous settings will however be restored after execution of the current piece for successors. This is the default scope if none is listed in the directive.

Topics

Can either be all, none, or a combination of eval, piece, function and message. If no topic is listed in the directive, it defaults to piece function message

none

Show none of the topics. Please note that this is not identical with disable mode: none still logs some hidden information to let the error handler in case know where the last position was, while disable does not.

eval

Show the name of the piece immediately before eval'ing it to trace down parse errors.

piece

Show piece entry and exit at execution

function

Show function entry and exit at execution

message

Show user messages emitted with ff_trace() while executing

all

A shortcut for eval piece function message.

Examples

Note: All tags can be abbreviated to three characters since developers hate writing too much. So instead of disable you may also just write dis for example.

No directive at all

If you have no directive at all, the trace settings default to //+trace popup minimal global none

//+trace glo

This is eqivalent to //+trace popup normal global all

//+trace max none

Disables tracing while in this piece, hiding it and its callees from the trace dump. Cannot be overruled.

//+trace glo high fun mes

Enables tracing of function entry/exit and messages for this piece, callees and successors. Can only be overridden by callee and successor directives with priority high or max

/*+trace dir glo */

Select direct mode if this is the first directive running. If this is not the first directive, direct will be ignored. Enables all topics for this piece, callees and successors. Can be overruled by callee and successor directives with priority normal or up.

//+trace dis

Disables tracing if this is the first trace directive (usually in the before form and the begin submit pieces). This is the setting you use for well tested forms published on a productive site.

User defined trace entries

You have 2 options to include your own debug output in the trace:

Function ff_trace($message)

This function acts according to the trace settings of the current piece. E.g. when neither message nor all is defined, it wont produce any output. The message string gets indented to the current trace level:

ff_trace('I am now on line '.__LINE__);

Sample output:

+Enter piece data2 of displang[1] at line 1
  +Enter function rnmlanguagelist(1) at line 3
    I am now on line 10
  -Leave function rnmlanguagelist at line 44
-Leave piece data2 of displang[1] at line 1      

I also find it handy to use print_r() to dump any variable with the ff_trace() function. Dont forget to set the second parameter of print_r true, otherwise output will be echo'ed instead of going into the trace:

ff_trace( 'Current values of object $row:'.print_r($row, true) );

PHP's standard function trigger_error()

This will create an entry in the trace log too, but with these differences to ff_trace():

• The output is formatted by the facile forms error handler, just the same way it does for other errors and warnings of levels (1) emitted by PHP:

trigger_error('I am now on line '.__LINE__);

Sample output:

+Enter piece data2 of displang[1] at line 1
  +Enter function rnmlanguagelist(1) at line 3

*** EXCEPTION CAUGHT BY FACILE FORMS ***
PHP error level : E_USER_NOTICE
PHP filename    : K:xampplitehtdocs452...cess.php(755) : eval()'d code
PHP linenumber  : 10
Last known pos  : Enter function rnmlanguagelist at line 3
Error message   : I am now on line 10

  -Leave function rnmlanguagelist at line 44
-Leave piece data2 of displang[1] at line 1      

• When running in backend, the last known position is clickable and takes you directly to the related form, element, script or piece.

• If tracing is enabled, all triggered errors of level (1) will show up in the trace dump.

• Triggering errors of type E_USER_ERROR will let facile forms die gracefully (3):

trigger_error('Some fatal error', E_USER_ERROR);

Sample output:

+Enter piece data2 of displang[1] at line 1
  +Enter function rnmlanguagelist(1) at line 3

*** EXCEPTION CAUGHT BY FACILE FORMS ***
PHP error level : E_USER_ERROR
PHP filename    : K:xampplitehtdocs452...cess.php(755) : eval()'d code
PHP linenumber  : 10
Last known pos  : Enter function rnmlanguagelist at line 3
Error message   : Some fatal error

(3) Dying gracefully means the form output is discarded and the session continues (see also library function ff_die). Allthough there is an error message displayed in space where the form should be, facile forms does not leave a html mess behind and processing can continue with the next module or whatever comes behind to complete the page. Compared to this a sudden death by die, exit or an error level (2) will not allow the rest of the page to be completed since the PHP session is really dead after.