Technical Manual > Core > Logging

Logging

Event Logging

Event Logging

A new event logging was introduced in AGR v6.2 as a part of the new system core concept. This new event logging replaces the old logging with a more unified concept with greater flexibility. The new term event logging is a used because it is not only error logging, it can also be used for logging progress, warnings or just events in general.

It is probably best to start by showing an example of the new logging:

-- ===============================================================================
-- Author:      Mr. SQL
-- Create date: 20.02.2020
-- Description: Event logging example
-- ===============================================================================
CREATE PROCEDURE cus.example (
    @batch_id  INT = NULL,
    @origin_id TINYINT = NULL,
    @parent_id INT = NULL
)
AS
BEGIN
    SET NOCOUNT ON

    BEGIN TRY
        DECLARE @event_id INT
        EXEC @event_id = core.event_task_start @task_name = @@PROCID, @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @parent_id, @print = 1

        -- do some procedure stuff
        SELECT col_1, col_2 FROM cus.table_1

        -- here we execute another procedure and feed it the appropriate variables. Note how the @event_id is used as @parent_id
        EXEC cus.sub_example @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @event_id

        EXEC core.event_task_complete @event_id = @event_id, @print = 1
    END TRY
    BEGIN CATCH
        EXEC core.catch_error @event_id = @event_id
    END CATCH	
END

Here we see an example of a procedure that utilizes the new event logging. Every procedure that logs should start with the same 3 parameters:

@batch_id: Allows you to batch together multiple executions
@origin_id: Who executed the procedure? Was it 1 the web or 2the App Server? It is possible to add more origins by adding rows to the core.event_origin table
@parent_id: If a procedure executes another procedure we can use this variable to connect the two.

All of the above parameters are optional when executing the procedure making it easy to execute procedures manually

Core Objects

All procedures, tables, views and functions related to the event logging can be found in the core schema. The objects are available in both the stg database and the prod database. The most common objects you will need are:

core.event (view) - This is the base event view which will show you all the event log entries
core.event_ex (view) - Same as above, but with a little bit more information and nicer formatting
core.event_task_start (proc) - This is the procedure you use at the beginning of a procedure to log that the procedure has started
core.event_task_complete (proc) - If the procedure finishes without errors you call this procedure to log that the procedure has finished. Note that if an error occurs and you are thrown to the CATCH block of the procedure you will NOT call this one.
core.catch_error (proc) - This one should be placed in the CATCH block to log if an error occurred.
core.event_tx (table) - This is the main event log table. By default, you should not need to use this table directly, the core.event or core.event_ex views should be enough
core.event_type (table) - A list of available event types
core.event_origin (table) - A list of available event origins
core.event_task_info, core.event_task_warning & core.event_task_error (procs) - If you need to log additional information from within a procedure you can use these procedures. They will use event types 204 - 206
core.event_task_active (function) - Check if task registered running in core.event

The logging procedures have a lot of parameters. Most of them are rarely used but there are a few that you will need to know.

@task_name - The name of the “task”. In most cases this will be the name of the procedure. If you give this parameter the @@PROCID value it will figure out that this is an object ID and find the name from that ID (see example above)
@fixed_text & fixed_text2 - These are VARCHAR(900) fields and are good for storing shorter info
@event_text - This one is VARCHAR(MAX) and is good for storing error messages, stack trace etc…
@int_1 - int_5 & date_1 - optional parameters if you wish to store some extra numbers or dates. For example the int1, 2 & 3 parameters are used in STG2 to log the numbers of rows that are inserted/updated/deleted

This is how the core.event view looks like inst Let’s do a quick explanation of what we are seeing:

