Forum OpenACS Development: QD_LOGGER logs debug message yet all debug parameters are Off

Collapse
1: QD_LOGGER logs debug message yet all debug parameters are Off
Posted by Bart Teeuwisse on 09/17/01 03:01 AM
The QD_LOGGER records many debug messages even though I have all debug paramters in my nsd.tcl file turned 'Off'. Including the verbose parameters.

What could cause the QD_LOGGER to record debug messages regardless? Is there a parameter I'm unaware of?

Collapse
2: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Gilbert Wong on 09/17/01 03:08 AM

Do you have this line in: ns_section ns/parameters:

    ns_param   debug              false
Collapse
3: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Gilbert Wong on 09/17/01 03:11 AM

Hmm. I have everything set off and the QD still logs. Maybe it has something to do with this: https://openacs.org/bboard/q-and-a-fetch-msg.tcl?msg_id=0002Te

Collapse
4: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Ola Hansson on 06/03/02 06:31 PM
Did anyone come up with a way to reduce the level of verbosity of the QD?

I get this in the error log every time someone requests a static page: 

Debug: QD_LOGGER = LEVEL=3= template::adp_parse /web/infogettable-dev//packages/static-pages/www/templates/static 
{body {blah, blah, blah.

...
... followed by ~3000 words - that's the word count on the average chapter in the book my brother's about to publish.

It just seems like an aweful waste of disk space to put it in the server log😊

Collapse
5: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by David Burch on 10/19/02 09:13 PM
Why is this problem being ignored?  With all debug/verbose settings set to off, debug messages still go to the log, causing a 1GB+ logfile rather quickly.
Collapse
6: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Bart Teeuwisse on 10/20/02 08:04 AM
Ever noticed how ns_log works slightly different after OpenACS has been loaded and the server is ready to accept connections?

On a stock AOLServer (incl AOLserver/3.3.1+ad13) ns_log logs each entry with a timestamp (e.g. [19/Oct/2002:23:06:18]) and process (e.g. [-nssock-]). With OpenACS however, both the timestamp and the process are gone.

What has this to do with the QD_LOGGER? Everything because ns_log now also ignores the debug configuration in the [ns/parameter] section of the config file. No matter what configuration ns_log happily writes out all messages to the log file wether they are notices, errors or debug messages.

The problem must be cause by OpenACS as messages are written with timestamp and process during startup of AOLServer but this changes when startup is complete. Any suggestions?

/Bart

Collapse
7: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Jeff Davis on 10/20/02 09:13 AM
Bart, On the servers I have running the log file format does not change.
Also, arjun decreased the ammount of stuff spit out by QD in mid august
and very little should be printed by the query dispatcher at this point.
(even with Debug on).

If you are seeing things like "Notice: Querying (sql query follows)"
or "Notice: dbinit: sql(localhost::DBNAME) ..."
those are not actually from the query dispatcher and are instead being
printed because you have the postgres driver set to verbose.
(the messages have a different header for oracle but same idea there).

Collapse
8: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Bart Teeuwisse on 10/20/02 09:18 AM
Jeff, how odd that it the format of your log messages does not change. Maybe that you could take a look at the current test servers on openacs.hub.org. Both servers show the behaviour I described in my previous post.

/Bart

Collapse
9: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Jeff Davis on 10/20/02 09:50 AM
why don't you email me the config file and I will see if I can see anything there...
Collapse
10: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Bart Teeuwisse on 10/21/02 12:25 AM
At last, the root of this problem has been found. As I mentioned earlier this problem is not limited to the QD_LOGGER alone. It affects all log messages and rightfully demands attention. That it took so long to find a solution is because it was a hard one to track down.

The problem is caused by a combination of Search-OpenFTS-tcl (all versions) and nscache (all versions). Here is what happens:

  1. nscache.so gets loaded and messes with the way tcl files are sourced. Not only are the usual tcl files in aolserver/modules/tcl sourced but now the tcl files in /usr/local/Search-OpenFTS-tcl-x are source too! Why? Beats me!
  2. I don't know exactly when and in which order the tcl files are sourced but what is clear is that the tcl files in /usr/local/Search-OpenFTS-tcl-x are sourced before the ns_log command exists and ns_log gets redefined. Note that the tcl files in /usr/local/Search-OpenFTS-tcl-x are identical copies of the fts stuff in aolserver/modules/tcl. And that fts_index.tcl -which redefines ns_log- does check for the ns_log command to see if it should roll its own ns_log proc.

The current workaround is to remove the fts_*.tcl files from /usr/local/Search-OpenFTS-tcl-x.

/Bart

Collapse
11: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Dan Wickstrom on 10/21/02 01:09 AM
This sounds rather bizarre.  I don't know how nscache ties into this, but the openfts files should not be in aolserver/modules/tcl.  The openfts-driver defines a parameter to indicate where the openfts package is located, and it should be pointing to the  /usr/local/Search-OpenFTS-tcl-x directory.  When the openfts-driver package is sourced, it will then source the openfts-driver files, and this should happen well after nslog has registered its commands.
Collapse
12: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Bart Teeuwisse on 10/21/02 02:43 AM 
Dan,

from AOLSERVER.INSTALL of Search-OpenFTS-tcl-0.3.1:

3. Build aolserver module:


        tar xvzf openfts-tcl-0.3.tar.gz
        cd openfts-tcl-0.3
        ./configure --with-aolserver-src=DIR
        cd aolserver
        make
        cp fts.so [aolserver bin directory]
        cd ..
-->     cp fts_*.tcl [aolserver tcl lib directory]   <--


I was thus under the impression that the openfts-driver sourced 
the files in the AOLServer Tcl lib directory and not the
files in usr/local/Search-OpenFTS-tcl-x.
/Bart
Collapse
13: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Bart Teeuwisse on 10/21/02 02:47 AM
One more thing Dan. The openfts-driver package doesn't need to be installed to observe the wrong ns_log behaviour. Just nscache and Search-OpenFTS-tcl-x is enough.

/Bart

Collapse
14: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Dan Wickstrom on 10/21/02 04:43 AM
There's a mistake in the openfts docs.  The openfts docs are okay for installing without openacs, but for installing with openacs, the copy shouldn't be done.  I'll update the openfts docs and add a note about installing with openacs.  Do you see this kind of behavior on bare-bones openacs install (no openacs)?
Collapse
15: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Bart Teeuwisse on 10/22/02 05:26 AM
Dan,

the ns_log problem does occur on a bare bones AOLServer installation. As I mentioned earlier the solution is to remove either set of fts_*.tcl scripts. That could be the set in the aolserver/modules/tcl directory or the /usr/local/Search-OpenFTS-tcl-x set.

I furthermore found out that the problem only occurs when:
  1. Search-OpenFTS-tcl-0.2 is installed
  2. Two sets of fts_*.tcl scripts are being sourced

Contrary to my earlier post, Search-OpenFTS-tcl-0.3.1 does not cause this ns_log issue, even when 2 sets of fts_*.tcl scripts are installed as per the (incorrect) installation instructions.

/Bart

Collapse
16: Response to QD_LOGGER logs debug message yet all debug parameters are Off (response to 1)
Posted by Dan Wickstrom on 10/22/02 01:48 PM
Okay, now I remember. There was a bug in checking for an existing ns_log command.  If you're using version 0.2, you need to change line 33 of fts_index.tcl to use info commands instead of info proc.  This problem was fixed in the 0.3 release.