LoggerPro stop logging after application pool recycling within the IIS  

  RSS

Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
2 May 2017 8:57  

Hello,

I have some problems with LoggerPro in an ISAPI Webservice project if I recycle the application pool within the IIS. (this happens automatically every 1740 minutes). After recycling there are no new entries in the logfile.

Steps to reproduce:

- I have created a new Webservice (SOAP-Server-Application as ISAPI) with example methodes.
- Within this Webservice I use the Logger.
- I have created a client which constantly calls the Webservice. (4 different threads in a loop)
- If I run the client everything is fine. I see a lot of new log entries.
- If I click on "recycle" in IIS Application Pool the Logger stops writing to the output file (the Webservice works normally)

I have also created a simple demo application which demonstrates the problem. It is reproducable. Configure IIS for this ISAPI. Start the TestClient, click the Button. The Log file is created and you can see entries like 1, 2, 3, 4 ... Now recycle the application pool. Look in the Log file. There are no new entries.

I'm using Delphi 10.1 Berlin Update 2 with the latest (I think) Logger pro units.

Regards

Mathias

You can find the demo here: https://www.facebook.com/groups/delphimvcframework/1334175316665604/  


ReplyQuoteLikeReport
Daniele Teti
Eminent Member
Joined: 8 months  ago
Posts: 46
3 May 2017 9:28  

Hi Mathias, did you tried to use also other appenders? Do the others appender still work after the pool recycle?

It may be an issue related to the fileappender or to the loggerpro instance itself. However, I don't know, in terms of dll calls, what means "poll recycle"... did you?

 

DT

Daniele Teti
CEO & CTO @ bit Time Professionals
Embarcadero MVP
Books Author


ReplyQuoteLikeReport
Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
4 May 2017 10:57  

Hello,

I have tested the OutputDebugStringAppender and it works after recycling. It is a bit tricky but I could debug it. Steps to reproduce:

  • start IIS
  • start TestClient.exe and click the start button
  • in Delphi open the TestWebservice.dll project and connect to process w3wp
  • you can see OutputDebugString messages
  • click on recycle within the IIS
  • in delphi the ISAPI dll is unloaded and the debugger stops
  • again connect to process w3wp
  • you can see OutputDebugString messages again

I think if you recycle an application pool in the IIS all ISAPI dlls are unloaded/destroyed and the w3wp.exe is shutting down. You can see this in the debugger. 

I have made a new simple test which could better show the problem:

If You load a website from the IIS a w3wp.exe process is startet (one w3wp.exe per application pool). If You recycle the application pool the IIS starts a new one. AFTER this the old one is destroyed. You can see this in the task manager. That means the "old" LoggerPro has still a lock on the log file while a new one is startet. Right? What can we do?

Regards
Mathias


ReplyQuoteLikeReport
Daniele Teti
Eminent Member
Joined: 8 months  ago
Posts: 46
6 May 2017 0:06  

Yes, IMO what you supposed is correct.

So, what we could do is to create a "retry" mechanism in 

function TLoggerProFileAppender.CreateWriter(const aFileName: string): TStreamWriter;

or simply use a filename with the PID in the name (so that with new instance you have different log filename). While the second solution is not elegant nor "clean" it could be a good and easy test to verify our diagnose.

Try to put in your LoggerPro configuration somethig like this:

 _Log := BuildLogWriter([TLoggerProFileAppender.Create(10, 5, [TFileAppenderOption.IncludePID])]);

Let me know if it solve the problem, if so, we can think a better solution to the IIS problem.

DT

 

Daniele Teti
CEO & CTO @ bit Time Professionals
Embarcadero MVP
Books Author


ReplyQuoteLikeReport
Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
8 May 2017 9:05  

Hello Daniele,

did You need no sleep? You are a hard working guy. Respect.

I have tried "TFileAppenderOption.IncludePID" and it works. Thanks for the hint.

So an other/a better solution based on that would be very nice. But I have no idea how this could be solved using the same filename.

Regards
Mathias


Daniele Teti liked
ReplyQuoteLikeReport
Daniele Teti
Eminent Member
Joined: 8 months  ago
Posts: 46
8 May 2017 11:25  

Hi Mathias, I work in a very "fluid" way (and I sleep a lot 🙂 ). However thank you for your appreciating words.

 

About the solution, I was thinking about a "resume" mechanism which should allows to resume a stopped appender. The appender is disabled if the "setup" method call raise exceptions. So I think that from time to time (let's say 2 seconds) the main engine should try to resume the disabled appenders. I'm working on such kind of solution also for remote appenders over TCP/IP and HTTP/REST.

If you want to suggest other solutions, feel free to do it.

 

Best regards

 

DT

 

Daniele Teti
CEO & CTO @ bit Time Professionals
Embarcadero MVP
Books Author


ReplyQuoteLikeReport
Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
11 May 2017 14:14  

I have not really a good idea to solve this problem, yet.

One idea is some kind of "start delay". If the logger starts and can't get access to the logfile the "collector" thread will collect all log messages and every x seconds it will try to access the logfile again. If it does not get access after a "long" time a new/an other log file could be used?


ReplyQuoteLikeReport
Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
30 May 2017 7:47  

Any news to this problem?


ReplyQuoteLikeReport
Daniele Teti
Eminent Member
Joined: 8 months  ago
Posts: 46
31 May 2017 9:21  

Hi, LoggerPro 1.1.1 has been updated with a mechanism that should solve your problem. In the next hours dmvcframework RC6 will be published and will include the nre loggerpro version. If you are impatient, you can update loggerpro version in the dmvcframework RC5 folder.

 

best regards

Daniele Teti
CEO & CTO @ bit Time Professionals
Embarcadero MVP
Books Author


ReplyQuoteLikeReport
Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
1 June 2017 14:05  

Hello,

I have updated to 1.1.1 It "works better" now. After recycling logging starts again. But I lost some log entries.

My test client sends an integer to the service (for I := 1 to 100). Value I is written to log file. If I start client and click recycle in IIS and check the log I get entries like: 1, 2, 3, 4, 5, 6, 17, 18, 19, 20, 21, 22, 35, 36, 37 ...

Is it by design or bug?

Regards
Mathias


Daniele Teti liked
ReplyQuoteLikeReport
Daniele Teti
Eminent Member
Joined: 8 months  ago
Posts: 46
1 June 2017 14:25  

Does the client return any errors when IIS recycle the pool? The behaviour implemented should not loose log messages...

Maybe that the client simply doesn't have a server to talk with.

 

DT

Daniele Teti
CEO & CTO @ bit Time Professionals
Embarcadero MVP
Books Author


ReplyQuoteLikeReport
Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
2 June 2017 8:54  

No error, no exception. In my opinion the IIS spawns a new worker process, routes all incoming request to the new process and than terminate the old process. I think there are no missing requests.


ReplyQuoteLikeReport
Mathias Pannier
Active Member
Joined: 7 months  ago
Posts: 17
16 June 2017 9:33  

Hello Daniele, any news?


ReplyQuoteLikeReport
  
Working

Please Login or Register