[tbnl-devel] Odd behavior (socket leak)

[pete-tbnl-dev at kazmier.com]

I could use a sanity check.  I've been trying to track down a problem
with either mod_lisp (for apache 2.0) or TBNL.  Since I was not able to
isolate my problem, I decided to revert back to Apache 1.3 and mod_lisp
2.33 (for Apache 1.x).  The problem is that I think I'm seeing some odd
behavior and was hoping someone else could confirm.

In a nutshell, I added a simple print statement to APACHE-LISTEN in
TBNL's modlisp.lisp file so I would know when this function was being
invoked.  I also added print statements before each significant line in
that function so I could see what the heck was going on.  Here is my
version of that function:

(defun apache-listen (*apache-stream* command-processor &rest args)
  "Listens on *APACHE-STREAM* for commands from mod_lisp. Packages the                                                                   
command using GET-APACHE-COMMAND and passes it to the                                                                                    
COMMAND-PROCESSOR function \(which is PROCESS-APACHE-COMMAND). ARGS                                                                      
are ignored. Designed to be called by a KMRCL:LISTENER object."
  (declare (ignore args))
  (format t ">>>>>>> Opening stream~%")
  (force-output)
  (let ((*close-apache-stream* t))
    (unwind-protect
      (loop for *apache-socket-usage-counter* from 0
            for command = (debug-value *command* (get-apache-command))
            while command
            do (cond ((ignore-errors
                        (format t ">>>>>>> Processing command ~A~%" (subseq command 0 3))
                        (force-output)
                        (funcall command-processor command))
                      (ignore-errors
                        (format t ">>>>>>> Flushing stream cuz no errors occurred for ~A~%" (subseq command 0 3))
                        (force-output)
                        (force-output *apache-stream*)))
                     (t
                      ;; if an error occured during processing of                                                                        
                      ;; COMMAND we close this particular connection                                                                     
                      ;; to Apache                                                                                                       
                      (ignore-errors
                        (format t ">>>>>>> Closing stream cuz error occurred for ~A~%" (subseq command 0 3))
                        (force-output)
                        (setq *close-apache-stream* t))))
            until *close-apache-stream*)
      (ignore-errors
        (format t ">>>>>>> Closing stream - no more commands~%")
        (force-output)
        (kmrcl:close-active-socket *apache-stream*)))))

Now, back in Apache 1.3 world, I hit a webpage that invokes the mod_lisp
handler and thus TBNL.  I see the opening, processing, and flushing
messages.  The next time I hit the page (30 seconds later), I see the
same thing again.  I never see a closing message, and a look at 'netstat
-an | grep 3000' indicates that another socket has been allocated and is
in a connected state.  I repeated this process for a few minutes and got
up to 6 connected sockets without ever seeing a closing message.  If a
subsequent hit comes close enough, then it will reuse the socket and
I'll only see a processing and flusing message (no opening message).

I'm using SBCL (with multithreaded support).  I'll continue debugging
in the meantime and I'm going to start with fresh copies of everything
to make sure I have not inadvertently affected things while debugging my
original problems with Apache 2.x (which still appear when I use Apache
1.x).  

I'll summarize those problems as well (as I think they may be related), 
essentially, I have a web page that has three stylesheets included in 
it (and are processed by TBNL as well), so basically, TBNL receives 4 
requests in a fairly short amount of time.  After adding debugging code
to the mod-lisp.c Apache module, I've confirmed that mod-lisp sends the 
4 requests to TBNL.  Unfortunately, mod-lisp never receives any 
headers from TBNL for the last request although I've seen TBNL send them 
(I just didn't realize until now that they were probably going over
different sockets).

In any case, I've been banging my head all day, I need a break, but it
would be appreciated if someone could either confirm or deny the opening
of multiple sockets while never closing any of the old ones.  Its easy
to see via a 'netstat -an | grep 3000' (or whatever port you run it on).

Thanks,
Pete