Second app logs to log file of first app while first app running - Windows

[1marc1]

Symptoms:

• When I run app1.py it logs to app1.log.
• When I run app2.py, it logs to app2.log.
• When I run app2.py while app1.py is running, app2.py starts sending its logs to app1.log.

I am using logger_tt version 1.5 on Python 3.9. This happens in a Windows environment only. When running on Linux, app2.py will always log to app2.log, even when app1.py is running.

Below is a minimal example that illustrates the issue. It is to be said that in my actual programs I am using multi-processing and multi-threading. There is also shared code between the actual programs that uses the logging facility.

#!/usr/bin/env python

from time import sleep
from logging import getLogger
from logger_tt import setup_logging

setup_logging(config_path='log_config.json', log_path='app1.log', use_multiprocessing=True)
logger = getLogger('app1')

while True:
    logger.info('App1 is doing stuff')
    sleep(5)

#!/usr/bin/env python

from logging import getLogger
from logger_tt import setup_logging

setup_logging(config_path='log_config.json', log_path='app2.log', use_multiprocessing=True)
logger = getLogger('app2')

logger.info('App2 is doing stuff')

The contents of log_config.json are as follows:

{
  "version": 1,
  "disable_existing_loggers": false,
  "formatters": {
    "simple": {
      "format": "%(asctime)s %(name)-8s %(levelname)-8s %(processName)-10s %(message)s"
    },
    "brief": {
      "format": "[%(asctime)s] %(levelname)s: %(message)s",
      "datefmt": "%Y-%m-%d %H:%M:%S"
    }
  },

  "handlers": {
    "console": {
      "class": "logging.StreamHandler",
      "level": "INFO",
      "formatter": "brief",
      "stream": "ext://sys.stdout"
    },

    "error_file_handler": {
      "class": "logging.handlers.TimedRotatingFileHandler",
      "level": "DEBUG",
      "formatter": "simple",
      "filename": "logs/log.txt",
      "backupCount": 3,
      "encoding": "utf8",
      "when": "midnight"
    }
  },

  "loggers": {
    "urllib3": {
      "level": "ERROR",
      "handlers": ["error_file_handler"],
      "propagate": false
    }
  },

  "root": {
    "level": "DEBUG",
    "handlers": ["error_file_handler"]
  },

  "logger_tt": {
    "suppress": ["exchangelib"]
  }
}

[Dragon2fly]

Hi @1marc1

Because the SO_REUSEADDR option is set on the logging socket server,
the weird thing that you described happened.

So to run multiple independent multi-processing applications with logging at the same time,
and each of them writes logs into a different file,
currently, you have to use logger_tt version 1.7+ and set the port to a different number for each application.

You could set the port directly in the setup_logging as follows:

#!/usr/bin/env python

from logging import getLogger
from logger_tt import setup_logging

setup_logging(config_path='log_config.json', log_path='app2.log', use_multiprocessing=True, port=6789)
logger = getLogger('app2')

logger.info('App2 is doing stuff')

Of course, the port number must not be already used by other applications.

[1marc1]

Thank you so much for your continued support. I upgraded to logger_tt 1.7.3 and set the port number. It now works as expected!
I did notice one side effect of the upgrade. Closing the application takes about 2 seconds longer than when I was running with version 1.5. Any idea what could be causing that? I notice this effect both on Linux and on Windows. I double checked this effect by downgrading back to version 1.5. When using version 1.5 the application closes instantly.

[1marc1]

Further to my comment, it is particularly evident when adding the statement print('Done') to the bottom of app2.py. When using logger_tt 1.5 the command prompt is instantly returned. When using logger_tt 1.7.3, there is a significant delay between printing Done and the return of the command prompt.
Do you have any idea what could be causing this and what could be done to resolve it?

[Dragon2fly]

Hi @1marc1

TLDR:
There is no difference between 1.5 and 1.7.3 regarding this matter.
It will happen if we use a port number that is not the default one (9020) and because there is a 5 seconds connection timeout.
As for why there is a difference between the default port and the one we use, I don't know yet.
You could mitigate this issue by setting daemon_threads = True for the LogRecordSocketReceiver thread or setting the connection timeout to 1. Or just leave it there as it already works as designed.

Daemon thread (not recommended):

#!/usr/bin/env python

from logging import getLogger
from logger_tt import setup_logging
from logger_tt.core import LogRecordSocketReceiver    # <--- new

LogRecordSocketReceiver.daemon_threads = True         # <--- new
setup_logging(config_path='log_config.json', log_path='app2.log', use_multiprocessing=True, port=6789)
logger = getLogger('app2')

logger.info('App2 is doing stuff')

This will cause the main thread to exit immediately, even if there may be a log waiting to be sent to the logger thread.
On the other side, the logger thread will also exit shortly after the main thread died (as designed).
This means after handling logs from this child process, it won't wait for the incoming log data from the other child processes anymore. Thus you may suffer the loss of logs which is usually the uncaught exception one. Ough!

Set the connection timeout to 1:

#!/usr/bin/env python

from logging import getLogger
from logger_tt import setup_logging
from logger_tt.core import LogRecordStreamHandler  # <--- new

LogRecordStreamHandler.timeout = 1                 # <--- new
setup_logging(config_path='log_config.json', log_path='app2.log', use_multiprocessing=True, port=6789)
logger = getLogger('app2')

