Driver trace (logging) to DebugView using PROP:Profile='Debug:'

mriffey · February 28, 2024, 3:31pm

The Skype group gets this question regularly. Everything in this post is documented in the clarion help. Search for “driver i/o” or “logging” and you’ll find it.

This code shows how to enable and disable Clarion driver trace (for ODBC in this case, but it works the same for the other drivers).

It also includes a sample log so you can see what is produced from a typical prop:SQL query. The same type of output comes out when you use legacy or ABC file I/O because this is a driver level trace, not one dependent on ABC or legacy.

TestPSQLTrace.clw is the sample code. If you try it on your PC, you will need to add the ODBC driver to the drivers section of the project. I intentionally used “ridiculous” field sizes and all cstrings to make it clear that the ODBC driver doesnt generally care about this stuff and you can get a number (see the query in the code) back into a CSTRING field.

The command parameter OWNER is required to define the owner string so Clarion can access your database. I made this a parameter so that the code doesnt require credentials hardcoded in the code (which you shouldnt do).

Note that the code shows how you can easily intersperse your own OutputDebugString (ODS) log info along with the logging produced by the driver.

The output from ABC and legacy will be somewhat different vs prop:SQL because ABC and legacy use parameterized queries (as they should) to do their work. I didnt do that in this sample because that wasnt the point of the example.

Ive attached the debugview log output as well - you can easily see how the output lines up with what you see in the code.

Hope this helps.

TestPSQLTrace.clw (2.7 KB)
ClarionODBCDriverTrace.txt (14.6 KB)

Mark_Sarson · February 28, 2024, 8:00pm

Hi Mark,

Thanks, great info

This is something I do in my derived ABC FileManager class.

Trying to be helpful here, I created a cut down version of what I have created that shows the basics.

Repo can be found here

mriffey · February 28, 2024, 8:46pm

Normally I wouldn’t do it how I do it in this example:)

I have a couple of classes that manage all SQL access and utilitarian things like “turn on tracing for table ABC” (and turn it off), but I couldn’t use any of that here. While it would have cut 80% of the code out of the example, it wouldn’t have been nearly as clear.

Mark_Sarson · February 28, 2024, 9:01pm

I understand that, and I know you were trying to show how you can do this

I thought maybe the pairing here with understanding how to derive the FileManager might be useful also.

Cheers

Mark

mriffey · February 28, 2024, 9:32pm

I think thats a good idea. Maybe one of us (or someone) can show how they manage this in a homegrown class as well.

CarlBarnes · February 28, 2024, 9:41pm

I made a test project of Tracing to Debug (download at end) to send to SV to show how ugly Debug was with extra blank lines and short lines compared to the Text file that does not have the ugliness.

Below is a screen cap with Debug on the Left and Text file on the right to show the ugliness. It also provides a sample of what you get in the tracing output including PROP:Details and PROP:LogSQL

Below is the code that made the above. It does a variety of file access commands to see what comes out as Prop:Details and Prop:LogSQL. Project download at the end.

!Test PROP:Profile='DEBUG:' to send Profile to Debug View instead of a disk file
!Can also send to Disk file to compare the otuput to DEBUG and see how Debug is UGLY.
!Also tests various file ops with PROP:Profile to see what you get in the output
!
!IMO the DEBUG: output is Not formatted as nicely as the file logging. Its UGLY UGLY UGLY 
!       It has like breaks before the "Time Taken", and also inserts BLANK lines so is DOUBLE SPACED.
!       I think PROP:LOG has some limitations if you try to do multiple calls to it without a file op???

!Help: https://clarion.help/doku.php?id=prop_profile.htm
!Help: https://clarion.help/doku.php?id=prop_profile_1.htm

!==========================================================================================
  PROGRAM

  MAP 
TestProfile_AskMessage     PROCEDURE()  !Message to Ask if Log to Debug or File
TestProfile_FileCode       PROCEDURE()  !File Code to be Logged
  END

!The use of {PROP:Profile}='DEBUG:' is not well documented appearing only in topic "Debugging your SQL application"

Profile:OutputDebugString EQUATE('DEBUG:')  !Use with PROP:Profile to send to OutputDebugString()
Profile:LogFileName       EQUATE('ProfileLog_SQL_ToFILE.TXT')

MyFile1 FILE,DRIVER('SQLite'),PRE(MyF1), BINDABLE,CREATE,THREAD,OWNER('MyFile1.SQL')
KeyByID     KEY(MyF1:ID),PRIMARY 
KeyByDate   KEY(MyF1:Date),DUP,OPT 
Record  RECORD,PRE()
ID         SHORT        !MyF1:ID
Name       STRING(20)   !MyF1:Name
Date       LONG         !MyF1:Date
    END
 END

  CODE
  IF 0 THEN         !1=Test Profile without UI, a way to test my DbFileAccessON() function
       DbFileAccessON(MyFile1)      !Easy Call to Debug File Access to MyFile1 using PROP:Profile='DEBUG:'
       TestProfile_FileCode()       !
       DbFileTurnOFF(MyFile1)
  ELSE 
       TestProfile_AskMessage()     !Message to allow Profile to DEBUG or FILE
  END
  RETURN 
