NSSM and Symfony Scheduler
Recently I updated a project to use Symfony Scheduler to handle scheduled background tasks like sending emails and running data checks. In order for this to work, it is necessary run the messenger:consume console command for the scheduler as either a scheduled task or a service.
This project is hosted on Windows Server, so to do this I decided to use NSSM to create a service which runs this command. I installed NSSM, then used it to define a new service to run this command. After configuring and starting the service, I tested the messenger:stop-workers command to check that the consumer process would stop and NSSM would re-start it as it should.
What I found, was that the consumer process would exit, but NSSM was not restarting it. Instead, it sat there and windows showed the service as still running since NSSM was still running. This was not good, as this means if my script crashes, it won't restart and all my scheduled tasks would stop working. This is not the first time I've used NSSM for something like this, so I was confused why it was not working when it had in the past.
The fix
After much debugging, I discovered that this is an issue if you are using certain features of the I/O and File Rotation tabs when setting up the service. When using certain features, NSSM opens a pipe to handle the process output and then hangs on closing this pipe when the process ends, preventing it from ever reaching the code to restart the service. Based on my quick reading of the code, the scenarios that could lead to this are:
- Enabling file rotation while the service is running.
- Enabling the Timestamp option for I/O files.
- Redirecting output from hooks.
Reconfiguring the service to avoid these scenarios solves the problem. In my case, I had enabled the timestamp option for I/O files. Editing the service to remove this option resolved the problem.
Finding the problem
Looking at the logs in event viewer didn't really help with determining why this was happening. There were no logs related to it not wanting to restart the process. Since the source code for NSSM is available on its website, I decided to download it and start looking through it to determine why it might be failing to restart the process.
In the source code, I eventually found the end_service (service.cpp:2033) function which is called when the program exits and handles restarting the program. I saw there were a couple conditions that would prevent it from restarting, so to debug the problem I added extra logging events to this function and compiled a new version of nssm and used that for my service.
After replicating the problem, I found that the function ran up until the cleanup_loggers function call but then quit. I found the definition of this function (io.cpp:432) and added some more debug logging to this function to see where it was running into issues and re-compiled nssm. With this new version I was able to determine the program was getting hung on the close_handle call for stdout_pipe (io.cpp:441).
I don't know why this is happening, but it clued me into the fact that the issue is probably related to the IO logging configuration. I searched the code for where this handle is set up and found the flag use_stdout_pipe (registry.cpp:842) which is true when
- Online file rotation is enabled or
- Timestamping of logs is enabled or
- Hooks share the same output file as the service.
I checked my service definition and found I had enabled the timestamps option. I updated the service to disable this option and everything started working as expected.
