More than one logfile created when using multiprocessing ( exe built with pyinstaller)

Question

More than one logfile created when using multiprocessing ( exe built with pyinstaller)

Opened this issue 2 years ago · 22 comments

Hello.

I am using logger_tt module with python code having multiprocessing approach in windows environment. While running the code from python interpreter , one logfile is created as expected.

But when I build the exe ( using pyinstaller) and execute it using a windows command prompt , number of logfile created are more than one. I am creating three processes, and the four logfiles are created.
Though only one logfile contains all the logs (including print, etc..). The other logfiles created just contains following text (with different time stamps) :

[2022-11-02 10:58:44] [root:190 DEBUG] New log started_
[2022-11-02 10:58:44] [root:191 DEBUG] Log config file: configs\log_config.json

Answer 1 · 2022-11-03T07:55:21.000Z

Hi, could you include your log config and the name of the others 3 log files?

Answer 2 · 2022-11-03T09:02:06.000Z

Hi , yes sure.
I have attached the file here with changed extension (csv, .config is not allowing)

The name of the files:
LOG_2022-11-02_10-57-58.log ( complete content)
LOG_2022-11-02_10-58-48.log (extra file)
LOG_2022-11-02_10-58-44.log (extra file)
LOG_2022-11-02_10-58-40.log (extra file)

log_config.csv

Thanks

Answer 3 · 2022-11-03T09:59:48.000Z

Hi, can you also include the code that you config the logger? setup_logging(...)
Did you put it out or inside the if __name__ == "__main__"?
Are you running on Linux or Windows?
Just a minimal reproducible code would be very helpful.

Answer 4 · 2022-11-06T09:38:01.000Z

hi @81piyush, any update on your input?

If you are not using the latest logger_tt please upgrade and try again.
From your log filename, you are creating the name dynamically by a function.
You can reference issue #5 for an alternative solution with the same problem if it still persists.

Answer 5 · 2022-11-07T13:23:27.000Z

Hi @Dragon2fly , apologies for the delayed reply.

The setup_logging function is getting called in the following manner:
setup_logging(config_path=r"./configs/log_config.json", log_path=str_file_path, use_multiprocessing=True,
full_context=1, capture_print=True)

It is outside the if name == "main"
I am using it on Windows pc. It is updated to the version 1.7.0

I will go though the mentioned issue (#5 ) to check the changes accordingly.

If it still persists , I will share the reproducible code as well. Thanks for the suggestions.

Will keep updated about the same.

Answer 6 · 2023-04-01T01:06:32.000Z

Hey @Dragon2fly ,

I have tried to integrate logger_tt into our project, oceancabbage/RimSort

If you have a moment, do you think you could take a look at my implementation of your logger? All platforms have no issue with my implementation when running from source with the Python interpreter.

On Linux, it behaves as expected both when run from python interpreter, and PyInstaller directly.

On Windows, it behaves as expected up until I try to launch a process, and it launches the process without exception, but then some really wonky stuff happens:

On MacOS, it does not launch the process which I believe is failing because of this unhandled exception. I have similar behavior to Windows with the actual log file and what appears to be happening with the logger itself, except I was actually able to get a stacktrace out of it since running a Unix executable in a terminal is actually apparently much more informative than a Windows exe from PyInstaller ;)

$ ./RimSort 
[2023-03-31 19:52:54] WARNING: Running using PyInstaller bundle
QPixmap::scaled: Pixmap is a null pixmap
Traceback (most recent call last):
Traceback (most recent call last):
  File "RimSort.py", line 33, in <module>
  File "RimSort.py", line 33, in <module>
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 355, in __init__
  File "logger_tt/core.py", line 355, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 466, in server_bind
  File "socketserver.py", line 466, in server_bind
OSError: [Errno 48] Address already in use
[87774] OSError: [Errno 48] Address already in use
Failed to execute script 'RimSort' due to unhandled exception: [Errno 48] Address already in use
[87775] Failed to execute script 'RimSort' due to unhandled exception: [Errno 48] Address already in use
[87774] [87775] Traceback:
Traceback (most recent call last):
  File "RimSort.py", line 33, in <module>
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 355, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 466, in server_bind
OSError: [Errno 48] Address already in use

Traceback:
Traceback (most recent call last):
  File "RimSort.py", line 33, in <module>
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 355, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 466, in server_bind
OSError: [Errno 48] Address already in use

