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

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

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