Debugging Scripts by Writing to Event.log
This is a fresh story of me spending hours trying to fix a technical issue and accidentally revealing a gold nugget. A few days ago one of my nightly server-side scripts stopped working without any apparent reason. But when I tried to run the script in FileMaker Pro it worked just fine. I really needed a way to debug the script on the server.
Since there is no script debugger for server-side debugging, my first thought was to log some status information from different parts of the script, so that I can see if the script is doing what I expect it to do. So I created a simple log table and a custom function that writes a message to that table by executing an SQL statement using 24U Toolbox Plug-In.
I even made the log very nicely readable by applying very simple conditional formatting to the displayed fields. By highlighting the messages containing the “starting…” text I could easily recognize messages created by the same script instance. By using red text for messages containing the word “error” I could immediately notice any error message.
I you ever display any log in a FileMaker layout, I strongly suggest you use some similar conditional formatting rules. It’s just one minute of work that pays off immediately.
For my purpose of debugging the broken script the logging worked like a charm when I tested it in FileMker Pro Advanced. The script was working correctly there, so I needed to get the log from its server-side execution. But when I tried to run the script on the server nothing appeared in the log table. Not even the message that the sript has started. What? It was driving me crazy. Now I already had two things to discover. First, of course, was why my script stopped working on the server. The second was why my logging does not work on the server. I despertely needed another way log my messages.
I didn’t want to do it using a subscript creating the log record and writing to it – I can explain why in another article later if you’re interested. Instead, I tried to cross the borders and think outside the box as I like to do so much. I asked myself: “Is there really no way to affect what appears in the FileMker Server’s Event.log?”
And then I found it. it was sitting there, popping at me several times a day. I discovered that there is a script step that lets me write a message to the Event.log. It just is not named very intuitively for this purpose.
The script step is named Re-Login.
Yes, you’re reading right, Re-login is the script step that lets you write a custom message to the Event.log. If you have already tried to use server-side scripts you probably noticed that errors are logged just with the error number. But if youbtry to re-login with a wrong username or password, your failed login attempt will appear in the log together with the username you tried to login with.
So the trick is to use the message you want to appear in the log as a useraname in the Re-Login script step,..
Pretty easy, isn’t it? And here is what the result looks like:
2011-10-12 18:26:14.016 +0200 Warning 661 Marge Client "Import Today's Data" authentication failed on database "DailyReport.fp7" using "LogMessage: ?".
2011-10-12 18:26:14.686 +0200 Warning 661 Marge Client "Import Today's Data" authentication failed on database "DailyReport.fp7" using "Message: Import html download read error: 57005 (24U SimpleFile Plug-In 1.1.1)".
After I applied this To my solution I quickly found out that the reason why my SQL based logging was not working was a corrupt custom functions index. Debugging the script itself was then as easy as pie.
And the best part of this is that this trick works even when running the script on a client connected to your FileMaker Server remotely. Isn’t that cool?