Perhaps it is a misconfiguration on my end?

https://github.com/oceancabbage/RimSort/blob/ba71c6d746e9c9892900902de74cce6e33c57993/RimSort.py

This is happening when a multiprocessing.Process is created. Only appears to have issue with spawn() - Linux has no issues with fork()

Here is my logger_tt config: https://github.com/oceancabbage/RimSort/blob/ba71c6d746e9c9892900902de74cce6e33c57993/data/logging_config.json

Defining a port in my config does not resolve the issue on MacOS. Since Windows appears to either handle the exception, or not have it at all (it launches the process) - I am entirely unsure what is going on. But I think I might be missing something with logger_tt

Answer 7 · 2023-04-02T01:10:57.000Z

Hi @twstagg,

On Windows, you can open a command prompt and run your exe from there to get the error message if there is any.
Could you try and provide that messages too, if any?

Anyway, from your MacOS log, I suspect that logger-tt didn't recognize that it was running in the child process.
Thus it tried to launch the logger server again and failed as the server was already launched in the main process.

This needs further digging. But first, could you print out the child process name by using print(multiprocessing.current_process().name)?
Put it in your child process's code and see if it is different before and after pyinstallered

Answer 8 · 2023-04-02T01:21:11.000Z

@Dragon2fly

On Windows, you can open a command prompt and run your exe from there to get the error message if there is any. Could you try and provide that messages too, if any?

On Windows, I am not seeing any Unhandled Exception like I do on MacOS.

Anyway, from your MacOS log, I suspect that logger-tt didn't recognize that it was running in the child process. Thus it tried to launch the logger server again and failed as the server was already launched in the main process.

This needs further digging. But first, could you print out the child process name by using print(multiprocessing.current_process().name)? Put it in your child process's code and see if it is different before and after pyinstallered

This is what I see when I run it from Python 3.9.6 interpreter. The actual log file contains the output without issue, and the game process I am launching is created successfully. You can even see the logging work in the StreamHandler to stdout that i have setup:

Steamworks wrapper: <_MainProcess name='MainProcess' parent=None started>
Main script: <_MainProcess name='MainProcess' parent=None started>
[2023-04-01 18:19:34] WARNING: Running using Python interpreter
Steamworks wrapper: <_MainProcess name='Process-1' parent=None started>
Main script: <_MainProcess name='Process-1' parent=None started>
[2023-04-01 18:19:50] WARNING: Process-1 Unable to initiate Steamworks API call. Steam is not running!
[2023-04-01 18:19:50] WARNING: Process-1 Unable to launch game with Steamworks API. Please close your game and try to launch again after opening Steam.

This is what I see after running it from PyInstaller:

Steamworks wrapper: <_MainProcess name='MainProcess' parent=None started>
Main script: <_MainProcess name='MainProcess' parent=None started>
[2023-04-01 18:29:23] WARNING: Running using PyInstaller bundle
[2023-04-01 18:29:23] WARNING: Windows platform detected: using multiprocessing.freeze_support()
Steamworks wrapper: <_MainProcess name='MainProcess' parent=None started>
Main script: <_MainProcess name='MainProcess' parent=None started>
[2023-04-01 18:29:36] WARNING: Running using PyInstaller bundle
[2023-04-01 18:29:36] WARNING: Windows platform detected: using multiprocessing.freeze_support()
[2023-04-01 18:29:36] WARNING: Process-1 Unable to initiate Steamworks API call. Steam is not running!
[2023-04-01 18:29:36] WARNING: Process-1 Unable to launch game with Steamworks API. Please close your game and try to launch again after opening Steam.

It's very weird what is happening right there. The ~13 second gap you see is just because the VM I am using is laggy while it is initializing (metadata for 500 mods or so...). On real hardware, it is much snappier.

Answer 9 · 2023-04-02T02:02:15.000Z

@twstagg Thanks for your logs.

I'm seeing the below line repeated 2 times in the output after PyInstallered.
This is different than the pure interpreter's log.

Main script: <_MainProcess name='MainProcess' parent=None started>

Then the Process-1 appears in [2023-04-01 18:29:36] WARNING: Process-1 Unable to initiate Steamworks API call. Steam is not running!.

So, we see that the spawned child process still had the name MainProcess when logger-tt was invoked, which causes the problem. Then there are 2 questions that need to be answered.

Is the text Process-1 output by the multiprocessing.current_process().name too?
If yes, at which point the process name changed?

