Server Error 500

[urayoan]

Hello
  I am having a Web Server error 500 in a NetTalk Server after it is running for a while. Seeing the web server embed i found this (code below) with the message Server Busy, try again shortly.

  Does NetTalk server it is supposed to recover from that error? As far as i know, I need to restart the webserver to start serving pages again.

    loc:RequestData :=: p_RequestData
    If (self.performance.NumberOfThreads >= self.MaxThreads and self.MaxThreads > 0) or loc:shuttingDown
        if loc:RequestData.RequestMethodType <> NetWebServer_DELETESESSION and PoolWaiting = 0
          if not self.WebSocketServer &= null and self.WebSocketServer.IsWebSocket(self.packet.SockID)
            ! do not send invalid reply, it's a malformed packet in the wss protocol.
          else
            self.SendError(500,'Server Busy','Server Busy, try again shortly')
          end
          self._PerfEndThread(0,0,500)  ! Errors are counted, but otherwise not included in stats
          do UpdateStats
          dispose(p_RequestData.DataString)
        end
      return
    End

[Bruce]

Hi Ura,

You'll get this effect if you are "leaking threads".
To confirm, check the log to see what thread numbers are being allocated (and ideally what request triggered the start of the leak.)
Also, on the performance tab you can see "current threads" = 100 (or whatever your max is set to) which generally indicates a thread leak.

In a "normal" case, yes, the server will recover - as threads complete so the system becomes available again - but usually in cases like this there's a thread leak going on.

cheers
Bruce

[urayoan]

Bruce, in that web server, the threads I assigned are 20, and when the error occurred the number stays in 20. So if I understand correctly, that indicates a leak occurred. Right?

Another symptom when happen is, I see the same call again and again and again in the logs, that means that call that is repeating could be the culprit?

Thanks for the help

@ Urayoan

[Bruce]

>> So if I understand correctly, that indicates a leak occurred. Right?

20 is quite low, but yes, it's either
a) a leak or
b) your threads take a long time to complete, and all 20 are busy.

Assuming the request is "fast" I would assume the first one.

>> I see the same call again and again and again in the logs, that means that call that is repeating could be the culprit?

Maybe, but not really. The request to look into is the last one assigned to thread 3. thread leaks can happen in two different ways;

a) something is assigned to a thread which "stalls" the server. New requests come in, but are unable to complete. So all the threads are allocated and used up. What you are looking for in this case is the "trigger" request - the first thread that "doesn't complete". So typically thread 3, but could be nearby (4, 5 etc). you're looking for the first thread number that "never gets allocated again". That's the one I typically look closest at (although it might be the one right before that which causes the problem.)

b) an individual request "stalls" just one specific thread. It doesn't affect the others, but the thread never completes. so, for example, if a thread stalls with a MESSAGE then it's just stopped. The other threads carry on being allocated, and the system continues. When 20 threads have stalled in this way then your system is stalled. In this case you should see this pattern in the log, 3 stops being allocated, then sometime later 4, then later 5 and so on. Look at the "last request" to each thread for clues.

Cheers
Bruce

[urayoan]

Thank you Bruce. Thing is, the server is kind of very busy, and the last call can be a hundreds or more down very fast. I included the web server when it stalls with the error and that call is the one I see constantly when the server stops responding.

I did bump up the threads to 100 to see if the server at least holds better until I find the problematic call. The server has a request to make reports for the users and I am aware that that call is more slow than others.

Check when you had the chance the screenshot and if it hit any bells, please let me know

PD. When the server has the error, that call shows and keep moving the log, so it not stays there and try to process the call


Thank you again @ Urayoan

[Bruce]

That GPF is on thread 7, so that's likely the trigger for it to then have a problem.
So 2 things;

a) perhaps turn on the better stack trace stuff;
https://clarionhub.com/t/how-to-improve-the-call-stack-when-your-program-gpfs/188

b) turn on log-to-disk, so you can see the request that triggers the GPF thread.

cheers
Bruce

[urayoan]

Thank you very much Bruce. That would help me out pin the culprit better! Ill keep posted what I found

