Debugging Scripts by Writing to Event.log

October 17, 2011

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.

LogMessage Custom Function

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.

Log Conditional Formatting

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.

Import Log

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,..

Log Message Script

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?

{ 15 comments… read them below or add one }

Tim Neudecker October 17, 2011 at 8:47 am

Honza, What a great find. While I dont like using things in ways not intended as the could break in the future and be unsupported, this is just wonderful.

Many times I have wanted to log things server side, this makes it so easy.

Reply

Jonathan Fletcher October 17, 2011 at 8:50 am

Wow. How counter-intuitive. Love it. Thanks for sharing that!

Reply

Agnes Riley October 17, 2011 at 9:07 am

This is just plain great! There are many occasions where my server scripts are just not behaving as intended. This will give me the chance to see what actually happens!

Thanks for another great idea!

Reply

Drew Sanderson October 17, 2011 at 11:46 am

Very cool Honza! I know that will come in use.

Reply

Daniel Matsumura October 17, 2011 at 12:56 pm

Cool, I’m thinking about start to use FMS and this trick will be very useful thank you for share

Daniel – Aichi, Japan.

Reply

Andrew Duncan October 17, 2011 at 2:15 pm

Hi Honza,

It sounds like we’ve been doing the same thing recently – debugging server side scripts. I wrote a blog post about my experiences at:

http://www.databuzz.com.au/an-approach-to-filemaker-server-side-script-debugging/

which takes a similar approach to you but I’m not writing to the Event.log.

Thanks for the great article.

Reply

HOnza October 18, 2011 at 1:11 am

Thank you for all your comments. I am glad you like this trick.
And thanks, Andrew, for the link to your equally great article.
As you can see from the screenshot of my script, I also use SQL as a primary way to log messages, and only use the Re-Login trick to trap situations when the SQL logging fails to work.

Reply

Nick Stockbridge October 18, 2011 at 11:12 pm

That’s a really clever idea. Going to save that one.

Reply

Jesse Barnum October 21, 2011 at 11:22 am

Very cool trick – we have to debug server scripts often, so this will come in very handy. Thanks!

Reply

Josh Ormond October 21, 2011 at 8:53 pm

Great find HOnza. I do love your ability to think outside the box. Another tool added to my toolbox.

Reply

Dimitris Valachis October 23, 2011 at 11:47 pm

Genius…

Reply

Jack Rodgers November 1, 2011 at 8:23 am

One try and one which might have consequences:
The event log is a text file. If the server opens and then closes it each time it writes, you may also be able to write to the file using a plug in that appends to a file. Or even replace the entire file with your own data.
I did not suggest this if it causes any problem…

Reply

HOnza November 1, 2011 at 8:44 am

You can create your own log with a plug-in. The key benefit of this technique is that it is extremely reliable. In my case, it helped me to catch problem with just the plug-in that I would use to write to the log.

Darren Burgess September 10, 2012 at 7:18 am

Brilliant. Really great out of the box thinking. Thanks again for sharing your insights with the community.

Reply

HOnza September 10, 2012 at 11:23 am

Thanks. I just simply hate giving up… ;-)

Leave a Comment