Forum OpenACS Development: Re: ns_logctl Debug(sql) nsoracle driver and NaviServer

Collapse
Posted by Gustaf Neumann on
LogMinDuration is used for performance measurement of SQL statements. It is implemented via NsDbLogSql(), which is called in the C-implemented functions Ns_DbSelect(), Ns_DbExec(), and Ns_DbDML(), no matter which DB driver is used. The SQL statement is printed, when the duration of the statement is larger the min duration and the severity "Debug(sql)" is turned on.

There are also several other situations, when a driver logs statements. This might happen e.g. on errors, or whenever the implementor of a driver found it important to inform the operator of the server about a certain situation (mostly errors and warnings), these are not necessarily SQL statement specific.

Only the mentioned commands can be silenced pool-specifc via LogMinDuration. Note that the commands used by OpenACS are implemented per driver potentially via other commands. So, it is possible, that in certain situations too much logging might happen (in OpenACS, in nsdb, and in nsoracle),

Collapse
Posted by Raul Rodriguez on
Hi Gustaf,
We looked at this in more detail and we are unable to produce the described logminduration behavior in our NaviServer/NsOracle installation. The SQL statements and bind variable values are always printed in the log unless we disable all Debug(sql) with ns_logctl at which point we lose the control per pool. We are able to produce the behavior with a reference NaviServer/Postgresql installation with the same config options shown below. Any idea idea why the NaviServer/NsOracle installation is behaving differently?

# From Naviserver Config.tcl (on both installations)

# If debug is false, all debugging will be turned off.
set debug false
set dev false
set verboseSQL true
...
ns_section ns/db/pool/nolog {
    ns_param    maxidle            600
    ns_param    maxopen            0
    ns_param    connections        24
    ns_param  LogMinDuration     1000ms;# when SQL logging is on, log only statements above this duration
    ns_param logsqlerrors  false
    if { $database eq "oracle" } {
        ns_param        driver             nsoracle
        ns_param        datasource         $datasource
        ns_param        user               $db_name
        ns_param        password           $db_password
    } else {
        ns_param        driver             postgres
        ns_param        datasource         ${db_host}:${db_port}:dbname=${db_name}
        ns_param        user               $db_user
        ns_param        password           ""
    }
}
...
#ns_logctl severity Debug(ns:driver) on
#ns_logctl severity Debug(request) on
#ns_logctl severity Debug(task) on
#ns_logctl severity Debug(connchan) on
ns_logctl severity debug $debug
ns_logctl severity "Debug(sql)" $verboseSQL
...

# Test Script

if {[catch {
    set myvalue "success"
    set data "failed"

    ns_log notice "NOLOG: Begin [ns_db pools]"
    set db [ns_db gethandle nolog]

    ns_log notice "NOLOG: get nolog handle $db from pool [ns_db poolname $db]"
    set selection [ns_ora 0or1row $db "select :myvalue from dual"]
    set data [ns_set value $selection 0]

    ns_log notice "NOLOG: Query Return data: $data"

} errmsg]} { ns_log notice "NOLOG: Errro $data. $errmsg" set data err }

ns_log notice "NOLOG: END" ns_db releasehandle $db

ad_return_complaint 1 "NOLOG: handlereleased" return

# Log results where we wouldn't expect to see the Debug(sql) entries

[03/Jan/2023:18:18:48][567831.7faf90d8e700][-conn:lausd:default:2:1-] Notice: NOLOG: Begin main subquery log nolog
[03/Jan/2023:18:18:48][567831.7faf90d8e700][-conn:lausd:default:2:1-] Notice: NOLOG: get nolog handle nsdb1 from pool nolog
[03/Jan/2023:18:18:48][567831.7faf90d8e700][-conn:lausd:default:2:1-] Debug(sql): SQL():  select :myvalue from dual
[03/Jan/2023:18:18:48][567831.7faf90d8e700][-conn:lausd:default:2:1-] Debug(sql): bind variable 'myvalue' = 'success'
[03/Jan/2023:18:18:48][567831.7faf90d8e700][-conn:lausd:default:2:1-] Notice: NOLOG: Query Return data success
[03/Jan/2023:18:18:48][567831.7faf90d8e700][-conn:lausd:default:2:1-] Notice: NOLOG: END

Our goal is to disable sql logging per pool and in our AOLServer 4.5.1 installation we accomplished this by settting the verbose parameter to false on the database pool section as shown below. However, from looking at source comments in the NSOracle driver it appears that the verbose attribute has been deprecated in NaviServer. Do you know if it would be possible to restore this parameter or somehow bring back this functionality in a Naviserver/NsOracle driver setup?

# From Aol4.5.1 config.tcl:

...
ns_section ns/db/pool/nolog
    ns_param   maxidle            600
    ns_param   maxopen            0
    ns_param   connections        24
    ns_param   verbose            false
    ns_param   extendedtableinfo  true
    ns_param   logsqlerrors       false
    ns_param   driver             nsoracle
...

# Comment on NsOracle Naviserver Driver at line 956 at https://bitbucket.org/naviserver/nsoracle/src/main/nsoracle.c

    /*
     * In the old days we'd do this sort of thing:
     *    if(dbh->verbose) Ns_Log(Notice, "SQL():  %s", query);
     * But that no longer works in the current NaviServer.  The database
     * handle verbose flag is obsolete, and dbh->verbose is apparently ALWAYS
     * false.  Instead, set this in your config file:
     *    ns_logctl severity Debug(sql) on
     * And the calls below like this will then emit SQL into the log:
     *    Ns_Log(Ns_LogSqlDebug, "SQL():  %s", query);
     * mailto:--atp@piskorski.com, 2017/08/28 10:32 EDT
     */
    Ns_Log(Ns_LogSqlDebug, "SQL():  %s", query);

Thanks for all your help.