eCAP

adapter works, but I cannot see debug output

Asked by Tom

I have a working adapter, but I cannot see debug information in squid's cache.log file.

Using the clamav Debugger class as my example, I have added the code below which both writes to a file in /tmp and tries to write to the debug stream. I used the /tmp file to make sure my code was getting called.

As you'll see, I tried opening the debug stream with verbosity = ilNormal|flApplication (declaring their use earlier in the file, just like the clamav example) and by using libecap::flXaction | libecap::ilDebug. Neither seem to make a difference.

I did set "debug_options ALL,9" in my squid.conf file and that definitely creates a tremendous amount of information in cache.log, but never have I seen my debug information such as "***TEST*** Adapter::Service::start()" in the example below.

I am getting a valid debug pointer, which I know because I see the value of the debug pointer written to my /tmp file.

Any suggestions? Thanks in advance.

void Adapter::Service::start() {
 std::ofstream tmpFile("/tmp/ecap_log.txt", std::ios::out | std::ios::app);
 tmpFile << "Adapter::Service::start()" << std::endl;

 // std::ostream *debug = libecap::MyHost().openDebug(ilNormal|flApplication);
 std::ostream *debug = libecap::MyHost().openDebug(libecap::flXaction | libecap::ilDebug);
 if (debug)
 {
  tmpFile << "Adapter::Service::start(), debug=" << debug << std::endl;
  *debug << "***TEST*** Adapter::Service::start()";
  libecap::MyHost().closeDebug(debug);
 }
 tmpFile.close();
}

Question information

Language:
English Edit question
Status:
Solved
For:
eCAP Edit question
Assignee:
No assignee Edit question
Solved by:
Tom
Solved:
Last query:
Last reply:
Revision history for this message
Tom (web-l) said : 		#1

I'm still trying to figure this out. I took the Debugger.h & Debugger.cc from the clamav adapter and have been trying to use them. I've found that debug information is printed to squid's cache.log only when called from select locations in my adapter, but not from all locations. I found this by trying to log information at the start of most each Adapter::Service and Adapter::Xaction method. From this I have found that debug information does appear to be written from functions such as Adapter::Service::start() and Adapter::Service::configure(), but the same Debugger line will not print when called from Adapter::Service::wantsUrl.

With the functions that do not appear to work (like Adapter::Service::wantsUrl), I tried both the clamav Debugger code and explicitly calling libecap::MyHost().openDebug() (like shown in my initial questions). I can see that the function is working and returning a pointer to a std::ostream, but writing to that stream does not cause anything to be shown in the cache.log. I am simply copying & pasting the same lines of code which work just fine when called from Adapter::Service::start() and Adapter::Service::configure().

In general, there are more places where I cannot get information written to squid's cache.log file than there are places where I can legitimately write to cache.log. I notice that the clamav example only logs information, via its Debugger class, in the Adapter::Service::configure() function but no other Adapter::Service functions, so it's not possible to say with any certainty that it does or doesn't work there.

What else could be causing the logging to fail when called from places like Adapter::Service::wantsUrl? Any ideas?

Revision history for this message
Alex Rousskov (rousskov) said : 		#2

Most likely, this is a Squid problem or bug. You should debug (using gdb or std::clog output) what Squid is doing. If you use gdb, build Squid with --disable-optimizations.

Revision history for this message
Tom (web-l) said : 		#3

I believe I found the problem. It appears that if any one instance of the host debug stream has not been closed then subsequent, independent calls to a host debug stream will either fail or get queued up (I'm not sure which) until the first stream is closed.

To reproduce my problem stated in the original question, I just had to remove the call to libecap::MyHost().closeDebug(debug). Other streams could still be opened with subsequent calls to std::ostream libecap::MyHost().openDebug(), and the streams do appear to be valid, but nothing is printed out until the first one is closed.

I don't know whether that behavior is "as designed" or not, but I'm not really comfortable with the core squid code so I'm probably just going to move on with my work but leave this comment here for future reference.

Revision history for this message
Alex Rousskov (rousskov) said : 		#4

Debugging stream is valid for one debugging "record" (whatever that means to you, but usually just one line) only. It is not something you leave opened to be reused for multiple records.

 Squid does not queue debugging stream requests. Feel free to file a "Squid allows to open multiple concurrent eCAP debugging records but does not support them" bug with Squid bugzilla if you think Squid should either return a nil stream pointer until the first record is closed or support concurrent record logging.