My previous post Refactoring Foxhound: Logging talked about two kinds of diagnostic logging,
- program trace data written to the SQL Anywhere console log text file during development, and
- errors and exceptions written to a permanent table by both development and delivery builds,
Here's an example of an exception displayed by the Foxhound "Display Diagnostics" button:
Here is the full text of the message, wrapped to fit on screen. To the end user, the interesting part to the end user is the ERRORMSG "...cannot access the file". However, for the purposes of this article the interesting part is the substring "610a5c":
1 - 2008-10-27 14:54:48.281
Debug Build 3324a 14 610a5c(610eh1)
SQLCODE = -602, SQLSTATE = WL002, ERRORMSG()
= Cannot access file 'C:\projects\foxhound\dbping_p001.tmp'
-- The process cannot access the file because it is being
used by another process.From Foxhound's point of view, this exception is a minor glitch. Foxhound executed the dbping.exe utility to gather some information about the connection to the target database, and it could not display that information; i.e., this section of Foxhound's "Facts & Figures" display does not appear:
From the client's point of view, it may be more interesting; in some cases the culprit is a firewall getting in the way between Foxhound and the target database.
But... enough about the actual exception; we're here to see how it is trapped and how it is handled.
The following excerpt comes from the stored procedure that detected the exception; only the code specific to exception handling is shown, NOT the actual code that raised the exception:
1 CREATE PROCEDURE rroad_dbping (
2 IN @p_proxy_owner VARCHAR ( 128 ),
3 IN @p_connection_string LONG VARCHAR,
4 OUT @p_connect_using_message LONG VARCHAR,
5 OUT @p_connected_to_message LONG VARCHAR,
6 OUT @p_dbping_output LONG VARCHAR )
7 BEGIN -- rroad_dbping
8
9 ...
10
11 DECLARE @sqlcode INTEGER;
12 DECLARE @sqlstate VARCHAR ( 5 );
13 DECLARE @errormsg VARCHAR ( 32767 );
14 DECLARE @diagnostic_string VARCHAR ( 255 );
15
16 ...
17
18 SET @diagnostic_location = '610a5b';
19
20 ...
21
22 SET @diagnostic_location = '610a5c';
23
24 ... [[[[[ the code that raised an EXCEPTION ]]]]]
25
26 SET @diagnostic_location = '610a6';
27
28 ...
29
30 EXCEPTION
31
32 WHEN OTHERS THEN
33
34 SELECT SQLCODE, SQLSTATE, ERRORMSG()
35 INTO @sqlcode, @sqlstate, @errormsg;
36
37 SET @p_connect_using_message = '';
38 SET @p_connected_to_message = '';
39 SET @p_dbping_output = '';
40
41 CALL rroad_exception ( STRING (
42 @diagnostic_location, '(610eh1)',
43 ' SQLCODE = ', @sqlcode,
44 ', SQLSTATE = ', @sqlstate,
45 ', ERRORMSG() = ', @errormsg ) );
46
47 END; -- rroad_dbpingHere's how it works: Lines 18, 22 and 26 (and many others in the actual code) record the "current location" in the code, during execution, so that information may be saved when an exception occurs. The hand-coded @diagnostic_location values are alphanumeric, starting with the module (file) number "610", followed by increments "a1", "a2", ... "a9", "b1", etc. When new program logic is inserted, say between 610a5 and 610a6, more characters are added: 610a5b, 610a5c and so on.There's nothing special about that encoding technique, except for the fact it's easy to hand-code new values that are globally unique without having to keep track of a "last used value" or anything like it.
A global search for "610a5c" in all of the Foxhound source code will find exactly one location, and will narrow the search quite a bit.
It would be nice if SQL exception diagnostics showed the line numbers inside procedures, triggers and so on, but sometimes life is harsh.In this example, the exception was raised somewhere between lines 22 and 26. We know this because the @diagnostic_location value '610a5c' is passed to rroad_exception in line 33, and it ends up being displayed in the message text shown earlier "...610a5c...".
And yes, there all these SET @diagnostic_location statements do have an effect on performance. I've never been able to measure the effect, but I have also avoided placing the SETs inside tight loops.
The exception is trapped by the one single EXCEPTION block in the entire module, starting at line 30. Other, longer stored procedures have many nested BEGIN ... EXCEPTION ... END blocks, but this procedure only has one.
The hard-coded literal '(610eh1)' serves to uniquely identify the EXCEPTION handler itself. If this module had more than one, the others would be numbered '(610eh2)' and so on. The most exception handlers in any single Foxhound procedure is 14.The WHEN OTHERS THEN construction is shorthand for "trap everything". It is immediately followed by the SELECT at line 34 that saves the current values of SQLCODE, SQLSTATE and ERRORMSG(); it is important to do this right away inside the EXCEPTION block before any other code has a chance to change the values.
The three lines starting at line 37 are this module's way of graciously handling all exceptions: all the OUT parameters are set to empty strings to tell the caller "nothing to display".
The CALL to rroad_exception at line 41 passes all the diagnostic information gathered so far to a procedure that will store it in this table:
CREATE TABLE rroad_exception (
exception_id BIGINT NOT NULL
DEFAULT AUTOINCREMENT
PRIMARY KEY,
exception_diagnostic LONG VARCHAR NOT NULL );Here's the code for the procedure, and for the corresponding EVENT that it triggers: 1 CREATE PROCEDURE rroad_exception (
2 IN @diagnostic_text LONG VARCHAR ) -- may be truncated if it doesn't fit
3 BEGIN
4
5 DECLARE @build_number_fork VARCHAR ( 10 );
6 DECLARE @exception_diagnostic LONG VARCHAR;
7
8 ... [some code to fill @build_number_fork]
9
10 BEGIN -- ignore further exception
11
12 -- Build diagnostic string and truncate to
13 -- "page size - 100" limitation on event parameters
14
15 SET @exception_diagnostic = LEFT (
16 STRING ( CURRENT TIMESTAMP,
17 IF '{DEBUG_MESSAGES}' = 'ON'
18 THEN ' Debug Build '
19 ELSE ' Full Build '
20 ENDIF,
21 @build_number_fork,
22 CONNECTION_PROPERTY ( 'Number' ),
23 ' ',
24 @diagnostic_text ),
25 CAST ( PROPERTY ( 'PageSize' ) AS BIGINT ) - 100 );
26
27 MESSAGE STRING ( 'DIAG EXCEPTION ',
28 @exception_diagnostic ) TO CONSOLE DEBUG ONLY;
29
30 TRIGGER EVENT rroad_exception (
31 @p_exception_diagnostic
32 = @exception_diagnostic );
33
34 EXCEPTION WHEN OTHERS THEN
35
36 END; -- ignore further exception
37
38 END; -- rroad_exception
39
40 CREATE EVENT rroad_exception
41 HANDLER BEGIN
42
43 DECLARE @p_exception_diagnostic LONG VARCHAR;
44
45 ...
46
47 -- Store exception data using separate connection to commit.
48
49 BEGIN -- ignore further exception
50
51 SET @p_exception_diagnostic = COALESCE (
52 EVENT_PARAMETER ( '@p_exception_diagnostic' ),
53 'NULL' );
54
55 INSERT rroad_exception ( exception_diagnostic )
56 VALUES ( @p_exception_diagnostic );
57
58 COMMIT;
59
60 EXCEPTION WHEN OTHERS THEN
61
62 END; -- ignore further exception
63
64 END; -- rroad_exceptionHere's how it works, and why an EVENT is included:- The SET at line 15 adds some more data (timestamp, Foxhound build number, etc) to the incoming @diagnostic_text, and then right-truncates the result to the length that can be passed as a parameter to an event.
- The TRIGGER EVENT at line 30 uses the special syntax necessary for passing parameters to events.
- The SET at line 51 uses the special EVENT_PARAMETER function to receive the parameter that was passed to the event.
- The INSERT and COMMIT at lines 55 and 58 do the real work... on the separate connection started by the event so the data gets saved even if the caller does a ROLLBACK.
No comments:
Post a Comment