Not seeing messages from ApplicationBase on autorestart

dackjaniels

Hi,

I am using the very latest stable Photon version (3-2-10-4248) with C# and Unity3D.
I have a simple Photon server project which contains a peer and an Application which inherits from ApplicationBase.

Within my application class I have implemented the abstract Setup() and Teardown() methods.
In Setup() I configure the log file and Log a simple "Started" message.
In Teardown() I log a simple "Ended" message.

If I start the Photon server application manually using PhotonControl I see the following log entries:

Application start:... <-- This is from ApplicationBase
"Started" <-- This is from my Application class

If I stop the Photon server manually using PhotonControl I see the following entries:

Application is stopping <-- From ApplicationBase
Application stop <-- From ApplicationBase
"Ended" <-- From my Application class

This is exactly what I would expect to see.

However, I also have autorestart switched on so when I rebuild my Application class the Application restarts.

If the application is running and I rebuild, the Photon-Default logs show that the application was restarted with an incremented 'Domain' number.
It also shows that the original application was stopped, so it seems to restart the application correctly.

However, when it comes to the output from ApplicationBase and my Application class the logs only show log entries for the Application Stopping.
There are no entries to indicate that the application has restarted.

If I immediately rebuild I then see log entries from ApplicationBase and my Application class saying that the application has started, but there are no messages showing that the current application instance was stopped.

Each and every time I rebuild I would expect to see two separate log entries indicating that the application was first stopped and was then started, but as I said I only ever see one message or the other.

Anyone have any idea why this is happening?
Am I misunderstanding what restarting does?

Thanks

dackjaniels

Hi Guys,

After several hours of head scratching and reading I found the reason for the behaviour I was seeing.
As I now understand it, the default for log4net is to hold an exclusive lock on the file it is writing the log entries to.
This lock remains in force until the application quits.

When the autorestart feature of photon executes it first starts a new instance of the application and then stops the current instance.
Lets say we rebuild the project 5 times causing 5 auto restarts, we get 5 overlapping instances of the application

1**********
_____2**********
___________3**********
________________4**********
_____________________5**********

In this example, if we manually start the application instance 1 obtains a lock on the log file and correctly logs the start message.
Then we rebuild and instance 2 gets created while instance 1 still holds a lock on the log file. Therefore instance two cannot log a start message.
Instance 1 then closes, logs a Stop message and releases its lock on the log file.
We rebuild again and instance 3 gets instantiated.
The log file is not locked at this point so instance 3 obtains a lock on the file and prints a Start message.
Instance 2 is closed but the log file is locked so cannot log a Stop message.
We rebuild again and instance 4 gets created but cannot access the log file due to the lock instance 3 still has so logs no Start message.
Instance 3 is stopped, logs a Stop message and releases its lock on the log file.
We rebuild a final time and the newly created 5th instance obtains a lock on the log file and logs a Start message.
Instance 4 gets destroyed with no logging being done.


As you can see from the bold text above the cycle of rebuilds/logged messages is:
Start
*Rebuild*
Stop
*Rebuild*
Start
*Rebuild*
Stop
*Rebuild*
Start

After reading this Apache webpage (http://logging.apache.org/log4net/release/faq.html) under the heading "How do I get multiple process to log to the same file?" I realised I can overcome the problem by making a few changes to my log4net.config file.

It's possible to instruct log4net to use a MinimalLock (rather than the default Exclusive lock) which means log4net will lock the file immediately before writing to it and release the lock immediately after writing, rather than holding on to the lock for the life of the application.

In my case I was using a RollingFileAppender which is incompatible with using a Minimal Lock so I first had to change this to a standard FileAppender.
Then, with the appender element of the config file I had to add a lockingModel element as such:

<lockingModel type="log4net.Appender.FileAppender+MinimalLock"/>

All of my logs are now correctly written so when I rebuild and auto restart is triggered, I get a message to say a new instance has been started followed by a message to say the current instance has been stopped.

As I said previously I am totally new to Photon (and log4net) but wanted to share my findings in case it helps anyone else. I imagine this behaviour might cause problems if someone was planning on using the autorestart feature to update a live environment, only to find they have no logs being produced (or some entries are missing).

Regards,
Steve

[Deleted User]

Hi Steve,

first, thank you very much for sharing your findings, and especially for coming back after you've found a solution and giving this real good explanation of Photon & log4net.

I don't have to add much - I only want to explain the reasons for our approach:
First, there is a considerable performance impact when you are using the MinimalLock, vs. the default exclusive lock:

"MinimalLock only acquires the write lock while a log is being written. This allows multiple processes to interleave writes to the same file, albeit with a considerable loss in performance. "

(http://logging.apache.org/log4net/release/faq.html)

Never underestimate the performance impact of logging - it can be *massive*. In a production environment, you should reduce logging to a minimum and should carefully consider if you really need the MinimalLock. (I would always advise against it.)

The second reason is that we feel that the RollingLogFileAppender is really useful, especially in production environments - with the default FileAppender, you need to take care of your ever-growing log files yourself, while the RollingLogFileAppender restricts the size + amounts of log files automatically.

As always, it's a matter of choice - just make sure that you know the pro's and con's of each approach.

[PS: I'm moving this thread to the "Server" section.]

dackjaniels

Hi Nicole,

Thanks for the extra information.
I had noticed the same comments on the Apache site regarding performance and will certainly use the RollingFileAppender if anything I make ever makes it as far as production ;-).

As far as development though, its good to now understand why I was seeing the somewhat strange behaviour.

Steve