Forum OpenACS Development: ns_logctl Debug(sql) nsoracle driver and NaviServer
We think it may be the nsoracle driver. Any help is appreciated.
Relevant config entries:
...#--------------------------------------------------------------------- # If debug is false, all debugging will be turned off. set debug false set verboseSQL true
ns_section ns/server/$server/db {
ns_param pools pool1,pool2,pool3
ns_param defaultpool pool1
}
ns_section ns/db/pools {
ns_param pool1 "Pool 1"
ns_param pool2 "Pool 2"
ns_param pool3 "Pool 3"
}ns_section ns/db/pool/pool1 {
# ns_param maxidle 0 ;# time interval for shut-down of idle connections; default: 5m
# ns_param maxopen 0 ;# time interval for maximum time of open connections; default: 60m
# ns_param checkinterval 5m ;# check pools for stale handles in this interval
ns_param connections 15
ns_param LogMinDuration 100ms ;# 10ms when SQL logging is on, log only statements above this duration
ns_param logsqlerrors $debug
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 ""
}
}
#
# In case, you want to activate (more intense) SQL logging at runtime,
# consider the two commands (e.g. entered over ds/shell)
#
# ns_logctl severity "Debug(sql)" on
# ns_db logminduration pool1 10ms
#
ns_section ns/db/pool/pool2 {
# ns_param maxidle 0
# ns_param maxopen 0
# ns_param checkinterval 5m ;# check pools for stale handles in this interval
ns_param connections 5
ns_param LogMinDuration 100ms ;# when SQL logging is on, log only statements above this duration
ns_param logsqlerrors $debug
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 ""
}
}
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),
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.
... unable to produce the described logminduration behavior in our NaviServer/NsOracle installation.I was just reading what the code does, whenever the mentioned functions are called. I have currently no installation of nsoracle to help you with.
Log results where we wouldn't expect to see the Debug(sql) entries
When you see lines like
[03/Jan/2023:18:18:48][567831.7faf90d8e700][-conn:lausd:default:2:1-] Debug(sql): SQL(): select :myvalue from dualthen the severity "Debug(sql)" is on. Is maybe some code turning it on? Note, that all severities can be turned on/off at runtime. Do you see this severity turned on in "nsstats.tcl?@page=loglevel"? If so, turn it off over nsstats.
Whenever the line
Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);is executed, and "Debug(sql)" is set, it will print out the content of the variable "query". Without looking into the details, under which conditions this called, i would think this line should not be there.
I am currently abroad and will return to Austria in two weeks, so i have only very limited resources right now.
We do have the severity "Debug(sql)" turned on in our config.tcl. We did this to test the behavior of the pool parameter LogMinDuration which we set to 1000ms and ran a very simple query ("select :myvalue from dual") which should run in less time. However, we still saw the query and bind variable values printed in the log. This indicated to us that LogMinDuration was not working as described in a NaviServer/NsOracle installation.
This is general feedback to help resolve a possible issue with NaviServer/NsOracle installations, but ideally we would like the logging to be turned off completely at a per pool level as was accomplished using the "verbose" parameter in the AOLServer v4.5.1 / NSOracle v2.8a1 installation.
It is not clear to us why the verbose flag no longer works as expected in Naviserver. Is it broken functionality that could be restored? Or, was it deprecated by design? We are hoping there is a way to restore that functionality in either case.
Thanks for taking the time to respond while you are abroad.
We do have the severity "Debug(sql)" turned on in our config.tcl.Have you checked via nsstats the state at runtime of the SQL debug flag as i asked? What is the result?
However, we still saw the query and bind variable values printed in the log.As mentioned above, when the statement including
'SQL(): %s", query);' is on the code-path then it is clear that setting LogMinDuration does not change the behavior.
Since LogMinDuration is handled on a higher level (nsdb, not for a particular driver) and this value just addresses printing out full SQL statements (see above), one cannot expect it to have any effect on the log entry with the bind-vars either. I am not sure, why this log statement is there - maybe this is necessary due to the bind-var handling in Oracle.
One problem with nsoracle seems, that the nsoracle code has a different understanding what the SQL debug flag is for. Is it for debugging the driver internals, or for identifying slow or overly frequent SQL statements. While the other drivers use
"Ns_Log(Debug, ...)" for the first purpose, nsoracle seems to use here "Ns_Log(Ns_LogSqlDebug, ...)". So, maybe many of these should be changed to plain "Debug"?
Since you have a working configuration, it should be easy for you to remove/modify Ns_Log statements in the nsoracle driver. If this yields satisfiable results for your application, I can offer to update the code in the repository later (make a pull request). Touching the source code of nsoracle to remove/alter some log statements does not require a deep understanding of the driver.
We updated nsoracle.c to produce the logging similar to that of AOL4.5.1. Instead of removing the Ns_Log lines, we are checking the verbose flag controlled via logsqlerrors to enable/disable this logging at the pool level. LogMinDuration had no effect on any logging.
nsoralce.c diff:
585c585
\< Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
---
\> if(dbh->verbose) Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
693c693
\< Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
---
\> if(dbh->verbose) Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
965a966
\> if(dbh->verbose) Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
967,968d967
\< /* Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query); */
\< if(dbh->verbose) Ns_Log(Notice, "SQL(): %s", query);
1508c1507
\< Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
---
\> if(dbh->verbose) Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
1587a1587
\> if (dbh->verbose) {
1589a1590
\> }
1590a1592
\> if (dbh->verbose) {
1594a1597
\> }
1706c1709
\< Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
---
\> if(dbh->verbose) Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
1867c1870
\< Ns_Log(Ns_LogSqlDebug, " CLOB # %d, filename %s", i, fetchbuf->buf);
---
\> if (dbh->verbose) { Ns_Log(Ns_LogSqlDebug, " CLOB # %d, filename %s", i, fetchbuf->buf); }
1868a1872
\> if (dbh->verbose) {
1871a1876
\> }
2016c2021
\< Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);
---
\> if(dbh->verbose) Ns_Log(Ns_LogSqlDebug, "SQL(): %s", query);nsstats.tcl?@page=loglevel: The following table shows the current loglevels: Key Value Bug on Debug off Debug(access) off Debug(connchan) off Debug(ns:driver) off Debug(nsproxy) off Debug(request) off Debug(sql) on Debug(task) off Debug(timeout) off Debug(urlspace) off Debug(writer) off Dev off Error on Fatal on Notice on Warning on
Thank you for your help.
