Don’t you hate it when that elusive bug only happens “sometimes”? Tracking down the root cause of any bug often requires being able to replicate the problem, but what if the bug doesn’t appear each time you run the script?
Recently, I had a bug that only occurred when the script ran at the very beginning of a minute; when the seconds of the time were exactly 0. Of course, this wasn’t immediately obvious as the cause at first! The problem first appeared as a server-scheduled script failing—sometimes. I could run the script manually or even trigger the server script with Perform Script on Server and the script would appear to work just fine. I was dealing with external APIs so I assumed, at first, that their systems were finicky, or perhaps something with the network connection. But since this was out of my control, I was helpless to fix it. Once I realized that it was indeed a time-based bug—literally only happening when the script ran at a given time—I was able to quickly rectify the problem. Hindsight is always 20/20. Once I realized that it had to do with the time, it made much more sense why server-scheduled script would almost always fail, because the script would be triggered exactly at the beginning of a minute!
So what’s the real solution here? How should you work differently to avoid the situation that I was in? Yes, it may be nice to read this as a PSA to be aware that time itself may be a factor in bugs like these, but what caused me to realize I was dealing with a time-based bug in the first place?
Logging.
Logging is a whole other topic I can’t fully get into here, but here are just a few tips that always help me:
Log request AND response: When debugging with APIs it’s always a good idea to log the request and response of each API call. This practice really helps you verify whether or not you’re calling the API correctly or if it’s a network/external bug outside of your control. Can you make the exact same API call again and get the exact same result?
Logs can be anywhere: Logs can be their own FileMaker table, but you can also do some simple logging within a single additional field in your existing table if that makes sense. Just keep appending a new message to the field and soon you’ll see a full history of what happened during your server-scheduled script—just don’t forget to include a timestamp!
Avoid bloated logs: If you’re worried about your logs growing too large when they’re in their own table, consider setting them up with a feature flag so you can easily turn them on and off when needed, or set up a schedule to clear all logs older than 30 days for example. As a practice, we often only save non-success responses in our API logs, which also saves space.
Looking for a great logging solution that’s easy to set up in your own app? Check out the latest update to OttoFMS! With OttoFMS installed on your FileMaker server, just grab a log token from the settings page to put into the config script. Then call the “Log” script with a log level and message whenever you want to make a log, and view the logs directly from a web browser in the OttoFMS dashboard.
See the OttoFMS documentation for more details.