6 Replies Latest reply on Apr 1, 2015 2:14 PM by TSGal

    Timeout with error 502 using PHP API after FM Server upgrade to v13

    DaveWasmuth

      Summary

      Timeout with error 502 using PHP API after FM Server upgrade to v13

      Product

      FileMaker Server

      Version

      13.0.3

      Operating system version

      Windows 2008 Enterprise Edition SP1r2, IIS version 7.5

      Description of the issue

      We have some automated scripts on Linux that import data to and export data from a FileMaker Server hosted database (UserID).  A PHP script runs on the Linux system and makes calls to the FileMaker PHP API to connect to the FileMaker Server via cURL/HTTPS/IIS.  We recently upgraded the FileMaker Server from version 11 to 13.

      After updating the PHP API on the Linux system with the API that is delivered with FMS13, the import and export scripts are able to authenticate successfully and make API calls, including the running of FM scripts.  The import process loads up some staging tables in the FM UserID DB, then calls a FM script that runs for 8-12 minutes to process the staged data. 

      The execute() method of the object returned by PHP API’s newPerformScriptCommand() seems to timeout after 2 minutes, returning the following error:

      Communication Error: (22) The requested URL returned error: 502 - This can be due to an invalid username or password, or if the FMPHP privilege is not enabled for that user.

      The FM script continues to completion, but something along the way stops listening.  The FileMaker PHP API seems to be returning a 502 error code received in the HTTP response.  The IIS log seems to indicate that the request was successful, code 200.  I’m not sure how ARR and FastCGI are employed in the FileMaker setup, but my assumption is that FastCGI is for executing the PHP that calls the FM API in a web page and would not come into play when the API is invoked on a remote system.  It seems like the FM Web Publishing Engine or whatever is fielding the HTTP request generated by the FM PHP API is throwing the 502 after it gives up waiting for the FM script to complete.

      We found two timeout type things in the various configurations that were set to 2 minutes and changed them to 20 minutes, but neither addressed the problem.  They were the IIS Response timeout and the ARR Timeout.  The FM Admin tool does not seem to have any timeout value for the Web Publishing Engine.  FastCGI had one that was 90 seconds, rather than 120, so I don’t think that’s it.

      Are there any other more hidden timeouts or anything that might be causing this?  What actual components are used in what way in the interface between the FileMaker PHP API and the actual FileMaker Server?  The documentation is not very clear about the particulars.  Any help would be greatly appreciated.

      Steps to reproduce the problem

      Use the newPerformScriptCommand() method of the FM PHP API to make a call to a FM script that runs longer than two minutes with a default web publishing enabled FileMaker Server.  Preferably, run from a standalone PHP script, rather than PHP imbedded in a web page being rendered by the IIS instance from the FileMaker Server installation.

      Expected result

      The newPerformScriptCommand().execute() returns without error when the long-running FM script has completed.

      Actual result

      The newPerformScriptCommand().execute() returns with the following error after waiting 2 minutes for the script to complete:

      Communication Error: (22) The requested URL returned error: 502 - This can be due to an invalid username or password, or if the FMPHP privilege is not enabled for that user.

      Exact text of any error message(s) that appear

      Communication Error: (22) The requested URL returned error: 502 - This can be due to an invalid username or password, or if the FMPHP privilege is not enabled for that user.

      Workaround

      Have to do manual imports and exports, which is error prone, or give an anonymous login write access to the database.

        • 1. Re: Timeout with error 502 using PHP API after FM Server upgrade to v13
          TSGal

          Dave Wasmuth:

          Thank you for your post.

          I have forwarded your information to our Development and Testing departments for review.  When I receive any feedback, I will let you know.

          TSGal
          FileMaker, Inc.

          • 2. Re: Timeout with error 502 using PHP API after FM Server upgrade to v13
            TSGal

            Dave Wasmuth:

            The tester had a few questions that need answers.  What exactly is the FileMaker script doing?  How many records in the script are being moved?  How much megabytes of data?

            TSGal
            FileMaker, Inc.

            • 3. Re: Timeout with error 502 using PHP API after FM Server upgrade to v13
              TSGal

              Dave Wasmuth:

              There was another set of questions I forgot to include:

              1. Are you using FileMaker Server default PHP or another?  If another, which version?

              2. Is the PHP test page working?

              3. Is this a single machine or two machine configuration.

              4. Does this occur with only one database?  Or, do other databases also display the error?

              The tester would also like to see the FileMaker Server logs and IIS logs.  Please check your Inbox at the top of this page for instructions where to send these files.

              TSGal
              FileMaker, Inc.

              • 4. Re: Timeout with error 502 using PHP API after FM Server upgrade to v13
                DaveWasmuth

                Thanks for responding.  Here are some more details.

                The FileMaker Server configuration is all on a single machine.  My database is the only one being accessed via the PHP API.  I am using the API delivered with FMS 13.0.3.  Everything, including IIS and PHP, on the server is set up with the FileMaker installation defaults.  The PHP test page works fine.

                There are two shell scripts on the client side Linux machine that call PHP scripts that use the PHP API to communicate to the FileMaker Server Windows machine and manipulate the FileMaker database. 

                The export script works fine.  It uses a newFindAllCommand() object with the setRange(), getRecords() and getField() methods to pull data in 1,000 record chunks to create the export file that has about 42,000 lines and about 2.9 MB.  That takes less than a minute.

                The import script has the issue.  It starts with a file that is about 2.6 MB with about 17,500 lines of employee and user ID data with a one to many relationship (one employee can have multiple lines with user ID data).  It is loaded into two staging tables in the FM database.  The PHP script is called multiple times to process the file in 5,000 line chunks.  The PHP script does these things with the FM database:

                       
                • Before processing the 1st line of the 1st chunk, it empties two staging tables by running a FM script with a newPerformScriptCommand() object that uses Show All Records and Delete All Records -- takes about 15 seconds and works fine
                •      
                • Next, it loads the staging tables back up with the latest import data from the file, one FM record at a time, using the createRecord() and commit() methods -- takes 15-20 minutes with 10 of thousands of requests and works fine
                •      
                • Finally, once staging tables are filled up, a more complex FM script is called to process the data in the staging tables, importing changes into the actual FM database (about 10,000 rows of employee data and 6,500 rows of used ID data -- I know, one to many? but the many is often 0)

                That last step produces the communication error 22 now that we upgraded to FMS13.  The FM imports script runs for at least 7-8, maybe 10-12, minutes, but something stops listening after 120 seconds.  This whole process has been working fine for several years using pre-12 FMS versions.  My test script just tests the connection with listDatabases() and listLayouts(), then runs the import FM script using the staged data that is already there.  In production, I am working around the issue manually by basically running the exact same import script launched from the FileMaker client, since that works fine, taking about 20 minutes (longer because of its interaction with the FM client, I'm guessing).  I just ran the test script this morning (with predictable 120 second timeout).

                The IIS logfile shows this (note that the IIS times are off by 7 hours, and this actually kicked off at 2014-09-22 13:23:06):

                #Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status time-taken
                2014-09-22 20:23:06 128.114.114.27 POST /fmi/xml/fmresultset.xml X-ARR-CACHE-HIT=0&X-ARR-LOG-ID=1570f23e-0893-4b6f-8f43-1e685440a67c 443 - 128.114.115.23 - 200 0 0 1640

                The FileMaker Server log is long because there are a lot of "not found errors" that are intrinsic to processing the import.  I don't actually have access to the FMS13 Admin Console, but my co-worker who does emailed some excerpts to me and I have seen them.  Here is some data from the 4th from my import job that ran at 7:05 AM in production that led me to my conclusion.  First, here's a log from the email my Linux script sent me at 7:21:

                09/04/14 07:05:01: Import the account data with FileMaker PHP
                 
                 7:05:02 Import records 1 through 5000
                 7:05:18 Finished emptying staging tables
                 7:09:15 Import records 5001 through 10000
                 7:13:08 Import records 10001 through 15000
                 7:17:10 Import records 15001 through 20000
                 7:19:10 Finished loading data -- call FileMaker import
                Abnormal termination:
                FileMaker error processing the import: Communication Error: (22) The requested URL returned error: 502 - This can be due to an invalid username or password, or if the FMPHP privilege is not enabled for that user.
                
                ---------------------------------------------------------------------
                09/04/14 07:21:10: ******************************
                09/04/14 07:21:10: **** Stopping because of FMP PHP script failure 
                09/04/14 07:21:10: ******************************
                ---------------------------------------------------------------------
                

                Here is the end of the FileMaker Server log information from that run, showing the FM script (ImportPHP Process) completing later that morning.  The "Perform Find 401" errors are an intrinsic part of my looking for what needs to updated:

                2014-09-04 07:26:30 -0700     128.114.113.50    128.114.112.37:59755    CruzPay Depot    -    ERROR    401    1629    Web Scripting Error: 401, File: "UserID", Script: "ImportReplaceEmailAddrs", Script Step: "Perform Find"
                2014-09-04 07:26:30 -0700     128.114.113.50    128.114.112.37:59755    CruzPay Depot    -    ERROR    401    1629    Web Scripting Error: 401, File: "UserID", Script: "ImportFindUserID", Script Step: "Perform Find"
                2014-09-04 07:26:30 -0700     128.114.113.50    128.114.112.37:59755    CruzPay Depot    -    ERROR    401    1629    Web Scripting Error: 401, File: "UserID", Script: "ImportReplaceEmailAddrs", Script Step: "Perform Find"
                2014-09-04 07:26:30 -0700     128.114.113.50    128.114.112.37:59755    CruzPay Depot    -    ERROR    401    1629    Web Scripting Error: 401, File: "UserID", Script: "ImportReplaceEmailAddrs", Script Step: "Perform Find"
                2014-09-04 07:26:30 -0700     128.114.113.50    128.114.112.37:59755    CruzPay Depot    -    INFO    0    1629    "/fmi/xml/fmresultset.xml?-db=UserID&-lay=EmployeeImport&-script=ImportPHP Process&-findany”
                 

                 

                 

                 

                • 5. Re: Timeout with error 502 using PHP API after FM Server upgrade to v13
                  TSGal

                  Dave Wasmuth:

                  Thank you for the additional and detailed information.  I have sent this along back to Development and Testing for review.  I will continue to keep you posted as information becomes available to me.

                  TSGal
                  FileMaker, Inc.

                  • 6. Re: Timeout with error 502 using PHP API after FM Server upgrade to v13
                    TSGal

                    Dave Wasmuth:

                    I apologize for the late reply.

                    Testing had sent this to Development for investigation.  A developer noticed that the script was timing out.  Under Mac OS X, the default proxy time-out is five minutes.  Increasing this to 10 minutes allows the script to finish.  On IIS, the default is two minutes.  Again, increasing it to ten minutes allows the script to finish.  One recommendation was to break up the script into smaller tasks.

                    Since you reported this under Windows, modify:    c:\Windows\System32\inetsrv\config\applicationHost.config

                       <application fullPath="...\php-cgi.exe" instanceMaxRequests="1000"
                         activityTimout="xxx" requestTimeout="xxx">

                    ... where "xxx" is the number of seconds you want the timeout to be.  For ten minutes, this would be 600.

                    There is also a note that the php.ini may also need to be edited.  Increate the maximum execution time (max_execution_time) and/or memory limits (memory_limit).

                    Let me know if you need additional clarification.

                    TSGal
                    FileMaker, Inc.