!-------------------------------------------
TestProfile_AskMessage     PROCEDURE()
Profile2    PSTRING(256)
    CODE

    CASE Message('Test PROP:Profile=DEBUG: ' & |
                 '||Profile with OutputDebugString or File?' & |
                 '||CLA Library ' & system{PROP:LibVersion,2} &'.'& system{PROP:LibVersion,3} & |
                 '||Do you have Debug View running?', |
                 'Profile 2 Debug - SQLite',ICON:Clarion, |
                 'Profile=DEBUG:|File: '& Profile:LogFileName & '|Do Not Log|Halt')
    OF 1 ; Profile2 = Profile:OutputDebugString   !Secret word 'DEBUG:'. Can be any case
    OF 2 ; Profile2 = Profile:LogFileName         !Disk File Logging
                      REMOVE(Profile2)            !     Do not append
    OF 3 ; Profile2 = ''                          !Do Not Log
    OF 4 ; HALT
    END
    
    MyFile1{PROP:Profile} = Profile2  ! Filename to write profiling of all File I/O calls and errors returned by the file driver
    MyFile1{PROP:Details} = 1         ! True = Driver to include Record Buffer contents **
    MyFile1{PROP:LogSQL}  = 1         ! True = Turns ON logging of calls to the backend for SQL drivers 
    TestProfile_FileCode()
    RETURN 
!-------------------------------------------
TestProfile_FileCode     PROCEDURE()
    CODE
    !Message('PROP:Profile=' & MyFile1{PROP:Profile}  &'|PROP:Details=' & MyFile1{PROP:Details},'Profile PROPs') !Debug Message

    MyFile1{PROP:Log}='##### TestProfile_FileCode -- ' & |
                      FORMAT(TODAY(),@d3) &' '& FORMAT(CLOCK(),@t6) &' -- ' & |
                      'PROP:LibVersion: '& system{PROP:LibVersion,2} &'.'& system{PROP:LibVersion,3} &' #####'

    REMOVE('MyFile1.SQL')  !Simply get rid of this SQL DB Disk File so Create cannot have issue for Driver

    !Perform some file actions to Log
    CREATE(MyFile1)
    IF ErrorCode() THEN Message('CREATE(MyFile1) failed '& ErrorCode()&' '&Error(),'Profile2Dbg').
    OPEN(MyFile1)
    IF ErrorCode() THEN Message('OPEN(MyFile1) failed '& ErrorCode()&' '&Error(),'Profile2Dbg').

    !A Mix of File Access Commands to see the LOG
    MyFile1{PROP:Log}='##### ADD 4 Records #####'
    CLEAR(MyFile1)
    LOOP 4 TIMES
        MyF1:ID += 1
        MyF1:Name = 'Test Add ' & MyF1:ID
        MyF1:Date = TODAY() + CHOOSE(MyF1:ID % 2 = 0,-33,44) * MyF1:ID
        ADD(MyFile1)
    END
    
    MyFile1{PROP:Log}='##### SET to ID=3 then NEXT to EOF #####'
    CLEAR(MyF1:Record,-1)
    MyF1:ID = 3                     !See records 3 and 4 
    SET(MyF1:KeyByID,MyF1:KeyByID)
    LOOP
        NEXT(MyFile1) ; IF ERRORCODE() THEN BREAK.
    END

    MyFile1{PROP:Log}='##### SET to KeyByDate then PREVIOUS #####'
    SET(MyF1:KeyByDate)
    LOOP
        PREVIOUS(MyFile1) ; IF ERRORCODE() THEN BREAK.
    END

    MyFile1{PROP:Log}='##### GET ID=4 then DELETE #####'
    MyF1:ID = 4
    GET(MyFile1,MyF1:KeyByID)
    DELETE(MyFile1)
 
 
    !Try to GET and DELETE 4 again which WILL FAIL, see what Debug shows    
    MyFile1{PROP:Log}='##### Repeat GET(,4) and DELETE ... that will FAIL #####'
    CLEAR(MyFile1) ; GET(MyFile1,0)
    MyF1:ID = 4
    GET(MyFile1,MyF1:KeyByID)
    DELETE(MyFile1)
    
    CLOSE(MyFile1) 
    MyFile1{PROP:Log}='##### End of TestProfile_FileCode #####'
    RETURN

These were the little functions I made to wrap the setting the PROP’s needed. You could reuse these in your own code.

!==============================================================================
! Functions to make it easy to turn On/Off Profile going to Debug
!==============================================================================
   MAP
DbFileAccessON      PROCEDURE(*FILE File2Debug, BOOL DetailsOfRecord=True, BOOL SqlBackendCalls=True, <STRING DiskFileLogName>) !Turn ON PROP:Profile File Logging
DbFileComment       PROCEDURE(*FILE FileDebuging, STRING Comment2Log)   !Write Debug Comment to File Profile LOG
DbFileTurnOFF       PROCEDURE(*FILE File2NotDebug)                      !Turn OFF PROP:Profile File Logging
   END