Answer 10 · 2023-04-02T02:24:46.000Z

@Dragon2fly

@twstagg Thanks for your logs.

What OS did you collect the log from?

That was from Windows. I will post some additional output from MacOS for you soon, with these new debug prints added.

I'm seeing the below line repeated 2 times in the output after PyInstallered. This is different than the pure interpreter's log.

Main script: <_MainProcess name='MainProcess' parent=None started>

Then the Process-1 appears in [2023-04-01 18:29:36] WARNING: Process-1 Unable to initiate Steamworks API call. Steam is not running!.

So, we see that the spawned child process still had the name MainProcess when logger-tt was invoked, which causes the problem. Then there are 2 questions that need to be answered.
1. Is the text `Process-1` output by the `multiprocessing.current_process().name` too?

Yes it is. I went ahead and put the print in both of the files that are being used here:

The main script (where setup_logging is called)
- https://github.com/oceancabbage/RimSort/blob/c0f86bd55c2219afd8e7c0c43fbbb7b0f914a18f/RimSort.py#L20
The module which contains the functions that passed to the multiprocessing.Process
- https://github.com/oceancabbage/RimSort/blob/c0f86bd55c2219afd8e7c0c43fbbb7b0f914a18f/util/steam/steamworks/wrapper.py#L16
See where we are actually launching the processes (This method is triggered by PySide2 GUI element from the MainProcess:
- https://github.com/oceancabbage/RimSort/blob/c0f86bd55c2219afd8e7c0c43fbbb7b0f914a18f/view/main_content_panel.py#L781-L813

2. If yes, at which point the process name changed?

I am not sure how to answer this question exactly. It appears that when the application is PyInstaller'd and we are using spawn() - the MainProcess is copied before the Process-1 is created by the user action in the GUI.

If I do not have multiprocessing.freeze_support() run (this is conditionally run if platform.system() returns "Windows") then the GUI window will actually fully duplicate when the multiprocessing.Process is created.

You can see where I have some of that being done here: https://github.com/oceancabbage/RimSort/blob/c0f86bd55c2219afd8e7c0c43fbbb7b0f914a18f/RimSort.py#L155-L165

In another recreation of the issue, you can see that the log even continues from that main process, after it is cut off & overwritten upon the Process being created:

From the console:

PS C:\Users\localadmin\Desktop\RimSort\dist\RimSort> .\RimSort.exe
Steamworks wrapper: <_MainProcess name='MainProcess' parent=None started>
Main script: <_MainProcess name='MainProcess' parent=None started>
[2023-04-01 19:57:40] WARNING: Running using PyInstaller bundle
[2023-04-01 19:57:40] WARNING: Windows platform detected: using multiprocessing.freeze_support()
Steamworks wrapper: <_MainProcess name='MainProcess' parent=None started>
Main script: <_MainProcess name='MainProcess' parent=None started>
[2023-04-01 19:57:52] WARNING: Running using PyInstaller bundle
[2023-04-01 19:57:52] WARNING: Windows platform detected: using multiprocessing.freeze_support()
[2023-04-01 19:57:52] WARNING: Process-1 Unable to initiate Steamworks API call. Steam is not running!
[2023-04-01 19:57:52] WARNING: Process-1 Unable to launch game with Steamworks API. Please close your game and try to launch again after opening Steam.

The actualdata/RimSort.log` file from logger_tt:

[DEBUG][2023-04-01 19:55:45][4416][root][setup_logging][220] : _________________New log started__________________
[DEBUG][2023-04-01 19:55:45][4416][root][setup_logging][221] : Log config file: C:\Users\localadmin\Desktop\RimSort\dist\RimSort\data\logging_config.json
< ***insert NULLS you see in the pic above*** >
[DEBUG][2023-04-01 19:57:51][8480][root][_replace_with_socket_handler][161] : Logging server started!
[WARNING][2023-04-01 19:57:52][8480][view.status_panel][<module>][156] : Running using PyInstaller bundle
[WARNING][2023-04-01 19:57:52][8480][view.status_panel][<module>][158] : Windows platform detected: using multiprocessing.freeze_support()
[INFO][2023-04-01 19:57:52][8480][view.status_panel][launch_game_process][100] : Process-1 Attempting to find the game in the game folder C:\Program Files (x86)\Steam\steamapps\common\Rimworld
[WARNING][2023-04-01 19:57:52][8480][view.status_panel][launch_game_process][107] : Process-1 Unable to initiate Steamworks API call. Steam is not running!
[WARNING][2023-04-01 19:57:52][8480][view.status_panel][launch_game_process][112] : Process-1 Unable to launch game with Steamworks API. Please close your game and try to launch again after opening Steam.
[INFO][2023-04-01 19:57:52][8480][view.status_panel][launch_game_process][127] : Process-1 Path to game executable for Windows generated: C:\Program Files (x86)\Steam\steamapps\common\Rimworld\RimWorldWin64.exe
[INFO][2023-04-01 19:57:52][8480][view.status_panel][launch_game_process][131] : Process-1 Launching the game with subprocess.Popen(): `C:\Program Files (x86)\Steam\steamapps\common\Rimworld\RimWorldWin64.exe` with args: ``
[INFO][2023-04-01 19:57:52][8480][view.status_panel][launch_game_process][148] : Process-1 Launched independent RimWorld game process with PID: 4588
[INFO][2023-04-01 19:57:53][9268][view.status_panel][_do_steamworks_api_call][813] : Steamworks API process wrapper completed for PID: 8480
[INFO][2023-04-01 19:57:53][9268][view.status_panel][actions_slot][52] : Displaying fading text for action: run
[INFO][2023-04-01 19:57:56][9268][view.status_panel][main_thread][150] : Exiting program

Answer 11 · 2023-04-02T11:53:48.000Z

@twstagg

If I do not have multiprocessing.freeze_support() run (this is conditionally run if platform.system() returns "Windows") then the GUI window will actually fully duplicate when the multiprocessing.Process is created.

From your description above, I understand that it opened the second GUI exactly the same as the first one even though the code is guarded with: if __name__ == "__main__".

This suggests that the __name__ of the child process is still __main__ as opposed to __mp_main__ when running with the interpreter. So the multiprocessing.freeze_support() must have a different way to know if it is in a child process or not.

Following the freeze_support() function, I added a similar check into:
https://github.com/Dragon2fly/logger_tt/blob/4cdbe73ff254121a4ed0a9b710239e8a31810af4/logger_tt/core.py

Could you replace the logger_tt/core.py in your local environment and test again?

Answer 12 · 2023-04-02T15:58:34.000Z

@Dragon2fly

From your description above, I understand that it opened the second GUI exactly the same as the first one even though the code is guarded with: if __name__ == "__main__".

Correct.

This suggests that the __name__ of the child process is still __main__ as opposed to __mp_main__ when running with the interpreter. So the multiprocessing.freeze_support() must have a different way to know if it is in a child process or not.

Ahh! This makes sense. A quick test with similar debug prints confirms this as well.

Following the freeze_support() function, I added a similar check into: https://github.com/Dragon2fly/logger_tt/blob/4cdbe73ff254121a4ed0a9b710239e8a31810af4/logger_tt/core.py

Could you replace the logger_tt/core.py in your local environment and test again?

In my Windows env, I have replaced the Pypy distributed logger-tt (latest release) with a locally cloned version of logger-tt. I did git checkout pyinstaller_test before I built the module. Sadly, I don't think your change had any effect on my issue:

And with the prints of __main__ included:

It appears to not be mp_main for some reason? Why is it using the namespace of the module that the Process's function was imported from...?

Running from Python interpreter behaves as expected:

Answer 13 · 2023-04-05T01:56:18.000Z

@twstagg
Can you post the result of pyinstallered rimsort with the cloned logger-tt in the macOS env?
I want to know if it can run on macOS now or not.

As I understanding, there are 2 problems we are facing:

It runs on windows but output a bunch of Null when starting the child process.
It doesn’t run on macOS

We will have to solve it one by one.
As for the windows case, can you provide an instruction to build the environment and create an exe with pyinstaller?

Answer 14 · 2023-04-05T20:58:13.000Z

@Dragon2fly

@twstagg Can you post the result of pyinstallered rimsort with the cloned logger-tt in the macOS env? I want to know if it can run on macOS now or not.

Sure thing. For science, here is output when running from Python interpreter. The process launches properly and multiprocessing works as intended. The logger_tt log serializes just fine.

$ python RimSort.py
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __main__
sys.argv: ['RimSort.py']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['RimSort.py']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['RimSort.py']
[2023-04-05 15:44:21] WARNING: Running using Python interpreter
QPixmap::scaled: Pixmap is a null pixmap
RimSort.py: <_MainProcess name='Process-1' parent=None started>
__name__: __mp_main__
sys.argv: ['/Users/user/Desktop/RimSort/RimSort.py']
steamworks.wrapper: <_MainProcess name='Process-1' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['/Users/user/Desktop/RimSort/RimSort.py']
main_content_panel.py: <_MainProcess name='Process-1' parent=None started>
__name__: view.main_content_panel
sys.argv: ['/Users/user/Desktop/RimSort/RimSort.py']
[2023-04-05 15:44:28] WARNING: Process-1 Unable to initiate Steamworks API call. Steam is not running!
[2023-04-05 15:44:28] WARNING: Process-1 Unable to launch game with Steamworks API. Please close your game and try to launch again after opening Steam.

On MacOS, here is the PyInstaller'd output. It does not launch the process because of the Unhandled exception. Super weird compared to what we see on Windows. With this I also added an additional print for sys.argv:

$ ./RimSort 
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __main__
sys.argv: ['./RimSort']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['./RimSort']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['./RimSort']
[2023-04-05 15:55:30] WARNING: Running using PyInstaller bundle
[2023-04-05 15:55:30] WARNING: Non-Linux platform detected: using multiprocessing.freeze_support() & setting 'spawn' as MP method
QPixmap::scaled: Pixmap is a null pixmap
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __main__
sys.argv: ['/Users/user/Desktop/RimSort/dist/RimSort.app/Contents/MacOS/RimSort', '-B', '-S', '-E', '-s', '-c', 'from multiprocessing.resource_tracker import main;main(32)']
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __main__
sys.argv: ['/Users/user/Desktop/RimSort/dist/RimSort.app/Contents/MacOS/RimSort', '--multiprocessing-fork', 'tracker_fd=33', 'pipe_handle=35']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['/Users/user/Desktop/RimSort/dist/RimSort.app/Contents/MacOS/RimSort', '-B', '-S', '-E', '-s', '-c', 'from multiprocessing.resource_tracker import main;main(32)']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['/Users/user/Desktop/RimSort/dist/RimSort.app/Contents/MacOS/RimSort', '--multiprocessing-fork', 'tracker_fd=33', 'pipe_handle=35']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['/Users/user/Desktop/RimSort/dist/RimSort.app/Contents/MacOS/RimSort', '--multiprocessing-fork', 'tracker_fd=33', 'pipe_handle=35']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['/Users/user/Desktop/RimSort/dist/RimSort.app/Contents/MacOS/RimSort', '-B', '-S', '-E', '-s', '-c', 'from multiprocessing.resource_tracker import main;main(32)']
Traceback (most recent call last):
Traceback (most recent call last):
  File "RimSort.py", line 36, in <module>
  File "RimSort.py", line 36, in <module>
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 355, in __init__
  File "logger_tt/core.py", line 355, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 466, in server_bind
  File "socketserver.py", line 466, in server_bind
OSError: [Errno 48] Address already in use
OSError: [Errno 48] Address already in use
[7582] [7583] Failed to execute script 'RimSort' due to unhandled exception: [Errno 48] Address already in use
Failed to execute script 'RimSort' due to unhandled exception: [Errno 48] Address already in use
[7582] [7583] Traceback:
Traceback (most recent call last):
  File "RimSort.py", line 36, in <module>
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 355, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 466, in server_bind
OSError: [Errno 48] Address already in use

Traceback:
Traceback (most recent call last):
  File "RimSort.py", line 36, in <module>
  File "logger_tt/__init__.py", line 225, in setup_logging
  File "logger_tt/core.py", line 88, in from_dict
  File "logger_tt/core.py", line 111, in _set_mode
  File "logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "logger_tt/core.py", line 355, in __init__
  File "socketserver.py", line 452, in __init__
  File "socketserver.py", line 466, in server_bind
OSError: [Errno 48] Address already in use

As I understanding, there are 2 problems we are facing:

It runs on windows but output a bunch of Null when starting the child process.

Pretty much. I don't know why this happens when the app is frozen. When the app is running from interpreter, the log file just continues business as usual. It does not get cutoff and the process logs to the file with 0 issue using the handler.

It doesn’t run on macOS

Yeah, logger_tt crashes my Process on MacOS seemingly. The process is not spawned and subsequently the game is not launched, when the app is frozen. No issues when run from Python interpreter.

We will have to solve it one by one. As for the windows case, can you provide an instruction to build the environment and create an exe with pyinstaller?

Yep! It is a mod manager for RimWorld game however, but you might be able to trick it kinda. Let me know if you have any questions:

https://github.com/oceancabbage/RimSort/wiki/Development-Guide
- You can skip building SteamworksPy. The libs are already pre-built and included in-repo. You do need the submodule however, so make sure you follow that part. Make sure you copy ./SteamworksPy/steamworks/ to the project root so that the app has the actual python module used to interface with those libs.

Answer 15 · 2023-04-06T21:30:59.000Z

@Dragon2fly

Interesting development. I tried out compiling using Nuitka again, with my latest on Windows.

Frozen with Nuitka, it doesn't properly detect that the executable is frozen with sys.frozen and _MEIPASS checks? I had to just tab the freeze_support() back a bit to be outside of that check, as the check was failing (you can see it still thinks it is running from Python interpreter...???)

You can see below, the __name__ of the child process is __parents_main__ which is better than PyInstaller, because at least it's properly changing the name? I definitely like this behavior with Nuitka a lot more than the Pyinstaller'd behavior, as it made this a lot more functional in terms of the multiprocessing aspects:

PS C:\Users\localadmin\Desktop\RimSort\RimSort.dist> .\RimSort.exe
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __main__
sys.argv: ['C:\\Users\\localadmin\\Desktop\\RimSort\\RimSort.dist\\RimSort.exe']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['C:\\Users\\localadmin\\Desktop\\RimSort\\RimSort.dist\\RimSort.exe']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['C:\\Users\\localadmin\\Desktop\\RimSort\\RimSort.dist\\RimSort.exe']
Failed to load libEGL (The specified module could not be found.)
QWindowsEGLStaticContext::create: Failed to load and resolve libEGL functions
Failed to load opengl32sw.dll (The specified module could not be found.)
Failed to load and resolve WGL/OpenGL functions
[2023-04-06 14:16:37] WARNING: Running using Python interpreter
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __parents_main__
sys.argv: ['C:\\Users\\LOCALA~1\\Desktop\\RimSort\\RIMSOR~1.DIS\\RimSort.exe', '--multiprocessing-fork', 'parent_pid=9492', 'pipe_handle=1652']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['C:\\Users\\LOCALA~1\\Desktop\\RimSort\\RIMSOR~1.DIS\\RimSort.exe', '--multiprocessing-fork', 'parent_pid=9492', 'pipe_handle=1652']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['C:\\Users\\LOCALA~1\\Desktop\\RimSort\\RIMSOR~1.DIS\\RimSort.exe', '--multiprocessing-fork', 'parent_pid=9492', 'pipe_handle=1652']
[2023-04-06 14:16:48] WARNING: Process-1 Unable to initiate Steamworks API call. Steam is not running!
[2023-04-06 14:16:48] WARNING: Process-1 Unable to launch game with Steamworks API. Please close your game and try to launch again after opening Steam.

Ultimately, the child process appears to properly spawn when compiled with Nuitka. The issue with the logger_tt log being overwritten is still present however:

This makes me think there is more of an issue/limitation with Pyinstaller than I initially thought. Logger_tt is still having issue as well.

What are your thoughts on this?

Answer 16 · 2023-04-07T02:13:03.000Z

@Dragon2fly

Yeah, officially, I think we are ditching PyInstaller for Nuitka in light of these developments.

Seeing the same improvement in frozen multiprocessing spawn() behavior when using Nuitka to "build" on MacOS:

$ ./RimSort 
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __main__
sys.argv: ['./RimSort']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['./RimSort']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['./RimSort']
[2023-04-06 21:08:49] WARNING: Running using Python interpreter
QPixmap::scaled: Pixmap is a null pixmap
RimSort.py: <_MainProcess name='MainProcess' parent=None started>
__name__: __parents_main__
sys.argv: ['/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/RimSort', '--multiprocessing-fork', 'tracker_fd=35', 'pipe_handle=37']
steamworks.wrapper: <_MainProcess name='MainProcess' parent=None started>
__name__: util.steam.steamworks.wrapper
sys.argv: ['/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/RimSort', '--multiprocessing-fork', 'tracker_fd=35', 'pipe_handle=37']
main_content_panel.py: <_MainProcess name='MainProcess' parent=None started>
__name__: view.main_content_panel
sys.argv: ['/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/RimSort', '--multiprocessing-fork', 'tracker_fd=35', 'pipe_handle=37']
Traceback (most recent call last):
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/RimSort.py", line 36, in <module __parents_main__>
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/logger_tt/__init__.py", line 225, in setup_logging
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/logger_tt/core.py", line 88, in from_dict
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/logger_tt/core.py", line 111, in _set_mode
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/logger_tt/core.py", line 158, in _replace_with_socket_handler
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/logger_tt/core.py", line 355, in __init__
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/socketserver.py", line 452, in __init__
  File "/Users/user/Desktop/RimSort/RimSort.app/Contents/MacOS/socketserver.py", line 466, in server_bind
OSError: [Errno 48] Address already in use

Unfortunately, logger_tt still crashes the process. But it has a different __name__ at least!

With MacOS, we also see the log get corrupted/overwritten/whatever just like in Windows, and unlike Windows spawn() it does NOT launch the process (likely due to the unhandled exception):

Answer 17 · 2023-04-15T15:52:02.000Z

Hi @twstagg

I don't have RimWorld installed so my environment is not the same as yours. I replaced the call to the RimWorldWin64.exe with notepad.exe and tested it with pyinstaller on Windows. But I cannot replicate the log file as yours.

Can you replicate it on another machine?
Can you provide a minimal reproducible code that doesn't require installing RimWorld?

As for the MacOS with Nuitka, from the logs you provided, it doesn't contain the line Logging server started!.
This indicates that the main process/main thread wasn't able to start the log server.
From OSError: [Errno 48] Address already in use message, the port that it tried to bind was being in use by other applications.
Could you please make sure the 9020 port is not in use, or change the port in the config file and test again?

Answer 18 · 2023-04-16T15:29:46.000Z

Hi @twstagg

I added some modifications to detect child processes and print out some debug logs to logger-tt.
I would like to see the logs from your environment using the below package:
logger_tt-1.7.4-py3-none-any.whl.zip

unzip the above file
from within your venv, pip install -U [path_to_the_unzipped_file.whl]
do pyinstaller or nuitka as normal then run the exe to get the log

Answer 19 · 2023-06-01T03:22:03.000Z

Hi @twstagg

I don't have RimWorld installed so my environment is not the same as yours. I replaced the call to the RimWorldWin64.exe with notepad.exe and tested it with pyinstaller on Windows. But I cannot replicate the log file as yours.

Can you replicate it on another machine? Can you provide a minimal reproducible code that doesn't require installing RimWorld?

As for the MacOS with Nuitka, from the logs you provided, it doesn't contain the line Logging server started!. This indicates that the main process/main thread wasn't able to start the log server. From OSError: [Errno 48] Address already in use message, the port that it tried to bind was being in use by other applications. Could you please make sure the 9020 port is not in use, or change the port in the config file and test again?

Hi @twstagg

I added some modifications to detect child processes and print out some debug logs to logger-tt. I would like to see the logs from your environment using the below package: logger_tt-1.7.4-py3-none-any.whl.zip
1. unzip the above file

2. from within your venv, `pip install -U [path_to_the_unzipped_file.whl]`

3. do pyinstaller or nuitka as normal then run the exe to get the log

Hi @Dragon2fly. I think that this was more of an issue with my implementation. I've made a zillion changes to the structure of my application and am now doing things more intelligently. I just circled back to test this issue out again (with your 1.7.4 version provided above) and I don't have any of the previous issues on MacOS at least.

Testing on Windows here soon as well.

Thanks for your response and discussion! I'll let you know if I run into more issues.

Answer 20 · 2023-06-01T03:43:27.000Z

Ah, yes, on Windows the issue is still present with the log starting over and zeroing.

I don't see the same debug prints that you added on Windows that I do in MacOS though...

Answer 21 · 2023-06-21T13:48:15.000Z

Hi @twstagg. Have you had any progress on Windows yet?

Since the problem was resolved on MacOS, I'm going to officially release v1.7.4 to PyPI.
Of course, it includes other fixes and improvements too.

Answer 22 · 2023-08-07T22:33:33.000Z

@Dragon2fly I wanted to let you know that as of today i sorted out my stupidity

RimSort/RimSort@08ff199

This commit is what fixed all of my issues. The logger setup was getting executed on re-import. Idk what i was thinking before. Thank you very much for your time and for the awesome piece of software btw!