[urayoan]

Bruce a question related to this, the screen of the GPF was created with the same method posted by Mark in Clarionhub. The web server having problems uses DLLs from other parts of our app.

a) perhaps turn on the better stack trace stuff;
https://clarionhub.com/t/how-to-improve-the-call-stack-when-your-program-gpfs/188

Given the information of for that to work, all the DLLs need to be in the same mode too?

b) turn on log-to-disk, so you can see the request that triggers the GPF thread.

I think I never used the Screen & Disk option of NetTalk, can I have a hint where does NetTalk writes those logs?

UPDATE: about the Log File, RTFM (Read The Fantastic Manual), Building Apps With NetTalk. Had it all.

Thank you @Urayoan

[urayoan]

Bruce, given what I learn in the past few days, this is what i capture related to the possible thread leak and procedure. How can I handle properly?

I do not delete manually any session, the webserver is taking care of if for me.

[Bruce]

hmm.

So yes, that would lean towards the error happening in a call to DeleteSession. Which, yes, is triggered internally.
Do you have any embed code in webHandler? Anything in any of the deletesession or notifydeletesession methods?

Cheers
Bruce

[urayoan]

Hello Bruce:
  The only embded I have in the web handler is this, located in the ErrorTrap PROCEDURE

    p_web.Trace('Error Trap: ' & errorStr & ' ' & functionName) 

[Bruce]

anything in WebServer procedure?

but assuming not, then the next step would be to determine what in the delete is causing a problem - ie an example...

[urayoan]

anything in WebServer procedure?

but assuming not, then the next step would be to determine what in the delete is causing a problem - ie an example...

In the WebServer procedure I have some embeds, but mostly the ones who sets defaults to the specific client and the program start. Reding from INI file and open two files to read some company defaults and close again when the variables are set.

Recently to at least a work around the problem I did this (check code). If i detect and error 500 in the server I close and let the watchdog run the service again. Is not clean, but at least if the server goes Error 500 at an unfortunate hour, it start again. (The simple watchdog I use for the benefit of others here https://w-shadow.com/blog/2009/03/04/restart-on-crash/). If there is a clean way to do that, It will be appreciated.

I will check and try to make an example, In this case If you tell me what can help you out It could be great to try to compose whats needed to make this happen.

  loc:RequestData :=: p_RequestData
  If (self.performance.NumberOfThreads >= self.MaxThreads and self.MaxThreads > 0) or loc:shuttingDown
    If loc:shuttingDown = 0 and self.PoolSize
      Loop Index = 1 to self.PoolSize
        If self.ThreadPool[Index].Thread <> 0 and self.ThreadPool[Index].Status = Net:PoolWaiting and Self.ThreadPool[Index].ServerID = self.ServerID
          PoolWaiting = Index
          Break
        Elsif self.ThreadPool[Index].Thread = 0 and StartNewPool = 0! is there a space in the pool for another thread?
          StartNewPool = Index
        End
      End
    End
      if loc:RequestData.RequestMethodType <> NetWebServer_DELETESESSION and PoolWaiting = 0
        if not self.WebSocketServer &= null and self.WebSocketServer.IsWebSocket(self.packet.SockID)
          ! do not send invalid reply, it's a malformed packet in the wss protocol.
        else
          self.SendError(500,'Server Busy','Server Busy, try again shortly')
          HALT() !En lo que logramos onseguir cual es el procedure que falla
        end
        self._PerfEndThread(0,0,500)  ! Errors are counted, but otherwise not included in stats
        do UpdateStats
        dispose(p_RequestData.DataString)
      end
    return
  End

[urayoan]

Related to this, it is possible or pertinent in this structure to ramp up the field description to a higher length? I need the field larger to fit the request complete when it goes to disk. Is truncating the request in the log

LogQueue        QUEUE,PRE(LogQ)
Port              STRING(30)
Socket            LONG
Thread            LONG
Date              LONG
Time              LONG
Desc              STRING(4096)
                END

[Bruce]

yeah, you can bump that up, and I'll bump it up in the next build.