DbFileAccessON      PROCEDURE(*FILE File2Debug, BOOL DetailsOfRecord=True, BOOL SqlBackendCalls=True, <STRING DiskFileLogName>) !Turn ON PROP:Profile File Logging
    CODE
    IF ~OMITTED(DiskFileLogName) AND DiskFileLogName THEN   !Idea: Could pass AppendFlag=1 then If =0 Remove(LogFile)
       File2Debug{PROP:Profile} = DiskFileLogName  ! Filename to write profiling of all File I/O calls and errors returned by the file driver
    ELSE 
       File2Debug{PROP:Profile} = 'DEBUG:'         ! DebugView /Debugger gets Profiling 
    END
    File2Debug{PROP:Details} = DetailsOfRecord  ! True = Driver to include Record Buffer contents **
    File2Debug{PROP:LogSQL}  = SqlBackendCalls  ! True = Turns ON logging of calls to the backend for SQL drivers 
    RETURN

DbFileComment       PROCEDURE(*FILE FileDebuging, STRING Comment2Log) !Write Debug Comment to File Profile LOG
    CODE
    FileDebuging{PROP:LOG} = Comment2Log
    RETURN

DbFileTurnOFF       PROCEDURE(*FILE File2NotDebug)  !Turn OFF PROP:Profile File Logging
    CODE
    File2NotDebug{PROP:Profile} = ''
    RETURN
!==============================================================================

Test projects download for TPS and SQL which uses SQLite, so anyone can run it no server needed.

PROFILE_TestProject_UglyDebugOutput.ZIP (10.0 KB)

CarlBarnes · February 28, 2024, 10:20pm

Instead of calling OutputDebugString('My comment to output')
you could use FILE{PROP:Log}='My comment to output'

If PROP:Profile='Debug:' then PROP:Log text will go to DebugView; otherwise, it will go to the log file specified in PROP:Profile='FileName.log'. If Profiling is not turned On then the text is lost so it should only pertain to file logging else call ODS.

I see File{PROP:TraceFile} = 'DEBUG:' in your code and in the @Mark_Sarson repo. I think that code is not required, my example did not use it. It’s probably incorrect the Help says PROP:TraceFile is a SYSTEM property, so not for a FILE. It says it is for setting the INI file with Trace settings.

mriffey · February 28, 2024, 10:32pm

It is documented here:

mriffey · February 28, 2024, 10:37pm

I dont use file{prop:log} anywhere else, so I wouldn’t have added it here, but some may use it a lot. I’m not sure I’ve ever used it:)

Eliminating the use of the file drivers has allowed integration of more consistent, better controlled, more granular and far simpler logging - all with the same infrastructure and optional integration with observability platforms. You can use that external integration with ODS even if you use the drivers - there’s a ClarionLive episode showing this and a later one where John H turned that code into a product. Search for Honeycomb.

CarlBarnes · February 28, 2024, 10:57pm

Mark’s code:

 SYSTEM{PROP:DriverTracing} = '1'
 
 PSQLTbl{PROP:TraceFile} = 'DEBUG:'   ! sends the trace info to debugview
 PSQLTbl{PROP:Details}   = 1 
 PSQLTbl{PROP:Profile}   = 'DEBUG:'   ! sends the trace info to debugview
 PSQLTbl{PROP:LogSQL}    = 1

Are you are referring to my post about the PROP:TraceFile ?

In the Help page you posted the “TraceFile” you point to is an Entry in an INI file [CWdriver] section. It is NOT the same thing as PROP:TraceFile. The help says PROP:TraceFile names that INI File to something other than DRIVERS.INI.

And the code you point to the value =‘Debug:’ is assigned to PROP:Profile not PROP:TraceFile

My attached example does this all without PROP:TraceFile.

Another line I would question is setting SYSTEM{PROP:DriverTracing} = '1'

Help says that is only used when the INI or Registry is used to setup tracing, as is done by Trace.exe. That the PROP:Profile based tracing “will still take effect” when DriverTracing=‘’ i.e. Off. I did not use that PROP in my example.

In short this should work:

!no need--> SYSTEM{PROP:DriverTracing} = '1'
!no need--> PSQLTbl{PROP:TraceFile} = 'DEBUG:'   ! sends the trace info to debugview
 PSQLTbl{PROP:Details} = 1         ! include record buffer contents in the log file
 PSQLTbl{PROP:Profile} = 'DEBUG:'  ! sends the trace info to debugview
 PSQLTbl{PROP:LogSQL}  = 1         ! logging of calls to the backend for SQL drivers

PROP:TraceFile is documented as for SYSTEM not a Single File.

You should not change the SYSTEM PROP:DriverTracing that turns On/Off tracing for ALL Files that is configured by the INI / Trace.exe. Your purpose is to configure a Single File to trace.