Description
This is strange, I want to document it in the hope of clarity or a fix if it's needed
So it all started with me looking into a race condition to see if our event handler service was getting an event before we were saving the new transaction id.
Here is the log creating the transaction
So here was the original transaction being created at 8:05
Searching the bus handler shows this
It showed an event at 6:46, this was over an hour before the transaction was created.
These cloud logs run off our ops agent running on a google cloud vm instance. They monitor pm2 logs at the default location of, ~/.pm2/logs/*
By examining these logs and the entries before and after I can confirm this log entry happened at 8:05 NOT 6:46, I cannot find anything before.
So then I scrolled the logs without any search parameters and noticed hundreds and hundreds of entries with the same time of 6:46, our subscriber is only doing one at a time, so it's possible logging an obj might have it's elements logged at the same time, but otherwise these should not all be at the same time.
Eventually I reached the top of all the entries with the 6:46 time. And the log before this was the pm2 log rotation entry.
I'm not sure what to make of this, I guess the log rotation caused the entries to bunch up and somehow get entered with a different timestamp over an hour before the event occurred.
I'm not sure. If anyone has any thoughts on this, is there some setting on the log rotator to avoid this. What is happening?