logger.info('App2 is doing stuff')

This works well assuming all the necessary logs from the main process's main thread and child processes are sent to the logger thread within 1 second.

[1marc1]

Hi @Dragon2fly,

I have been running some test on Linux, using logger_tt 1.7.3. Here are the results.

When not specifying a port number in setup_logging or when specifying port number 9020, when I run time ./app2.py, this is the output:

$ time ./app2.py
Done

real	0m5.106s
user	0m0.080s
sys	0m0.020s

When I set the connection timeout to 1 and I don't specify the port (or I specify it as 9020), the results are similar:

$ time ./app2.py 
Done

real	0m5.111s
user	0m0.090s
sys	0m0.016s

When I use the not recommended daemon thread and either don't specify the port number or set it to 9020, then this is the result:

time ./app2.py 
Done

real	0m0.094s
user	0m0.085s
sys	0m0.008s

We can see that with the daemon thread the command prompt is returned quickly. However, with the daemon thread, the App2 is doing stuff message does not end up in the log file.

FWIW, if I use both the daemon thread and the connection timeout, the behavior is like specifying only the daemon thread: the application exists quickly and the message does not appear in the log.

The results are the same when I specify a completely different port such as 6789.

[Dragon2fly]

Hi @1marc1 ,

Sorry, I forgot to mention that you need to comment out the below line for it to work.
Otherwise, it will just wait 5 seconds as before no matter what timeout you set.

logger_tt/logger_tt/core.py

Line 313 in ef5a97d

self.connection.settimeout(5)

Please test again. If there is no other problem, I'll push it into the next version.

We can see that with the daemon thread the command prompt is returned quickly. However, with the daemon thread, the "App2 is doing stuff" message does not end up in the log file.

Yeah, you've just confirmed that the daemon thread is not a recommended way.

[1marc1]

Thanks @Dragon2fly, after commenting out that line it all seems to work, but you have to specify the connection timeout lines in app2.py. It then doesn't seem to matter if you specify a port or not. In my testing I (a) did not specify a port, (b) specified port 9020, (c) specified port 9021 and (d) specified port 6789. In all instances the App2 is doing stuff message shows up in the log file and the typical result is this:

$ time ./app2.py 
Done

real	0m1.111s
user	0m0.092s
sys	0m0.016s

Now, if I leave the following lines out of app2.py, then the application does not exit at all and seems to be stuck. I pressed CTRL+C after 40 seconds to terminate the application.

from logger_tt.core import LogRecordStreamHandler
LogRecordStreamHandler.timeout = 1

If I change line 313 of core.py to self.connection.settimeout(1) and I don't include the two lines (above) for the connection timeout, then the message makes it to the log and the typical output is:

$ time ./app2.py 
Done

real	0m1.105s
user	0m0.091s
sys	0m0.013s

Not sure what the best way is to further update your code, but based on these (limited) results, it seems that the best approach would be to update line 313 of core.py as it will not require the program using logger_tt to implement the connection timeout. However, I don't know if there are other implications to changing line 313.

[Dragon2fly]

Hi @1marc1

It then doesn't seem to matter if you specify a port or not. In my testing I (a) did not specify a port, (b) specified port 9020, (c) specified port 9021 and (d) specified port 6789. In all instances the App2 is doing stuff message shows up in the log file and the typical result is this

There are 2 separate things here.

• Set the timeout to 1 second and it will wait for 1 second then exit after the main thread dies no matter what the port was.
• Changing the port in App2 will ensure it will always send logs to App2's log server and thus logs separately from App1.

Now, if I leave the following lines out of app2.py, then the application does not exit at all and seems to be stuck. I pressed CTRL+C after 40 seconds to terminate the application.

After the socket is closed, the address: port resource is not released immediately. It is moved into TIME_WAIT state.
It just hangs in there for a little while, for how long is platform dependence.

The SO_REUSEADDR option is used to ensure that when you restart the app, it can instantly reuse the same address: port even when the old socket is in TIME_WAIT state. logger-tt didn't use that option to be able to log from multiple multiprocessing apps at the same time.

That being said, the SO_REUSEADDR option doesn't behave the same on all platforms regarding two or more sockets binding to the same address: port at the same time. The log message could be delivered to one of the sockets arbitrarily, or by some other rule, delivered to one specific socket. Refer to this for more detail.

If I change line 313 of core.py to self.connection.settimeout(1) and I don't include the two lines (above) for the connection timeout, then the message makes it to the log

So, not setting the port and getting the log message to the right file is really a hit or a miss.
I would recommend always setting the port to be sure that it has the same behavior across platforms.

Not sure what the best way is to further update your code, but based on these (limited) results, it seems that the best approach would be to update line 313 of core.py as it will not require the program using logger_tt to implement the connection timeout. However, I don't know if there are other implications to changing line 313.

Changing line 313 is fine. It has the same effect as adding the 2 lines that you tried.
However, in the future, I'm thinking of removing that line and setting the default timeout in the class, so that users could change it from the outside if needed. I'm also thinking of setting daemon_threads=True and keeping the logger thread alive 5 seconds after the main thread dies

[1marc1]

Cool. I am keen to see your updates implemented!