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

4: Re: ns_logctl Debug(sql) nsoracle driver and NaviServer (response to 1)

Posted by Gustaf Neumann on 01/04/23 04:50 PM

... 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 dual

then 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.

5: Re: ns_logctl Debug(sql) nsoracle driver and NaviServer (response to 4)

Posted by Raul Rodriguez on 01/04/23 11:05 PM

Hi Gustaf,

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.

6: Re: ns_logctl Debug(sql) nsoracle driver and NaviServer (response to 5)

Posted by Gustaf Neumann on 01/05/23 05:56 PM

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.

7: Re: ns_logctl Debug(sql) nsoracle driver and NaviServer (response to 6)

Posted by Raul Rodriguez on 01/18/23 12:16 AM

Hi Gustaf,
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.