event_id - This is just the regular incremental identity id
event_date - The date of the event, basic stuff
event_type_id & event_type_name - List of event types can be found in the core.event_type table, more on that below
task_name - Usually the name of the procedure. In some cases when the Web or the App Server are executing something this can be some other name
batch_id & batch_name - The number & name of the execution batch (usually a daily job). If this is a negative number it means that the batch originated in the other database (e.g. if -1 in prod then it’s batch 1 in stg)
seconds & duration - Needs no explanation
fixed_text & fixed_text2 - Some text decided by the one that is logging
event_text - Long text, usually error message or stack trace
error - 0 = not an error, 1 = error. This is a useful flag to filter the view looking for errors
event_xml - Not used so far
origin_name - Name of the origin, i.e. who was executing the code, the web, the app server, someone else? See core.event_origin table for a list of available origins
parent_id - The event_id of the parent, i.e. the one that executed the stored procedure
reference_id - The event_id of the current procedure start event. If you are logging info or warning within a procedure this links back to the task start event
nest_level - If a procedure executes another procedure that executes another procedure that executes another procedure that executes another procedure…. this number tells you how deep you are. If you are looking at the logs and there seems to be missing a nest level, e.g. you jump from 3 to 6 it might be that some of the procedures are not logging (usually on purpose)
date_1 & int_1 - int_5 - Generic date and integer fields if you feel like using them. When doing an automatic data merge (stg2 stuff) this will for example log the number of rows inserted/updated/deleted
login_name - This is the name of the windows or sql user that executed the code.

Batching

When executing a number of procedures together, as is done in the daily job you can use the @batch_id parameter. You will first need to create a batch. Let’s see a code example:

DECLARE @batch_id INT
EXEC @batch_id = core.event_batch_insert
     @batch_name = 'DailyExt', 
     @description = 'External daily job',
     @insert_by = 'system'

EXEC cus.job_part_1 @batch_id = @batch_id
EXEC cus.job_part_2 @batch_id = @batch_id
EXEC cus.job_part_3 @batch_id = @batch_id
EXEC cus.job_part_4 @batch_id = @batch_id

It is unlikely that you will need to create this batching manually since it is built into the App Server (Task scheduler) to do this for all tasks

Custom Logging

The system comes with a number of standard event types. A list of available event types can be found in the core.event_type table:

event_type_id	event_type_name	severity_level
104	info	0
105	warning	1
106	ERROR	2
107	CRITICAL / FATAL	3
201	task executed	0
202	task started	0
203	task completed	0
204	task info	0
205	task warning	1
206	task ERROR	2
401	index rebuild	0
402	index reorganize	0
403	update statistics	0

You can create new types by adding them to this table. Under the hood, all the logging procedures use the core.event_insert procedure to write to the core.event_tx table. You can use this procedure directly to utilize the new event types. Let’s see an example:

-- create a new event type
INSERT INTO core.event_type (event_type_id,	event_type_name, severity_level)
VALUES (1001, 'Custom event type 1', 0)

-- use this new event type
EXEC core.event_insert @event_type_id = 1001, @event_text = 'Something has happened and I needed to log it'

Error Handling

There is one major difference between the old way of logging and the new and that is the error handling. If you end up in the CATCH block and call the core.catch_error, that procedure will not just log the error silently and carry on but it will actually re-raise the error causing the web to display an error or the parent procedure (if this is a nested procedure) to also cast an error. The core.catch_error procedure has a @reraise_error parameter that can be used to change this behaviour. If you set it to 0 it will only log the error but not re-raise it. Let’s create some dummy procedures to see how this works in real life:

-- dummy1
CREATE PROCEDURE cus.dummy1 (
    @batch_id  INT = NULL,
    @origin_id TINYINT = NULL,
    @parent_id INT = NULL
)
AS
BEGIN
    SET NOCOUNT ON

    BEGIN TRY
        DECLARE @event_id INT
        EXEC @event_id = core.event_task_start @task_name = @@PROCID, @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @parent_id, @print = 1

        -- let's call dummy2
        EXEC cus.dummy2 @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @event_id

        EXEC core.event_task_complete @event_id = @event_id, @print = 1
    END TRY
    BEGIN CATCH
        EXEC core.catch_error @event_id = @event_id
    END CATCH	
END
GO

-- dummy2
CREATE PROCEDURE cus.dummy2 (
    @batch_id  INT = NULL,
    @origin_id TINYINT = NULL,
    @parent_id INT = NULL
)
AS
BEGIN
    SET NOCOUNT ON

    BEGIN TRY
        DECLARE @event_id INT
        EXEC @event_id = core.event_task_start @task_name = @@PROCID, @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @parent_id, @print = 1

        -- let's call dummy3
        EXEC cus.dummy3 @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @event_id

        EXEC core.event_task_complete @event_id = @event_id, @print = 1
    END TRY
    BEGIN CATCH
        EXEC core.catch_error @event_id = @event_id
    END CATCH	
