Web Publishing Log Files

[Zardoz]

Does anybody know how to interpret entries in the wpc_access_log file? On W2K3, this file is located in the following path: FileMaker / FileMaker Server 7 / Web Publishing / Logs.

There is another log file in that same directory called pe_application_log which is indicating that a few web publishing errors are occurring. This file just gives the FileMaker error number and a timestamp, but no further explanation. Both logs have timestamps, so it is possible to cross-reference from one log file to the other based on date and time of occurrence. I can find the corresponding entry in the wpc_access_log that tells me lots of good information, such as the account name and IP address of the user. Tracing back in the log, it is also possible to find the name of the database that the user was connected to. However, there is lots of other information in the wpc_access_log entry that will probably help to narrow down the specific source/cause of the Web Publishing error, but I don't know how to interpret this information.

I don't believe these errors are significant, as there are no errors occurring in the databases (at least on the surface). It could be that the corresponding error messages are being suppressed in the databases by the use of the Set Error Capture script step. However, I would like to get a better understanding of what these log entries are telling me in case there are scripting changes I can make to make my solutions more logical and efficient.

Here is a sample entry from the wpc_access_log (with IP address deleted) [03/Nov/2005:10:15:00 -0700] /fmi/iwp/cgi?-index=50&-recid=1922&-relatedrecid=1922&-buttonscript=" 400 9087

This seems to be associated with the following entry in the pe_application_log:[03/Nov/2005:10:15:00 -0700] FM Web Publishing: Error: 400

There are a few of these 400 errors. Not all of the corresponding entries in the wpc_access_log follow the same pattern as the example above, but all of the ones that I've looked at so far have the "400 9087" as the last part of the entry. Maybe the 400 is the error number, but what is the 9087?

If there is something in these entries that will help me figure out what script is executing at the time of the error, that would be great.

Is there some documentation from FileMaker or elsewhere that can help me to interpret these entries?

Thank you.

[Martin Brändle]

The wpc_access_log is similar to a web server's access.log, but only for the web publishing core (wpc)

- the 3-number codes like 400 and so on are the HTTP status code

- 400 means "bad request"(e.g. a syntax error in the query)

- the number behind is the length of the XML tree (CWP) or the IWP data delivered (e.g. 9087 bytes)

The pe_application_log logs the behaviour of the complete publishing enginee (pe), e.g. the behaviour of Tomcat

[Zardoz]

Great stuff, Martin. Thanks. I wasn't familiar with HTTP status codes before, but a simple google search turned up lots of info.

I'm using IWP, and our web server is IIS.

So in the case of a bad request (HTTP Status Code 400), is this something that I have any control over within the database (i.e., is there something I can investigate and change that would make this error stop occurring), or does it have something to do with how FileMaker structures HTTP requests?

Is there any way of finding out what the offending 9087 byte string is?

The timestamp of the HTTP status code in the wpc_access_log always seems to match the occurrence of a FM Web Publishing 400 error ("find criteria are empty") in the pe_application_log. Is this significant? Is this a clue that the culprit may be a find with empty criteria being performed somewhere in the database?

Thanks.

[Martin Brändle]

The "offending string" of 9087 is indeed not offending. It is just the result that comes out for your offending query, e.g. it is probably an XML tree (in CWP, in IWP I don't know if it is XML) that contains the error message.

This one is the offending query:

/fmi/iwp/cgi?-index=50&-recid=1922&-relatedrecid=1922&-buttonscript=

The problem seems to be that the script name behind -buttonscript= is missing. Therefore FMS7A does not know what to do with the record ids. You should check your buttons in the DB layout, and also on the layout displayed by IWP.

[Zardoz]

Thanks again Martin. Are recid and relatedrecid referring to FileMaker's internal record id numbering system? What is "Index=50" referring to?

[Zardoz]

I've scanned the wpc_access_log for other 'buttonscript' references. Although there are many hundreds of entries that reference 'buttonscript', none of them provide a scriptname--they are all buttonscript=". This is true even for the entries where the HTML status code = 200, which translates as 'ok' (the request has succeeded).

In other words, of the many hundreds of entries that reference buttonscript, 99.9% of them are associated with a HTML status code = 200, yet there is nothing specified after buttonscript in these entries.

So I'm still somewhat confused about what these log entries are telling me. Does anyone have log entries where there is something specified after buttonscript? Or is it always blank?

[Zardoz]

Here are some additional findings for anyone who is interested:

The following entry in the pe_application_log appears to be correlated with a user's web session timing out: "FM Web Publishing: Error: 400." Session timeout may not be the only event that is generating these 400 errors, but it is the only causal factor isolated to date. The 400 in this case would appear to refer to the HTML 400 code ("Bad Request") and not to the FileMaker 400 error ("find criteria are empty").

The following entry in the pe_application_log relates to the 'GoToNextRecord/Request' scriptmaker step: "FM Web Publishing: Web Scripting Error: 101." If you have script logging turned on, you will see the name of the specific script and the name of the script step. From what I can determine, this error is being generated by specifying 'GoToRecord (Next; Exit after Last)' in a looping script. Regarding this script step, the 'Using FileMaker 7' book (Lane et al) indicates that if the pointer is already on the last record, FileMaker generates a 101 error ("record is missing") that is not reported to the user. Same holds true when specifying 'GoToRecord (Previous, Exit after Last) and the pointer is on the first record.

Although the 101 error is not reported to the user, it seems to get captured in the pe_application_log. This occurs even if SetErrorCapture is on and AllowUserAbort is off.

The 101 error does not appear to have any significant impact on database usage/performance, but it is cluttering up the log file. It seems like this error gets recorded in the log file everytime a looping script is executed that uses this script step in IWP.

Similarly, "Web Scripting Error: 401" seems to get recorded in the log file everytime an IWP user executes a script containing the PerformFind script step and no records are found. This is FileMaker's 401 error ("No records match the request"). Turning SetErrorCapture on and trapping for this error does not seem to suppress the generation of this error in the web log file (pe_application_log).

I don't see these errors turning up in the server's Event Viewer when desktop clients perform these same scripts. So I'm not sure why web logging captures them, especially as they don't seem to be significant.