END
GO

-- dummy3
CREATE PROCEDURE cus.dummy3 (
    @batch_id  INT = NULL,
    @origin_id TINYINT = NULL,
    @parent_id INT = NULL
)
AS
BEGIN
    SET NOCOUNT ON

    BEGIN TRY
        DECLARE @event_id INT
        EXEC @event_id = core.event_task_start @task_name = @@PROCID, @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @parent_id, @print = 1

        -- let's do someting dumb that triggers an error
        SELECT 1/0

        EXEC core.event_task_complete @event_id = @event_id, @print = 1
    END TRY
    BEGIN CATCH
        EXEC core.catch_error @event_id = @event_id
    END CATCH	
END
GO

Now we execute cus.dummy1. This is how the log looks: inst Note how the error cascades all the way up to the first (dummy1) procedure and in each step we get the error chain in the event text. Also note that there is no task completed event.

If we were to change dummy3 so that it does not reraise the error like so:

    ...
    BEGIN CATCH
        EXEC core.catch_error @event_id = @event_id, @reraise_error = 0
    END CATCH	
    ...

The result would be like this: inst Note here how we get an ERROR entry in the log but the tasks still continue and complete

Manually Triggering an Error

The TRY / CATCH in SQL only goes to the CATCH block if an SQL error occurs. There is a way to manually trigger an error, using RAISERROR, which can be nice if we need to break on a logical error instead of an SQL error. Let’s see an example:

CREATE PROCEDURE cus.dummy (
    @batch_id  INT = NULL,
    @origin_id TINYINT = NULL,
    @parent_id INT = NULL
)
AS
BEGIN
    SET NOCOUNT ON

	BEGIN TRY
        DECLARE @event_id INT
        EXEC @event_id = core.event_task_start @task_name = @@PROCID, @batch_id = @batch_id, @origin_id = @origin_id, @parent_id = @parent_id, @print = 1

        DECLARE @itemcnt INT = (SELECT COUNT(*) FROM dbo.items)
        IF @itemcnt < 10000
        BEGIN
            DECLARE @msg VARCHAR(100) = CONCAT('Item count is too low: ',@itemcnt)
            RAISERROR(@msg,16,1)
        END
        ELSE
        BEGIN
            --
            -- do some cool stuff here
            --
        END

        EXEC core.event_task_complete @event_id = @event_id, @print = 1
    END TRY
    BEGIN CATCH
        EXEC core.catch_error @event_id = @event_id
    END CATCH	
END

The log will show our custom error inst

Abort if proc already running

You can use the core.event_task_active function to check if a task is registered as running and f.e. abort if that is the case. The test proc below is an example of how to do that, where you of course need to do the check before registering the “task started” event.

If you would execute this test proc in one session and then try to execute it two times in another session while the first one is running you would end up with something like this in core.event…

inst

The thing to notice here is that the “task info” events are not part of the “task started/completed” events, you will notice that the “task completed” event has reference_id pointing to the “task started” event while the “task info” events do not have reference_id set.

CREATE PROCEDURE cus.test_proc
AS
BEGIN
    SET NOCOUNT ON
 
    BEGIN TRY
        IF core.event_task_active(@@PROCID) = 1
        BEGIN
            EXEC core.event_task_info @task_name = @@PROCID, @fixed_text = 'Proc already running, execution aborted', @print = 1
            RETURN
        END

        DECLARE @event_id INT
        EXEC @event_id = core.event_task_start @@PROCID
 
        WAITFOR DELAY '00:00:10'
 
        EXEC core.event_task_complete @event_id
    END TRY
    BEGIN CATCH
        EXEC core.catch_error @event_id
    END CATCH
END

Log Level

Note that the setting core_log_level allows us to have logging inside procs that only activates for a higher log level.

If core_log_level is set to 1, which is the default, this code will do nothing until core_log_level is changed to 2 or higher…

        EXEC @event_id = core.event_task_start @@PROCID, @log_level = 2
        ...
        EXEC core.event_task_complete @event_id

Note that if you use this you also need to change the call to core.catch_error like this…

        EXEC core.catch_error @event_id, @@PROCID